[alsa-devel] [PATCH v4 07/14] ASoC: SOF: Add DSP firmware logger support

[Pierre-Louis Bossart]

From: Liam Girdwood <liam.r.girdwood at linux.intel.com>

This patch adds support for real-time DSP logging (timestamped events
and bespoke binary data) for firmware debug. The current solution
relies on DMA transfers to system memory that is then accessed by
userspace tools such as sof-logger. For Intel platforms, two types of
DMAs are currently used (GP-DMA for Baytrail/CherryTrail and HDaudio
DMA for SKL+)

Due to historical reasons, the driver code follows the DSP firmware
conventions and refers to 'traces', but it is currently unrelated to
the Linux trace subsystem. Future solutions will include support for
more advanced hardware (e.g. MIPI Sys-T), additional formats and the
ability to enable/disable specific traces dynamically.

Signed-off-by: Pan Xiuli <xiuli.pan at linux.intel.com>
Signed-off-by: Liam Girdwood <liam.r.girdwood at linux.intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart at linux.intel.com>
---
 sound/soc/sof/trace.c | 298 ++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 298 insertions(+)
 create mode 100644 sound/soc/sof/trace.c

diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c
new file mode 100644
index 000000000000..d74074096dcb
--- /dev/null
+++ b/sound/soc/sof/trace.c
@@ -0,0 +1,298 @@
+// SPDX-License-Identifier: (GPL-2.0 OR BSD-3-Clause)
+//
+// This file is provided under a dual BSD/GPLv2 license.  When using or
+// redistributing this file, you may do so under either license.
+//
+// Copyright(c) 2018 Intel Corporation. All rights reserved.
+//
+// Author: Liam Girdwood <liam.r.girdwood at linux.intel.com>
+//
+
+#include <linux/debugfs.h>
+#include <linux/sched/signal.h>
+#include "sof-priv.h"
+#include "ops.h"
+
+static size_t sof_wait_trace_avail(struct snd_sof_dev *sdev,
+				   loff_t pos, size_t buffer_size)
+{
+	wait_queue_entry_t wait;
+
+	/*
+	 * If host offset is less than local pos, it means write pointer of
+	 * host DMA buffer has been wrapped. We should output the trace data
+	 * at the end of host DMA buffer at first.
+	 */
+	if (sdev->host_offset < pos)
+		return buffer_size - pos;
+
+	/* If there is available trace data now, it is unnecessary to wait. */
+	if (sdev->host_offset > pos)
+		return sdev->host_offset - pos;
+
+	/* wait for available trace data from FW */
+	init_waitqueue_entry(&wait, current);
+	set_current_state(TASK_INTERRUPTIBLE);
+	add_wait_queue(&sdev->trace_sleep, &wait);
+
+	if (signal_pending(current)) {
+		remove_wait_queue(&sdev->trace_sleep, &wait);
+	} else {
+		/* set timeout to max value, no error code */
+		schedule_timeout(MAX_SCHEDULE_TIMEOUT);
+		remove_wait_queue(&sdev->trace_sleep, &wait);
+	}
+
+	/* return bytes available for copy */
+	if (sdev->host_offset < pos)
+		return buffer_size - pos;
+
+	return sdev->host_offset - pos;
+}
+
+static ssize_t sof_dfsentry_trace_read(struct file *file, char __user *buffer,
+				       size_t count, loff_t *ppos)
+{
+	struct snd_sof_dfsentry *dfse = file->private_data;
+	struct snd_sof_dev *sdev = dfse->sdev;
+	unsigned long rem;
+	loff_t lpos = *ppos;
+	size_t avail, buffer_size = dfse->size;
+	u64 lpos_64;
+
+	/* make sure we know about any failures on the DSP side */
+	sdev->dtrace_error = false;
+
+	/* check pos and count */
+	if (lpos < 0)
+		return -EINVAL;
+	if (!count)
+		return 0;
+
+	/* check for buffer wrap and count overflow */
+	lpos_64 = lpos;
+	lpos = do_div(lpos_64, buffer_size);
+
+	if (count > buffer_size - lpos) /* min() not used to avoid sparse warnings */
+		count = buffer_size - lpos;
+
+	/* get available count based on current host offset */
+	avail = sof_wait_trace_avail(sdev, lpos, buffer_size);
+	if (sdev->dtrace_error) {
+		dev_err(sdev->dev, "error: trace IO error\n");
+		return -EIO;
+	}
+
+	/* make sure count is <= avail */
+	count = avail > count ? count : avail;
+
+	/* copy available trace data to debugfs */
+	rem = copy_to_user(buffer, dfse->buf + lpos, count);
+	if (rem == count)
+		return -EFAULT;
+
+	*ppos += count;
+
+	/* move debugfs reading position */
+	return count;
+}
+
+static const struct file_operations sof_dfs_trace_fops = {
+	.open = simple_open,
+	.read = sof_dfsentry_trace_read,
+	.llseek = default_llseek,
+};
+
+static int trace_debugfs_create(struct snd_sof_dev *sdev)
+{
+	struct snd_sof_dfsentry *dfse;
+
+	if (!sdev)
+		return -EINVAL;
+
+	dfse = devm_kzalloc(sdev->dev, sizeof(*dfse), GFP_KERNEL);
+	if (!dfse)
+		return -ENOMEM;
+
+	dfse->type = SOF_DFSENTRY_TYPE_BUF;
+	dfse->buf = sdev->dmatb.area;
+	dfse->size = sdev->dmatb.bytes;
+	dfse->sdev = sdev;
+
+	dfse->dfsentry = debugfs_create_file("trace", 0444, sdev->debugfs_root,
+					     dfse, &sof_dfs_trace_fops);
+	if (!dfse->dfsentry) {
+		/* can't rely on debugfs, only log error and keep going */
+		dev_err(sdev->dev,
+			"error: cannot create debugfs entry for trace\n");
+	}
+
+	return 0;
+}
+
+int snd_sof_init_trace_ipc(struct snd_sof_dev *sdev)
+{
+	struct sof_ipc_dma_trace_params params;
+	struct sof_ipc_reply ipc_reply;
+	int ret;
+
+	if (sdev->dtrace_is_enabled || !sdev->dma_trace_pages)
+		return -EINVAL;
+
+	/* set IPC parameters */
+	params.hdr.size = sizeof(params);
+	params.hdr.cmd = SOF_IPC_GLB_TRACE_MSG | SOF_IPC_TRACE_DMA_PARAMS;
+	params.buffer.phy_addr = sdev->dmatp.addr;
+	params.buffer.size = sdev->dmatb.bytes;
+	params.buffer.offset = 0;
+	params.buffer.pages = sdev->dma_trace_pages;
+	params.stream_tag = 0;
+
+	sdev->host_offset = 0;
+
+	ret = snd_sof_dma_trace_init(sdev, &params.stream_tag);
+	if (ret < 0) {
+		dev_err(sdev->dev,
+			"error: fail in snd_sof_dma_trace_init %d\n", ret);
+		return ret;
+	}
+	dev_dbg(sdev->dev, "stream_tag: %d\n", params.stream_tag);
+
+	/* send IPC to the DSP */
+	ret = sof_ipc_tx_message(sdev->ipc,
+				 params.hdr.cmd, &params, sizeof(params),
+				 &ipc_reply, sizeof(ipc_reply));
+	if (ret < 0) {
+		dev_err(sdev->dev,
+			"error: can't set params for DMA for trace %d\n", ret);
+		goto trace_release;
+	}
+
+	ret = snd_sof_dma_trace_trigger(sdev, SNDRV_PCM_TRIGGER_START);
+	if (ret < 0) {
+		dev_err(sdev->dev,
+			"error: snd_sof_dma_trace_trigger: start: %d\n", ret);
+		goto trace_release;
+	}
+
+	sdev->dtrace_is_enabled = true;
+
+	return 0;
+
+trace_release:
+	snd_sof_dma_trace_release(sdev);
+	return ret;
+}
+
+int snd_sof_init_trace(struct snd_sof_dev *sdev)
+{
+	int ret;
+
+	/* set false before start initialization */
+	sdev->dtrace_is_enabled = false;
+
+	/* allocate trace page table buffer */
+	ret = snd_dma_alloc_pages(SNDRV_DMA_TYPE_DEV, sdev->dev,
+				  PAGE_SIZE, &sdev->dmatp);
+	if (ret < 0) {
+		dev_err(sdev->dev,
+			"error: can't alloc page table for trace %d\n", ret);
+		return ret;
+	}
+
+	/* allocate trace data buffer */
+	ret = snd_dma_alloc_pages(SNDRV_DMA_TYPE_DEV_SG, sdev->dev,
+				  DMA_BUF_SIZE_FOR_TRACE, &sdev->dmatb);
+	if (ret < 0) {
+		dev_err(sdev->dev,
+			"error: can't alloc buffer for trace %d\n", ret);
+		goto page_err;
+	}
+
+	/* create compressed page table for audio firmware */
+	ret = snd_sof_create_page_table(sdev, &sdev->dmatb, sdev->dmatp.area,
+					sdev->dmatb.bytes);
+	if (ret < 0)
+		goto table_err;
+
+	sdev->dma_trace_pages = ret;
+	dev_dbg(sdev->dev, "dma_trace_pages: %d\n", sdev->dma_trace_pages);
+
+	if (sdev->first_boot) {
+		ret = trace_debugfs_create(sdev);
+		if (ret < 0)
+			goto table_err;
+	}
+
+	init_waitqueue_head(&sdev->trace_sleep);
+
+	ret = snd_sof_init_trace_ipc(sdev);
+	if (ret < 0)
+		goto table_err;
+
+	return 0;
+table_err:
+	sdev->dma_trace_pages = 0;
+	snd_dma_free_pages(&sdev->dmatb);
+page_err:
+	snd_dma_free_pages(&sdev->dmatp);
+	return ret;
+}
+EXPORT_SYMBOL(snd_sof_init_trace);
+
+int snd_sof_trace_update_pos(struct snd_sof_dev *sdev,
+			     struct sof_ipc_dma_trace_posn *posn)
+{
+	if (sdev->dtrace_is_enabled && sdev->host_offset != posn->host_offset) {
+		sdev->host_offset = posn->host_offset;
+		wake_up(&sdev->trace_sleep);
+	}
+
+	if (posn->overflow != 0)
+		dev_err(sdev->dev,
+			"error: DSP trace buffer overflow %u bytes. Total messages %d\n",
+			posn->overflow, posn->messages);
+
+	return 0;
+}
+
+/* an error has occurred within the DSP that prevents further trace */
+void snd_sof_trace_notify_for_error(struct snd_sof_dev *sdev)
+{
+	if (sdev->dtrace_is_enabled) {
+		dev_err(sdev->dev, "error: waking up any trace sleepers\n");
+		sdev->dtrace_error = true;
+		wake_up(&sdev->trace_sleep);
+	}
+}
+EXPORT_SYMBOL(snd_sof_trace_notify_for_error);
+
+void snd_sof_release_trace(struct snd_sof_dev *sdev)
+{
+	int ret;
+
+	if (!sdev->dtrace_is_enabled)
+		return;
+
+	ret = snd_sof_dma_trace_trigger(sdev, SNDRV_PCM_TRIGGER_STOP);
+	if (ret < 0)
+		dev_err(sdev->dev,
+			"error: snd_sof_dma_trace_trigger: stop: %d\n", ret);
+
+	ret = snd_sof_dma_trace_release(sdev);
+	if (ret < 0)
+		dev_err(sdev->dev,
+			"error: fail in snd_sof_dma_trace_release %d\n", ret);
+
+	sdev->dtrace_is_enabled = false;
+}
+EXPORT_SYMBOL(snd_sof_release_trace);
+
+void snd_sof_free_trace(struct snd_sof_dev *sdev)
+{
+	snd_sof_release_trace(sdev);
+
+	snd_dma_free_pages(&sdev->dmatb);
+	snd_dma_free_pages(&sdev->dmatp);
+}
+EXPORT_SYMBOL(snd_sof_free_trace);
-- 
2.17.1