[v2,07/12] ASoC: SOF: Add DSP firmware trace event support
diff mbox series

Message ID 20180831151910.16122-8-liam.r.girdwood@linux.intel.com
State New
Headers show
Series
  • Sound Open Firmware Core
Related show

Commit Message

Liam Girdwood Aug. 31, 2018, 3:19 p.m. UTC
Add a trace event buffer that can be used by userspace to read DSP runtime
trace events alongside bespoke trace data in realtime for firmware debug.

Signed-off-by: Liam Girdwood <liam.r.girdwood@linux.intel.com>
---
 sound/soc/sof/sof-priv.h |   1 +
 sound/soc/sof/trace.c    | 293 +++++++++++++++++++++++++++++++++++++++
 2 files changed, 294 insertions(+)
 create mode 100644 sound/soc/sof/trace.c

Comments

Mark Brown Sept. 3, 2018, 4:25 p.m. UTC | #1
On Fri, Aug 31, 2018 at 04:19:05PM +0100, Liam Girdwood wrote:

> Add a trace event buffer that can be used by userspace to read DSP runtime
> trace events alongside bespoke trace data in realtime for firmware debug.

Should this be integrated into the Linux trace event mechanism rather
than open coded?  It would at least be nice to not call this a trace
event buffer - when I initially read this I was expecting it to be for
the standard Linux stuff which obviously it isn't.
Liam Girdwood Sept. 4, 2018, 1:21 p.m. UTC | #2
On Mon, 2018-09-03 at 17:25 +0100, Mark Brown wrote:
> On Fri, Aug 31, 2018 at 04:19:05PM +0100, Liam Girdwood wrote:
> 
> > Add a trace event buffer that can be used by userspace to read DSP runtime
> > trace events alongside bespoke trace data in realtime for firmware debug.
> 
> Should this be integrated into the Linux trace event mechanism rather
> than open coded?  It would at least be nice to not call this a trace
> event buffer - when I initially read this I was expecting it to be for
> the standard Linux stuff which obviously it isn't.

Your right, I'll rename. The eventual aim is to make it more like Linux trace
but we are constrained somewhat as some DSPs only 96kB or instruction RAM, hence
it's a simple and raw trace infrastructure.

Liam
Mark Brown Sept. 4, 2018, 3:03 p.m. UTC | #3
On Tue, Sep 04, 2018 at 02:21:20PM +0100, Liam Girdwood wrote:
> On Mon, 2018-09-03 at 17:25 +0100, Mark Brown wrote:

> > Should this be integrated into the Linux trace event mechanism rather
> > than open coded?  It would at least be nice to not call this a trace
> > event buffer - when I initially read this I was expecting it to be for
> > the standard Linux stuff which obviously it isn't.

> Your right, I'll rename. The eventual aim is to make it more like Linux trace
> but we are constrained somewhat as some DSPs only 96kB or instruction RAM, hence
> it's a simple and raw trace infrastructure.

I was thinking the code could read it like it's doing now and then just
have a trace event to dump it into the core trace infrastructure as it
reads things in.
Liam Girdwood Sept. 4, 2018, 3:28 p.m. UTC | #4
On Tue, 2018-09-04 at 16:03 +0100, Mark Brown wrote:
> On Tue, Sep 04, 2018 at 02:21:20PM +0100, Liam Girdwood wrote:
> > On Mon, 2018-09-03 at 17:25 +0100, Mark Brown wrote:
> > > Should this be integrated into the Linux trace event mechanism rather
> > > than open coded?  It would at least be nice to not call this a trace
> > > event buffer - when I initially read this I was expecting it to be for
> > > the standard Linux stuff which obviously it isn't.
> > Your right, I'll rename. The eventual aim is to make it more like Linux
> > trace
> > but we are constrained somewhat as some DSPs only 96kB or instruction RAM,
> > hence
> > it's a simple and raw trace infrastructure.
> 
> I was thinking the code could read it like it's doing now and then just
> have a trace event to dump it into the core trace infrastructure as it
> reads things in.

Most of the data is binary atm, so we were decoding in userspace. Any objection
to decoding in the kernel as different trace events ?

Thanks

Liam
Mark Brown Sept. 4, 2018, 3:46 p.m. UTC | #5
On Tue, Sep 04, 2018 at 04:28:49PM +0100, Liam Girdwood wrote:
> On Tue, 2018-09-04 at 16:03 +0100, Mark Brown wrote:

> > I was thinking the code could read it like it's doing now and then just
> > have a trace event to dump it into the core trace infrastructure as it
> > reads things in.

> Most of the data is binary atm, so we were decoding in userspace. Any objection
> to decoding in the kernel as different trace events ?

I wouldn't think so.

