Quelle  ipc4-mtrace.c   Sprache: C

// 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,
};