From e43a64d36f55d05b464762d23bc0c23c49fa96b6 Mon Sep 17 00:00:00 2001 From: Peter Ujfalusi Date: Wed, 16 Mar 2022 15:08:47 +0200 Subject: [PATCH 1/6] ASoC: SOF: trace: Introduce SOF_DTRACE_INITIALIZING state With the new state we can make sure we are not missing the first host_offset update. In case the dtrace is small, the DMA copy will be fast and depending on the moonphase it might be done before we set the sdev->dtrace_state to SOF_DTRACE_ENABLED. The DMA will start the copy as soon as the host starts the DMA. Set the dtrace to enabled before we let the DMA to run in order to avoid missing the position update. The new state is needed to cover architectures where the host side snd_sof_dma_trace_trigger() is a NOP and the dtrace in the firmware is ready as soon as the IPC message has been processed. Signed-off-by: Peter Ujfalusi --- sound/soc/sof/sof-priv.h | 1 + sound/soc/sof/trace.c | 19 ++++++++++++++----- 2 files changed, 15 insertions(+), 5 deletions(-) diff --git a/sound/soc/sof/sof-priv.h b/sound/soc/sof/sof-priv.h index 8678972b00adc6..df8a4698dfa8ff 100644 --- a/sound/soc/sof/sof-priv.h +++ b/sound/soc/sof/sof-priv.h @@ -446,6 +446,7 @@ struct snd_sof_ipc { enum sof_dtrace_state { SOF_DTRACE_DISABLED, SOF_DTRACE_STOPPED, + SOF_DTRACE_INITIALIZING, SOF_DTRACE_ENABLED, }; diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c index 5d171bf8a5ea1c..3ec2a361ede97c 100644 --- a/sound/soc/sof/trace.c +++ b/sound/soc/sof/trace.c @@ -18,6 +18,15 @@ #define TRACE_FILTER_ELEMENTS_PER_ENTRY 4 #define TRACE_FILTER_MAX_CONFIG_STRING_LENGTH 1024 +static bool trace_pos_update_expected(struct snd_sof_dev *sdev) +{ + if (sdev->dtrace_state == SOF_DTRACE_ENABLED || + sdev->dtrace_state == SOF_DTRACE_INITIALIZING) + return true; + + return false; +} + static int trace_filter_append_elem(struct snd_sof_dev *sdev, uint32_t key, uint32_t value, struct sof_ipc_trace_filter_elem *elem_list, int capacity, int *counter) @@ -263,7 +272,7 @@ static size_t sof_wait_trace_avail(struct snd_sof_dev *sdev, if (ret) return ret; - if (sdev->dtrace_state != SOF_DTRACE_ENABLED && sdev->dtrace_draining) { + if (sdev->dtrace_draining && !trace_pos_update_expected(sdev)) { /* * tracing has ended and all traces have been * read by client, return EOF @@ -429,6 +438,7 @@ static int snd_sof_enable_trace(struct snd_sof_dev *sdev) dev_dbg(sdev->dev, "%s: stream_tag: %d\n", __func__, params.stream_tag); /* send IPC to the DSP */ + sdev->dtrace_state = SOF_DTRACE_INITIALIZING; ret = sof_ipc_tx_message(sdev->ipc, ¶ms, sizeof(params), &ipc_reply, sizeof(ipc_reply)); if (ret < 0) { dev_err(sdev->dev, @@ -437,6 +447,8 @@ static int snd_sof_enable_trace(struct snd_sof_dev *sdev) } start: + sdev->dtrace_state = SOF_DTRACE_ENABLED; + ret = snd_sof_dma_trace_trigger(sdev, SNDRV_PCM_TRIGGER_START); if (ret < 0) { dev_err(sdev->dev, @@ -444,8 +456,6 @@ static int snd_sof_enable_trace(struct snd_sof_dev *sdev) goto trace_release; } - sdev->dtrace_state = SOF_DTRACE_ENABLED; - return 0; trace_release: @@ -524,8 +534,7 @@ int snd_sof_trace_update_pos(struct snd_sof_dev *sdev, if (!sdev->dtrace_is_supported) return 0; - if (sdev->dtrace_state == SOF_DTRACE_ENABLED && - sdev->host_offset != posn->host_offset) { + if (trace_pos_update_expected(sdev) && sdev->host_offset != posn->host_offset) { sdev->host_offset = posn->host_offset; wake_up(&sdev->trace_sleep); } From 18bcb31b16960428021e74b1e561e9977132f870 Mon Sep 17 00:00:00 2001 From: Peter Ujfalusi Date: Mon, 14 Mar 2022 09:38:09 +0200 Subject: [PATCH 2/6] ASoC: SOF: trace: Add helper function to update the sdev->host_offset We are using the READ_ONCE() on the debugfs read path for accessing sdev->host_offset, but the set is not atomic or protected in any way. Add a small helper to do the host_offset update and be really paranoid about the a possible race in update Signed-off-by: Peter Ujfalusi --- sound/soc/sof/trace.c | 25 ++++++++++++++++++++----- 1 file changed, 20 insertions(+), 5 deletions(-) diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c index 3ec2a361ede97c..b3adc626d8323e 100644 --- a/sound/soc/sof/trace.c +++ b/sound/soc/sof/trace.c @@ -242,6 +242,21 @@ static int trace_debugfs_filter_create(struct snd_sof_dev *sdev) return 0; } +static bool sof_trace_set_host_offset(struct snd_sof_dev *sdev, u32 new_offset) +{ + u32 host_offset = READ_ONCE(sdev->host_offset); + + if (host_offset != new_offset) { + /* This is a bit paranoid and unlikely that it is needed */ + u32 ret = cmpxchg(&sdev->host_offset, host_offset, new_offset); + + if (ret == host_offset) + return true; + } + + return false; +} + static size_t sof_trace_avail(struct snd_sof_dev *sdev, loff_t pos, size_t buffer_size) { @@ -354,7 +369,7 @@ static int sof_dfsentry_trace_release(struct inode *inode, struct file *file) /* avoid duplicate traces at next open */ if (sdev->dtrace_state != SOF_DTRACE_ENABLED) - sdev->host_offset = 0; + sof_trace_set_host_offset(sdev, 0); return 0; } @@ -426,7 +441,7 @@ static int snd_sof_enable_trace(struct snd_sof_dev *sdev) params.buffer.pages = sdev->dma_trace_pages; params.stream_tag = 0; - sdev->host_offset = 0; + sof_trace_set_host_offset(sdev, 0); sdev->dtrace_draining = false; ret = snd_sof_dma_trace_init(sdev, ¶ms); @@ -534,9 +549,9 @@ int snd_sof_trace_update_pos(struct snd_sof_dev *sdev, if (!sdev->dtrace_is_supported) return 0; - if (trace_pos_update_expected(sdev) && sdev->host_offset != posn->host_offset) { - sdev->host_offset = posn->host_offset; - wake_up(&sdev->trace_sleep); + if (trace_pos_update_expected(sdev)) { + if (sof_trace_set_host_offset(sdev, posn->host_offset)) + wake_up(&sdev->trace_sleep); } if (posn->overflow != 0) From a3cdaadc30c1949d29c56d6d5b3dfc665f54e61b Mon Sep 17 00:00:00 2001 From: Peter Ujfalusi Date: Mon, 14 Mar 2022 12:04:48 +0200 Subject: [PATCH 3/6] ASoC: SOF: trace: Return from trace_read if there is no new data available If no new trace data is available then return immediately, there is no need to continue with the execution of the trace_read() function. Signed-off-by: Peter Ujfalusi --- sound/soc/sof/trace.c | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c index b3adc626d8323e..a6f1c30a67ef0e 100644 --- a/sound/soc/sof/trace.c +++ b/sound/soc/sof/trace.c @@ -340,6 +340,10 @@ static ssize_t sof_dfsentry_trace_read(struct file *file, char __user *buffer, return -EIO; } + /* no new trace data */ + if (!avail) + return 0; + /* make sure count is <= avail */ if (count > avail) count = avail; From dfc1f81392a71c46ecd8a22af51e08f454d2835e Mon Sep 17 00:00:00 2001 From: Peter Ujfalusi Date: Mon, 14 Mar 2022 12:23:53 +0200 Subject: [PATCH 4/6] ASoC: SOF: trace: Print out the new host_offset value on change Printing out the host_offset can help tracking the progress and can provide insights of anything suspicious going on with the dtrace. Signed-off-by: Peter Ujfalusi --- sound/soc/sof/trace.c | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c index a6f1c30a67ef0e..2937edb22d8449 100644 --- a/sound/soc/sof/trace.c +++ b/sound/soc/sof/trace.c @@ -250,8 +250,10 @@ static bool sof_trace_set_host_offset(struct snd_sof_dev *sdev, u32 new_offset) /* This is a bit paranoid and unlikely that it is needed */ u32 ret = cmpxchg(&sdev->host_offset, host_offset, new_offset); - if (ret == host_offset) + if (ret == host_offset) { + dev_dbg(sdev->dev, "trace: new host_offset: %#x\n", new_offset); return true; + } } return false; From 92a74881544da77ef14b5ad915eeb9b4308ba115 Mon Sep 17 00:00:00 2001 From: Peter Ujfalusi Date: Wed, 16 Mar 2022 15:09:00 +0200 Subject: [PATCH 5/6] ASoC: SOF: trace: DEBUG messages for reading To see what is actually going on. Signed-off-by: Peter Ujfalusi --- sound/soc/sof/trace.c | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c index 2937edb22d8449..b0e98bec9539ea 100644 --- a/sound/soc/sof/trace.c +++ b/sound/soc/sof/trace.c @@ -322,6 +322,8 @@ static ssize_t sof_dfsentry_trace_read(struct file *file, char __user *buffer, size_t avail, buffer_size = dfse->size; u64 lpos_64; + dev_dbg(sdev->dev, "trace: %s: ENTER (count: %zu, lpos: %llu)\n", __func__, count, lpos); + /* make sure we know about any failures on the DSP side */ sdev->dtrace_error = false; @@ -343,8 +345,10 @@ static ssize_t sof_dfsentry_trace_read(struct file *file, char __user *buffer, } /* no new trace data */ - if (!avail) + if (!avail) { + dev_dbg(sdev->dev, "trace: nothing to copy\n"); return 0; + } /* make sure count is <= avail */ if (count > avail) @@ -358,6 +362,8 @@ static ssize_t sof_dfsentry_trace_read(struct file *file, char __user *buffer, */ snd_dma_buffer_sync(&sdev->dmatb, SNDRV_DMA_SYNC_CPU); /* copy available trace data to debugfs */ + dev_dbg(sdev->dev, "trace: copy to user from offset : %#llx, count: %#zx\n", + lpos, count); rem = copy_to_user(buffer, ((u8 *)(dfse->buf) + lpos), count); if (rem) return -EFAULT; From 83f74b0891b37acbc7c2c1bb1fbbf946efa1339f Mon Sep 17 00:00:00 2001 From: Peter Ujfalusi Date: Fri, 18 Mar 2022 20:54:04 +0200 Subject: [PATCH 6/6] ASoC: SOF: trace: DEBUG: track trace file open/release To see of the sof-logger is opening the file in the first place... Signed-off-by: Peter Ujfalusi --- sound/soc/sof/trace.c | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c index b0e98bec9539ea..52434f3b84f698 100644 --- a/sound/soc/sof/trace.c +++ b/sound/soc/sof/trace.c @@ -374,11 +374,22 @@ static ssize_t sof_dfsentry_trace_read(struct file *file, char __user *buffer, return count; } +static int sof_dfsentry_trace_open(struct inode *inode, struct file *file) +{ + struct snd_sof_dfsentry *dfse = inode->i_private; + struct snd_sof_dev *sdev = dfse->sdev; + + dev_dbg(sdev->dev, "trace: %s: ENTER\n", __func__); + + return simple_open(inode, file); +} + static int sof_dfsentry_trace_release(struct inode *inode, struct file *file) { struct snd_sof_dfsentry *dfse = inode->i_private; struct snd_sof_dev *sdev = dfse->sdev; + dev_dbg(sdev->dev, "trace: %s: ENTER\n", __func__); /* avoid duplicate traces at next open */ if (sdev->dtrace_state != SOF_DTRACE_ENABLED) sof_trace_set_host_offset(sdev, 0); @@ -387,7 +398,7 @@ static int sof_dfsentry_trace_release(struct inode *inode, struct file *file) } static const struct file_operations sof_dfs_trace_fops = { - .open = simple_open, + .open = sof_dfsentry_trace_open, .read = sof_dfsentry_trace_read, .llseek = default_llseek, .release = sof_dfsentry_trace_release,