// SPDX-License-Identifier: GPL-2.0-only
//
// Copyright(c) 2022 Intel Corporation
#include <linux/debugfs.h>
#include <linux/sched/signal.h>
#include <linux/sched/clock.h>
#include <sound/sof/ipc4/header.h>
#include "sof-priv.h"
#include "ipc4-priv.h"
/*
* debug info window is organized in 16 (equal sized) pages:
*
* ------------------------
* | Page0 - descriptors |
* ------------------------
* | Page1 - slot0 |
* ------------------------
* | Page2 - slot1 |
* ------------------------
* | ... |
* ------------------------
* | Page14 - slot13 |
* ------------------------
* | Page15 - slot14 |
* ------------------------
*
* The slot size == page size
*
* The first page contains descriptors for the remaining 15 cores
* The slot descriptor is:
* u32 res_id;
* u32 type;
* u32 vma;
*
* Log buffer slots have the following layout:
* u32 host_read_ptr;
* u32 dsp_write_ptr;
* u8 buffer[];
*
* The two pointers are offsets within the buffer.
*/
#define FW_EPOCH_DELTA 11644473600LL
#define MAX_ALLOWED_LIBRARIES 16
#define SOF_IPC4_INVALID_SLOT_OFFSET 0xffffffff
/* for debug and critical types */
#define SOF_MTRACE_SLOT_CORE_MASK GENMASK(7, 0)
#define SOF_MTRACE_SLOT_TYPE_MASK GENMASK(31, 8)
#define DEFAULT_AGING_TIMER_PERIOD_MS 0x100
#define DEFAULT_FIFO_FULL_TIMER_PERIOD_MS 0x1000
/* ipc4 log level and source definitions for logs_priorities_mask */
#define SOF_MTRACE_LOG_LEVEL_CRITICAL BIT(0)
#define SOF_MTRACE_LOG_LEVEL_ERROR BIT(1)
#define SOF_MTRACE_LOG_LEVEL_WARNING BIT(2)
#define SOF_MTRACE_LOG_LEVEL_INFO BIT(3)
#define SOF_MTRACE_LOG_LEVEL_VERBOSE BIT(4)
#define SOF_MTRACE_LOG_SOURCE_INFRA BIT(5) /* log source 0 */
#define SOF_MTRACE_LOG_SOURCE_HAL BIT(6)
#define SOF_MTRACE_LOG_SOURCE_MODULE BIT(7)
#define SOF_MTRACE_LOG_SOURCE_AUDIO BIT(8)
#define SOF_MTRACE_LOG_SOURCE_SCHEDULER BIT(9)
#define SOF_MTRACE_LOG_SOURCE_ULP_INFRA BIT(10)
#define SOF_MTRACE_LOG_SOURCE_ULP_MODULE BIT(11)
#define SOF_MTRACE_LOG_SOURCE_VISION BIT(12) /* log source 7 */
#define DEFAULT_LOGS_PRIORITIES_MASK (SOF_MTRACE_LOG_LEVEL_CRITICAL | \
SOF_MTRACE_LOG_LEVEL_ERROR | \
SOF_MTRACE_LOG_LEVEL_WARNING | \
SOF_MTRACE_LOG_LEVEL_INFO | \
SOF_MTRACE_LOG_SOURCE_INFRA | \
SOF_MTRACE_LOG_SOURCE_HAL | \
SOF_MTRACE_LOG_SOURCE_MODULE | \
SOF_MTRACE_LOG_SOURCE_AUDIO)
struct sof_log_state_info {
u32 aging_timer_period;
u32 fifo_full_timer_period;
u32 enable;
u32 logs_priorities_mask[MAX_ALLOWED_LIBRARIES];
} __packed;
enum sof_mtrace_state {
SOF_MTRACE_DISABLED,
SOF_MTRACE_INITIALIZING,
SOF_MTRACE_ENABLED,
};
struct sof_mtrace_core_data {
struct snd_sof_dev *sdev;
int id;
u32 slot_offset;
void *log_buffer;
struct mutex buffer_lock; /* for log_buffer alloc/free */
u32 host_read_ptr;
u32 dsp_write_ptr;
/* pos update IPC arrived before the slot offset is known, queried */
bool delayed_pos_update;
wait_queue_head_t trace_sleep;
};
struct sof_mtrace_priv {
struct snd_sof_dev *sdev;
enum sof_mtrace_state mtrace_state;
struct sof_log_state_info state_info;
struct sof_mtrace_core_data cores[];
};
static int sof_ipc4_mtrace_dfs_open(struct inode *inode, struct file *file)
{
struct sof_mtrace_core_data *core_data = inode->i_private;
int ret;
mutex_lock(&core_data->buffer_lock);
if (core_data->log_buffer) {
ret = -EBUSY;
goto out;
}
ret = debugfs_file_get(file->f_path.dentry);
if (unlikely(ret))
goto out;
core_data->log_buffer = kmalloc(SOF_IPC4_DEBUG_SLOT_SIZE, GFP_KERNEL);
if (!core_data->log_buffer) {
debugfs_file_put(file->f_path.dentry);
ret = -ENOMEM;
goto out;
}
ret = simple_open(inode, file);
if (ret) {
kfree(core_data->log_buffer);
debugfs_file_put(file->f_path.dentry);
}
out:
mutex_unlock(&core_data->buffer_lock);
return ret;
}
static bool sof_wait_mtrace_avail(struct sof_mtrace_core_data *core_data)
{
wait_queue_entry_t wait;
/* data immediately available */
if (core_data->host_read_ptr != core_data->dsp_write_ptr)
return true;
/* wait for available trace data from FW */
init_waitqueue_entry(&wait, current);
set_current_state(TASK_INTERRUPTIBLE);
add_wait_queue(&core_data->trace_sleep, &wait);
if (!signal_pending(current)) {
/* set timeout to max value, no error code */
schedule_timeout(MAX_SCHEDULE_TIMEOUT);
}
remove_wait_queue(&core_data->trace_sleep, &wait);
if (core_data->host_read_ptr != core_data->dsp_write_ptr)
return true;
return false;
}
static ssize_t sof_ipc4_mtrace_dfs_read(struct file *file, char __user *buffer,
size_t count, loff_t *ppos)
{
struct sof_mtrace_core_data *core_data = file->private_data;
u32 log_buffer_offset, log_buffer_size, read_ptr, write_ptr;
struct snd_sof_dev *sdev = core_data->sdev;
struct sof_mtrace_priv *priv = sdev->fw_trace_data;
void *log_buffer = core_data->log_buffer;
loff_t lpos = *ppos;
u32 avail;
int ret;
/* check pos and count */
if (lpos < 0)
return -EINVAL;
if (!count || count < sizeof(avail))
return 0;
/* get available count based on current host offset */
if (!sof_wait_mtrace_avail(core_data)) {
/* No data available */
avail = 0;
if (copy_to_user(buffer, &avail, sizeof(avail)))
return -EFAULT;
return 0;
}
if (core_data->slot_offset == SOF_IPC4_INVALID_SLOT_OFFSET)
return 0;
/* The log data buffer starts after the two pointer in the slot */
log_buffer_offset = core_data->slot_offset + (sizeof(u32) * 2);
/* The log data size excludes the pointers */
log_buffer_size = SOF_IPC4_DEBUG_SLOT_SIZE - (sizeof(u32) * 2);
read_ptr = core_data->host_read_ptr;
write_ptr = core_data->dsp_write_ptr;
if (read_ptr < write_ptr)
avail = write_ptr - read_ptr;
else
avail = log_buffer_size - read_ptr + write_ptr;
if (!avail)
return 0;
if (avail > log_buffer_size)
avail = log_buffer_size;
/* Need space for the initial u32 of the avail */
if (avail > count - sizeof(avail))
avail = count - sizeof(avail);
if (sof_debug_check_flag(SOF_DBG_PRINT_DMA_POSITION_UPDATE_LOGS))
dev_dbg(sdev->dev,
"core%d, host read: %#x, dsp write: %#x, avail: %#x\n",
core_data->id, read_ptr, write_ptr, avail);
if (read_ptr < write_ptr) {
/* Read data between read pointer and write pointer */
sof_mailbox_read(sdev, log_buffer_offset + read_ptr, log_buffer, avail);
} else {
/* read from read pointer to end of the slot */
sof_mailbox_read(sdev, log_buffer_offset + read_ptr, log_buffer,
avail - write_ptr);
/* read from slot start to write pointer */
if (write_ptr)
sof_mailbox_read(sdev, log_buffer_offset,
(u8 *)(log_buffer) + avail - write_ptr,
write_ptr);
}
/* first write the number of bytes we have gathered */
ret = copy_to_user(buffer, &avail, sizeof(avail));
if (ret)
return -EFAULT;
/* Followed by the data itself */
ret = copy_to_user(buffer + sizeof(avail), log_buffer, avail);
if (ret)
return -EFAULT;
/* Update the host_read_ptr in the slot for this core */
read_ptr += avail;
if (read_ptr >= log_buffer_size)
read_ptr -= log_buffer_size;
sof_mailbox_write(sdev, core_data->slot_offset, &read_ptr, sizeof(read_ptr));
/* Only update the host_read_ptr if mtrace is enabled */
if (priv->mtrace_state != SOF_MTRACE_DISABLED)
core_data->host_read_ptr = read_ptr;
/*
* Ask for a new buffer from user space for the next chunk, not
* streaming due to the heading number of bytes value.
*/
*ppos += count;
return count;
}
static int sof_ipc4_mtrace_dfs_release(struct inode *inode, struct file *file)
{
struct sof_mtrace_core_data *core_data = inode->i_private;
debugfs_file_put(file->f_path.dentry);
mutex_lock(&core_data->buffer_lock);
kfree(core_data->log_buffer);
core_data->log_buffer = NULL;
mutex_unlock(&core_data->buffer_lock);
return 0;
}
static const struct file_operations sof_dfs_mtrace_fops = {
.open = sof_ipc4_mtrace_dfs_open,
.read = sof_ipc4_mtrace_dfs_read,
.llseek = default_llseek,
.release = sof_ipc4_mtrace_dfs_release,
.owner = THIS_MODULE,
};
static ssize_t sof_ipc4_priority_mask_dfs_read(struct file *file, char __user *to,
size_t count, loff_t *ppos)
{
struct sof_mtrace_priv *priv = file->private_data;
int i, ret, offset, remaining;
char *buf;
/*
* one entry (14 char + new line = 15):
* " 0: 000001ef"
*
* 16 * 15 + 1 = 241
*/
buf = kzalloc(241, GFP_KERNEL);
if (!buf)
return -ENOMEM;
for (i = 0; i < MAX_ALLOWED_LIBRARIES; i++) {
offset = strlen(buf);
remaining = 241 - offset;
snprintf(buf + offset, remaining, "%2d: 0x%08x\n", i,
priv->state_info.logs_priorities_mask[i]);
}
ret = simple_read_from_buffer(to, count, ppos, buf, strlen(buf));
kfree(buf);
return ret;
}
static ssize_t sof_ipc4_priority_mask_dfs_write(struct file *file,
const char __user *from,
size_t count, loff_t *ppos)
{
struct sof_mtrace_priv *priv = file->private_data;
unsigned int id;
char *buf;
u32 mask;
int ret;
/*
* To update Nth mask entry, write:
* "N,0x1234" or "N,1234" to the debugfs file
* The mask will be interpreted as hexadecimal number
*/
buf = memdup_user_nul(from, count);
if (IS_ERR(buf))
return PTR_ERR(buf);
ret = sscanf(buf, "%u,0x%x", &id, &mask);
if (ret != 2) {
ret = sscanf(buf, "%u,%x", &id, &mask);
if (ret != 2) {
ret = -EINVAL;
goto out;
}
}
if (id >= MAX_ALLOWED_LIBRARIES) {
ret = -EINVAL;
goto out;
}
priv->state_info.logs_priorities_mask[id] = mask;
ret = count;
out:
kfree(buf);
return ret;
}
static const struct file_operations sof_dfs_priority_mask_fops = {
.open = simple_open,
.read = sof_ipc4_priority_mask_dfs_read,
.write = sof_ipc4_priority_mask_dfs_write,
.llseek = default_llseek,
.owner = THIS_MODULE,
};
static int mtrace_debugfs_create(struct snd_sof_dev *sdev)
{
struct sof_mtrace_priv *priv = sdev->fw_trace_data;
struct dentry *dfs_root;
char dfs_name[100];
int i;
dfs_root = debugfs_create_dir("mtrace", sdev->debugfs_root);
if (IS_ERR_OR_NULL(dfs_root))
return 0;
/* Create files for the logging parameters */
debugfs_create_u32("aging_timer_period", 0644, dfs_root,
&priv->state_info.aging_timer_period);
debugfs_create_u32("fifo_full_timer_period", 0644, dfs_root,
&priv->state_info.fifo_full_timer_period);
debugfs_create_file("logs_priorities_mask", 0644, dfs_root, priv,
&sof_dfs_priority_mask_fops);
/* Separate log files per core */
for (i = 0; i < sdev->num_cores; i++) {
snprintf(dfs_name, sizeof(dfs_name), "core%d", i);
debugfs_create_file(dfs_name, 0444, dfs_root, &priv->cores[i],
&sof_dfs_mtrace_fops);
}
return 0;
}
static int ipc4_mtrace_enable(struct snd_sof_dev *sdev)
{
struct sof_mtrace_priv *priv = sdev->fw_trace_data;
const struct sof_ipc_ops *iops = sdev->ipc->ops;
struct sof_ipc4_msg msg;
u64 system_time;
int ret;
if (priv->mtrace_state != SOF_MTRACE_DISABLED)
return 0;
msg.primary = SOF_IPC4_MSG_TARGET(SOF_IPC4_MODULE_MSG);
msg.primary |= SOF_IPC4_MSG_DIR(SOF_IPC4_MSG_REQUEST);
msg.primary |= SOF_IPC4_MOD_ID(SOF_IPC4_MOD_INIT_BASEFW_MOD_ID);
msg.primary |= SOF_IPC4_MOD_INSTANCE(SOF_IPC4_MOD_INIT_BASEFW_INSTANCE_ID);
msg.extension = SOF_IPC4_MOD_EXT_MSG_PARAM_ID(SOF_IPC4_FW_PARAM_SYSTEM_TIME);
/*
* local_clock() is used to align with dmesg, so both kernel and firmware logs have
* the same base and a minor delta due to the IPC. system time is in us format but
* local_clock() returns the time in ns, so convert to ns.
*/
system_time = div64_u64(local_clock(), NSEC_PER_USEC);
msg.data_size = sizeof(system_time);
msg.data_ptr = &system_time;
ret = iops->set_get_data(sdev, &msg, msg.data_size, true);
if (ret)
return ret;
msg.extension = SOF_IPC4_MOD_EXT_MSG_PARAM_ID(SOF_IPC4_FW_PARAM_ENABLE_LOGS);
priv->state_info.enable = 1;
msg.data_size = sizeof(priv->state_info);
msg.data_ptr = &priv->state_info;
priv->mtrace_state = SOF_MTRACE_INITIALIZING;
ret = iops->set_get_data(sdev, &msg, msg.data_size, true);
if (ret) {
priv->mtrace_state = SOF_MTRACE_DISABLED;
return ret;
}
priv->mtrace_state = SOF_MTRACE_ENABLED;
return 0;
}
static void ipc4_mtrace_disable(struct snd_sof_dev *sdev)
{
struct sof_mtrace_priv *priv = sdev->fw_trace_data;
const struct sof_ipc_ops *iops = sdev->ipc->ops;
struct sof_ipc4_msg msg;
int i;
if (priv->mtrace_state == SOF_MTRACE_DISABLED)
return;
msg.primary = SOF_IPC4_MSG_TARGET(SOF_IPC4_MODULE_MSG);
msg.primary |= SOF_IPC4_MSG_DIR(SOF_IPC4_MSG_REQUEST);
msg.primary |= SOF_IPC4_MOD_ID(SOF_IPC4_MOD_INIT_BASEFW_MOD_ID);
msg.primary |= SOF_IPC4_MOD_INSTANCE(SOF_IPC4_MOD_INIT_BASEFW_INSTANCE_ID);
msg.extension = SOF_IPC4_MOD_EXT_MSG_PARAM_ID(SOF_IPC4_FW_PARAM_ENABLE_LOGS);
priv->state_info.enable = 0;
msg.data_size = sizeof(priv->state_info);
msg.data_ptr = &priv->state_info;
iops->set_get_data(sdev, &msg, msg.data_size, true);
priv->mtrace_state = SOF_MTRACE_DISABLED;
for (i = 0; i < sdev->num_cores; i++) {
struct sof_mtrace_core_data *core_data = &priv->cores[i];
core_data->host_read_ptr = 0;
core_data->dsp_write_ptr = 0;
wake_up(&core_data->trace_sleep);
}
}
/*
* Each DSP core logs to a dedicated slot.
* Parse the slot descriptors at debug_box offset to find the debug log slots
* and map them to cores.
* There are 15 slots and therefore 15 descriptors to check (MAX_MTRACE_SLOTS)
*/
static void sof_mtrace_find_core_slots(struct snd_sof_dev *sdev)
{
struct sof_mtrace_priv *priv = sdev->fw_trace_data;
struct sof_mtrace_core_data *core_data;
u32 slot_desc_type_offset, type, core;
int i;
for (i = 0; i < SOF_IPC4_MAX_DEBUG_SLOTS; i++) {
/* The type is the second u32 in the slot descriptor */
slot_desc_type_offset = sdev->debug_box.offset;
slot_desc_type_offset += SOF_IPC4_DEBUG_DESCRIPTOR_SIZE * i + sizeof(u32);
sof_mailbox_read(sdev, slot_desc_type_offset, &type, sizeof(type));
if ((type & SOF_MTRACE_SLOT_TYPE_MASK) == SOF_IPC4_DEBUG_SLOT_DEBUG_LOG) {
core = type & SOF_MTRACE_SLOT_CORE_MASK;
if (core >= sdev->num_cores) {
dev_dbg(sdev->dev, "core%u is invalid for slot%d\n",
core, i);
continue;
}
core_data = &priv->cores[core];
/*
* The area reserved for descriptors have the same size
* as a slot.
* In other words: slot0 starts at
* debug_box + SOF_MTRACE_SLOT_SIZE offset
*/
core_data->slot_offset = sdev->debug_box.offset;
core_data->slot_offset += SOF_IPC4_DEBUG_SLOT_SIZE * (i + 1);
dev_dbg(sdev->dev, "slot%d is used for core%u\n", i, core);
if (core_data->delayed_pos_update) {
sof_ipc4_mtrace_update_pos(sdev, core);
core_data->delayed_pos_update = false;
}
} else if (type) {
dev_dbg(sdev->dev, "slot%d is not a log slot (%#x)\n", i, type);
}
}
}
static int ipc4_mtrace_init(struct snd_sof_dev *sdev)
{
struct sof_ipc4_fw_data *ipc4_data = sdev->private;
struct sof_mtrace_priv *priv;
int i, ret;
if (sdev->fw_trace_data) {
dev_err(sdev->dev, "fw_trace_data has been already allocated\n");
return -EBUSY;
}
if (!ipc4_data->mtrace_log_bytes ||
ipc4_data->mtrace_type != SOF_IPC4_MTRACE_INTEL_CAVS_2) {
sdev->fw_trace_is_supported = false;
return 0;
}
priv = devm_kzalloc(sdev->dev, struct_size(priv, cores, sdev->num_cores),
GFP_KERNEL);
if (!priv)
return -ENOMEM;
sdev->fw_trace_data = priv;
/* Set initial values for mtrace parameters */
priv->state_info.aging_timer_period = DEFAULT_AGING_TIMER_PERIOD_MS;
priv->state_info.fifo_full_timer_period = DEFAULT_FIFO_FULL_TIMER_PERIOD_MS;
/* Only enable basefw logs initially (index 0 is always basefw) */
priv->state_info.logs_priorities_mask[0] = DEFAULT_LOGS_PRIORITIES_MASK;
for (i = 0; i < sdev->num_cores; i++) {
struct sof_mtrace_core_data *core_data = &priv->cores[i];
init_waitqueue_head(&core_data->trace_sleep);
mutex_init(&core_data->buffer_lock);
core_data->sdev = sdev;
core_data->id = i;
}
ret = ipc4_mtrace_enable(sdev);
if (ret) {
/*
* Mark firmware tracing as not supported and return 0 to not
* block the whole audio stack
*/
sdev->fw_trace_is_supported = false;
dev_dbg(sdev->dev, "initialization failed, fw tracing is disabled\n");
return 0;
}
sof_mtrace_find_core_slots(sdev);
ret = mtrace_debugfs_create(sdev);
if (ret)
ipc4_mtrace_disable(sdev);
return ret;
}
static void ipc4_mtrace_free(struct snd_sof_dev *sdev)
{
ipc4_mtrace_disable(sdev);
}
static int sof_ipc4_mtrace_update_pos_all_cores(struct snd_sof_dev *sdev)
{
int i;
for (i = 0; i < sdev->num_cores; i++)
sof_ipc4_mtrace_update_pos(sdev, i);
return 0;
}
int sof_ipc4_mtrace_update_pos(struct snd_sof_dev *sdev, int core)
{
struct sof_mtrace_priv *priv = sdev->fw_trace_data;
struct sof_mtrace_core_data *core_data;
if (!sdev->fw_trace_is_supported ||
priv->mtrace_state == SOF_MTRACE_DISABLED)
return 0;
if (core >= sdev->num_cores)
return -EINVAL;
core_data = &priv->cores[core];
if (core_data->slot_offset == SOF_IPC4_INVALID_SLOT_OFFSET) {
core_data->delayed_pos_update = true;
return 0;
}
/* Read out the dsp_write_ptr from the slot for this core */
sof_mailbox_read(sdev, core_data->slot_offset + sizeof(u32),
&core_data->dsp_write_ptr, 4);
core_data->dsp_write_ptr -= core_data->dsp_write_ptr % 4;
if (sof_debug_check_flag(SOF_DBG_PRINT_DMA_POSITION_UPDATE_LOGS))
dev_dbg(sdev->dev, "core%d, host read: %#x, dsp write: %#x",
core, core_data->host_read_ptr, core_data->dsp_write_ptr);
wake_up(&core_data->trace_sleep);
return 0;
}
static void ipc4_mtrace_fw_crashed(struct snd_sof_dev *sdev)
{
/*
* The DSP might not be able to send SOF_IPC4_NOTIFY_LOG_BUFFER_STATUS
* messages anymore, so check the log buffer status on all
* cores and process any pending messages.
*/
sof_ipc4_mtrace_update_pos_all_cores(sdev);
}
static int ipc4_mtrace_resume(struct snd_sof_dev *sdev)
{
return ipc4_mtrace_enable(sdev);
}
static void ipc4_mtrace_suspend(struct snd_sof_dev *sdev, pm_message_t pm_state)
{
ipc4_mtrace_disable(sdev);
}
const struct sof_ipc_fw_tracing_ops ipc4_mtrace_ops = {
.init = ipc4_mtrace_init,
.free = ipc4_mtrace_free,
.fw_crashed = ipc4_mtrace_fw_crashed,
.suspend = ipc4_mtrace_suspend,
.resume = ipc4_mtrace_resume,
};
Codebase Browser
linux