The way the trace stuff works is that the writer dumps blocks of data
into the trace buffer in raw binary form in a structured block tagged
with the event type and then later on when something reads out the
buffer they can be formatted as desired, including things like hex dumps
(IIRC there's facilities to just get the raw buffer entries too, I've
only ever used the human readable interface myself, writing software is
hard).  This gives very fast writes which is really nice for anything
performance sensitive and means you can leave trace on a lot more than
you would otherwise.  I'd guess if you were decoding it'd just be
splitting the buffer up into per message chunks.
Liam Girdwood Sept. 20, 2018, 4:02 p.m. UTC | #6
On Tue, 2018-09-04 at 16:46 +0100, Mark Brown wrote:
> On Tue, Sep 04, 2018 at 04:28:49PM +0100, Liam Girdwood wrote:
> > On Tue, 2018-09-04 at 16:03 +0100, Mark Brown wrote:
> > > I was thinking the code could read it like it's doing now and then just
> > > have a trace event to dump it into the core trace infrastructure as it
> > > reads things in.
> > Most of the data is binary atm, so we were decoding in userspace. Any
> > objection
> > to decoding in the kernel as different trace events ?
> 
> I wouldn't think so.
> 

I was initially thinking about a partial decode. The FW has many subsystems for
trace that can be individually switched on/off via IPC. e.g. driver would read
the trace packet class and then call the appropriate trace event for that class
(note that class is not decoded any further). But I'm not so sure now as these
classes can change at runtime based on topologies. 

> The way the trace stuff works is that the writer dumps blocks of data
> into the trace buffer in raw binary form in a structured block tagged
> with the event type and then later on when something reads out the
> buffer they can be formatted as desired, including things like hex dumps
> (IIRC there's facilities to just get the raw buffer entries too, I've
> only ever used the human readable interface myself, writing software is
> hard). 

Yeah, I'm just reading up on this now, human readable is easy.

>  This gives very fast writes which is really nice for anything
> performance sensitive and means you can leave trace on a lot more than
> you would otherwise.  I'd guess if you were decoding it'd just be
> splitting the buffer up into per message chunks.

So I think now we will trace the driver side (easy) and then trace event
firmware trace packets as ASCII text (which userspace would decode).

I will delay upstreaming the trace part so v4 will be sent minus trace.

I will probably have some debugFS interface that would export dynamic firmware
trace tuning controls.

Liam

> _______________________________________________
> Alsa-devel mailing list
> Alsa-devel@alsa-project.org
> http://mailman.alsa-project.org/mailman/listinfo/alsa-devel

Patch
diff mbox series

diff --git a/sound/soc/sof/sof-priv.h b/sound/soc/sof/sof-priv.h
index 0d2cfeb18a65..bd33e9437d02 100644
--- a/sound/soc/sof/sof-priv.h
+++ b/sound/soc/sof/sof-priv.h
@@ -357,6 +357,7 @@  struct snd_sof_dev {
 	wait_queue_head_t trace_sleep;
 	u32 host_offset;
 	bool dtrace_is_enabled;
+	bool dtrace_error;
 
 	void *private;			/* core does not touch this */
 };
diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c
new file mode 100644
index 000000000000..bd72a12bc7a6
--- /dev/null
+++ b/sound/soc/sof/trace.c
@@ -0,0 +1,293 @@ 
+// 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@linux.intel.com>
+//         Yan Wang <yan.wan@linux.intel.com>
+//
+
+#include <linux/delay.h>
+#include <linux/fs.h>
+#include <linux/slab.h>
+#include <linux/sched/signal.h>
+#include <linux/time.h>
+#include <linux/device.h>
+#include <linux/interrupt.h>
+#include <linux/module.h>
+#include <linux/dma-mapping.h>
+#include <linux/platform_device.h>
+#include <linux/firmware.h>
+#include <linux/debugfs.h>
+#include <uapi/sound/sof-ipc.h>
+#include <uapi/sound/sof-fw.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);
+		goto out;
+	}
+
+	/* set timeout to max value, no error code */
+	schedule_timeout(MAX_SCHEDULE_TIMEOUT);
+	remove_wait_queue(&sdev->trace_sleep, &wait);
+
+out:
+	/* return bytes available for copy */
+	if (sdev->host_offset < pos)
+		return buffer_size - pos;
+	else
+		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_buf *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)
+		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_buf *dfse;
+
+	if (!sdev)
+		return -EINVAL;
+
+	dfse = kzalloc(sizeof(*dfse), GFP_KERNEL);
+	if (!dfse)
+		return -ENOMEM;
+
+	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) {
+		dev_err(sdev->dev,
+			"error: cannot create debugfs entry for trace\n");
+		kfree(dfse);
+		return -ENODEV;
+	}
+
+	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;
+
+	/* 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;
+
+	init_waitqueue_head(&sdev->trace_sleep);
+	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);
+		return ret;
+	}
+
+	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);
+		return ret;
+	}
+
+	sdev->dtrace_is_enabled = true;
+
+	return 0;
+}
+
+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->parent,
+				  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->parent,
+				  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;
+	}
+
+	/* craete 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);
+
+	ret = trace_debugfs_create(sdev);
+	if (ret < 0)
+		goto table_err;
+
+	ret = snd_sof_init_trace_ipc(sdev);
+	if (ret < 0)
+		goto table_err;
+
+	return 0;
+table_err:
+	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);
+
+	snd_dma_free_pages(&sdev->dmatb);
+	snd_dma_free_pages(&sdev->dmatp);
+}
+EXPORT_SYMBOL(snd_sof_release_trace);