// SPDX-License-Identifier: GPL-2.0-only // // Copyright(c) 2022 Intel Corporation. All rights reserved. #include #include #include #include #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, };