diff mbox series

[v4,07/14] ASoC: SOF: Add DSP firmware logger support

Message ID 20190213220734.10471-8-pierre-louis.bossart@linux.intel.com (mailing list archive)
State New, archived
Headers show
Series ASoC: Sound Open Firmware (SOF) core | expand

Commit Message

Pierre-Louis Bossart Feb. 13, 2019, 10:07 p.m. UTC
From: Liam Girdwood <liam.r.girdwood@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@linux.intel.com>
Signed-off-by: Liam Girdwood <liam.r.girdwood@linux.intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
---
 sound/soc/sof/trace.c | 298 ++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 298 insertions(+)
 create mode 100644 sound/soc/sof/trace.c

Comments

Takashi Iwai Feb. 14, 2019, 1:19 p.m. UTC | #1
On Wed, 13 Feb 2019 23:07:27 +0100,
Pierre-Louis Bossart wrote:
> 
> +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);
> +	}

Can be slightly optimized here, e.g. no need of two
remove_wait_queue() calls.

> +
> +	/* return bytes available for copy */
> +	if (sdev->host_offset < pos)
> +		return buffer_size - pos;
> +
> +	return sdev->host_offset - pos;

Are these sdev->host_offset accesses race-free?

If I understand correctly, snd_sof_trace_update_pos() can be called at
any time, and the offset might become inconsistent during these
multiple references.


thanks,

Takashi
Pierre-Louis Bossart Feb. 14, 2019, 3:13 p.m. UTC | #2
On 2/14/19 7:19 AM, Takashi Iwai wrote:
> On Wed, 13 Feb 2019 23:07:27 +0100,
> Pierre-Louis Bossart wrote:
>>
>> +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);
>> +	}
> 
> Can be slightly optimized here, e.g. no need of two
> remove_wait_queue() calls.


Yes. This was cleaned-up to remove a goto but we missed the common code. 
will fix

> 
>> +
>> +	/* return bytes available for copy */
>> +	if (sdev->host_offset < pos)
>> +		return buffer_size - pos;
>> +
>> +	return sdev->host_offset - pos;
> 
> Are these sdev->host_offset accesses race-free?
> 
> If I understand correctly, snd_sof_trace_update_pos() can be called at
> any time, and the offset might become inconsistent during these
> multiple references.


It's my understanding that there is a single trace stream and a single 
consumer (via a debugfs file), but will double check.
Mark Brown Feb. 20, 2019, 5:44 p.m. UTC | #3
On Wed, Feb 13, 2019 at 04:07:27PM -0600, Pierre-Louis Bossart wrote:

> +	/* make sure count is <= avail */
> +	count = avail > count ? count : avail;

count = min(avail, count)?
Pierre-Louis Bossart Feb. 20, 2019, 8:18 p.m. UTC | #4
On 2/20/19 11:44 AM, Mark Brown wrote:
> On Wed, Feb 13, 2019 at 04:07:27PM -0600, Pierre-Louis Bossart wrote:
>
>> +	/* make sure count is <= avail */
>> +	count = avail > count ? count : avail;
> count = min(avail, count)?
as discussed in the last review, we didn't use min() since it adds a 
number of obscure warnings with sparse. I haven't found any time to look 
into this so for now left the code as is. Sparse is a useful tool for 
the address checks (topology/DMAs with _le32, __iomem, etc), the fewer 
warnings we get the better.
Andy Shevchenko Feb. 21, 2019, 12:29 p.m. UTC | #5
On Wed, Feb 20, 2019 at 02:18:01PM -0600, Pierre-Louis Bossart wrote:
> On 2/20/19 11:44 AM, Mark Brown wrote:
> > On Wed, Feb 13, 2019 at 04:07:27PM -0600, Pierre-Louis Bossart wrote:

> > > +	/* make sure count is <= avail */
> > > +	count = avail > count ? count : avail;
> > count = min(avail, count)?
> as discussed in the last review, we didn't use min() since it adds a number
> of obscure warnings with sparse. I haven't found any time to look into this
> so for now left the code as is. Sparse is a useful tool for the address
> checks (topology/DMAs with _le32, __iomem, etc), the fewer warnings we get
> the better.

Shouldn't be sparse itself get fixed?
Pierre-Louis Bossart Feb. 21, 2019, 2:57 p.m. UTC | #6
>>>> +	/* make sure count is <= avail */
>>>> +	count = avail > count ? count : avail;
>>> count = min(avail, count)?
>> as discussed in the last review, we didn't use min() since it adds a number
>> of obscure warnings with sparse. I haven't found any time to look into this
>> so for now left the code as is. Sparse is a useful tool for the address
>> checks (topology/DMAs with _le32, __iomem, etc), the fewer warnings we get
>> the better.
> Shouldn't be sparse itself get fixed?
Absolutely. I just don't have time to even look into it given all the 
feedback on the kernel patches I have to deal with :-)
Mark Brown Feb. 21, 2019, 3:04 p.m. UTC | #7
On Thu, Feb 21, 2019 at 02:29:57PM +0200, Andy Shevchenko wrote:
> On Wed, Feb 20, 2019 at 02:18:01PM -0600, Pierre-Louis Bossart wrote:

> > as discussed in the last review, we didn't use min() since it adds a number
> > of obscure warnings with sparse. I haven't found any time to look into this
> > so for now left the code as is. Sparse is a useful tool for the address
> > checks (topology/DMAs with _le32, __iomem, etc), the fewer warnings we get
> > the better.

> Shouldn't be sparse itself get fixed?

Ideally.  We had this discussion last time :/
diff mbox series

Patch

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@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);