ASoC: SOF: trace: Make sure we are not missing the first host_offset … #3523

ujfalusi · 2022-03-16T13:12:50Z

…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.

Signed-off-by: Peter Ujfalusi peter.ujfalusi@linux.intel.com

ujfalusi · 2022-03-16T13:14:53Z

@marc-hb, this should fix the check-sof-logger.sh issue tracked under thesofproject/sof#4333

I did managed to reproduce after all on one of my machine.

dbaluta · 2022-03-16T17:32:12Z

@ujfalusi is this related to #3448 ?

ujfalusi · 2022-03-16T17:54:01Z

@ujfalusi is this related to #3448 ?

@dbaluta, hrm, yes it looks that way. On iMX you don't use the host trigger. We can not set the state to ENABLED twice, we might want to add a new state, like STARTING and accept the position update while the dtrace is STARTING || ENABLED.

I think that would cover the non host dtrace architectures also.

What do you think?

dbaluta · 2022-03-16T17:56:04Z

What do you think?

Yes, I think this would work. Can you / do you have time to implement this? I can test it somewhere at the end of the week.

…#4333 Peter has a tentative fix in thesofproject/linux#3523, remove the workaround so it can better tested and evaluated. Signed-off-by: Marc Herbert <marc.herbert@intel.com> (cherry picked from commit 4b3f847)

ujfalusi · 2022-03-16T17:59:49Z

@dbaluta, I'll do this first thing in the morning (tomorrow's), I hope it will fix both issue.
CI is acting up, I can not see the test results for this PR.

marc-hb · 2022-03-16T18:16:45Z

We should first remove the workaround in sof-test and then resubmit this to CI, sof-test change submitted in

check-sof-logger: disable again dma_nudge() workaround for stuck DMA #4333 sof-test#880

CI is completely broken this week so maybe next week.

XiaoyunWu6666 · 2022-03-17T01:06:05Z

SOFCI TEST

ujfalusi · 2022-03-17T07:27:16Z

@dbaluta, can you take a look and test this version? It should fix iMX as well (and AMD, Intel atom, Mediatek).

dbaluta · 2022-03-17T10:31:32Z

@ujfalusi let me have a look at this today.

dbaluta · 2022-03-17T15:35:02Z

@ujfalusi this looks good to me. cannot test it on i.mx as we are still on 5.15 and there were a lot of changes in that area. even with 5.16 it looks like i cannot test it.

will do a test when our porting team will upgrade to 5.17.

marc-hb · 2022-03-17T23:34:42Z

https://sof-ci.01.org/linuxpr/PR3523/build7375/devicetest/ (run ID 11146) has a number of (hopefully unrelated) failures but the "DMA nudge" was never triggered in any check-sof-logger test.

ujfalusi · 2022-03-18T05:31:04Z

SOFCI TEST

ujfalusi · 2022-03-18T10:23:53Z

Changes since v2:

handle the other possible - but unlikely - race in sof_wait_trace_avail(), the trace data can be valid when we are in INITIALIZING state
- add helper to simplify the check when the position update is expected/valid: trace_pos_update_expected()

ujfalusi · 2022-03-18T11:38:40Z

We have one case where the dtrace data is empty:
https://sof-ci.01.org/linuxpr/PR3523/build7386/devicetest/?model=BYT_MB_NOCODEC&testcase=check-sof-logger

We have one position update, it is coming way longer after the trace is enabled. It is just empty.

I have added debugs to this PR, I want to see the host_offset updates: #3526

ujfalusi · 2022-03-18T13:05:48Z

With the binaries from #3526 on jf-byt-mb-nocodec-1:

dmesg | grep "trace\:"
[  326.614413] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[  326.614516] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[  327.115456] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xffc
[  331.208375] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xffc
[  333.205053] sof-audio-acpi-intel-byt 80860F28:00: trace: nothing to copy
...
[  418.612224] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[  418.612291] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[  419.113055] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xffc
[  423.183175] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xffc
[  425.180424] sof-audio-acpi-intel-byt 80860F28:00: trace: nothing to copy

[  431.327745] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[  431.327813] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[  431.828554] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xffc

When the dtrace returns empty (last group - after about 30 iteration) the kernel receives the position update but the copy to user does not happen.
I don't know why, there is no hint.

ujfalusi · 2022-03-18T13:51:57Z

@marc-hb, one thing stands out on the jf-byt-mb-nocodec-1: it never goes to runtime pm suspend. I'm not able to reproduce the issue ever since, but it is odd.

ujfalusi · 2022-03-18T14:10:50Z

@marc-hb, managed to catch it with the new print in #3526 (to print when the sof_dfsentry_trace_read() is entered:

[ 1324.554607] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[ 1324.554710] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[ 1325.055467] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xffc
[ 1329.132220] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[ 1329.132240] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xffc
[ 1329.140847] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 4092)
[ 1331.129464] sof-audio-acpi-intel-byt 80860F28:00: trace: nothing to copy
...
[ 1413.306707] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[ 1413.306794] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[ 1413.807551] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xffc
[ 1417.898211] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[ 1417.898227] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xffc
[ 1417.906805] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 4092)
[ 1419.894534] sof-audio-acpi-intel-byt 80860F28:00: trace: nothing to copy

[ 1426.241505] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[ 1426.241580] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[ 1426.742391] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xffc

The reason for the empty dtrace from sof-logger? The read never got placed.

Manually running the sof-logger at this point and we get out the trace:

[ 1715.768315] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[ 1715.768331] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xffc
[ 1715.776976] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 4092)

ujfalusi · 2022-03-21T11:36:37Z

@ujfalusi this looks good to me. cannot test it on i.mx as we are still on 5.15 and there were a lot of changes in that area. even with 5.16 it looks like i cannot test it.

will do a test when our porting team will upgrade to 5.17.

You can 'simulate' the change with pre enum sof_dtrace_state by moving the sdev->dtrace_is_enabled = true; before the sof_ipc_tx_message() in snd_sof_init_trace_ipc().

ujfalusi · 2022-04-05T08:56:44Z

Changes since v3:

Rebased on sof-dev (ipc3-dtrace introduction)

ujfalusi · 2022-05-04T07:03:08Z

Changes since v4:

rebased on topic/sof-dev

plbossart · 2022-05-09T16:17:42Z

sound/soc/sof/ipc3-dtrace.c

@@ -419,13 +428,16 @@ static int ipc3_dtrace_enable(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;


I don't fully get the proposal and what happens if the IPC fails. we would still allow the client to read stuff from the buffer?

@plbossart, I see. I will set the state to SOF_DTRACE_DISABLED if either the ipc or the host operation fails.

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 <peter.ujfalusi@linux.intel.com>

ujfalusi · 2022-05-10T12:08:04Z

Changes since v4:

rebased on sof=dev
Set SOF_DTRACE_DISABLED in case of error when enabling the dtrace.

plbossart · 2022-05-17T21:45:44Z

any other reviews? @dbaluta @ranj063 @bardliao @marc-hb ?

ujfalusi requested review from juimonen, lyakh and kv2019i as code owners March 16, 2022 13:12

ujfalusi requested review from ranj063, plbossart, lgirdwood and marc-hb March 16, 2022 13:13

ujfalusi mentioned this pull request Mar 16, 2022

[BUG]Empty or stuck DMA trace - Initial FW ABI banner message not found in logger.data.txt thesofproject/sof#4333

Closed

marc-hb requested review from dbaluta and ktrzcinx March 16, 2022 15:32

dbaluta previously approved these changes Mar 16, 2022

View reviewed changes

marc-hb mentioned this pull request Mar 16, 2022

check-sof-logger: disable again dma_nudge() workaround for stuck DMA #4333 thesofproject/sof-test#880

Draft

ranj063 previously approved these changes Mar 17, 2022

View reviewed changes

ujfalusi dismissed stale reviews from ranj063 and dbaluta via eb80144 March 17, 2022 07:25

ujfalusi force-pushed the peter/sof/pr/dtrace_first_update_race_01 branch from b3af96e to eb80144 Compare March 17, 2022 07:25

ujfalusi requested a review from keyonjie as a code owner March 17, 2022 07:25

dbaluta previously approved these changes Mar 17, 2022

View reviewed changes

ujfalusi dismissed dbaluta’s stale review via f96008a March 18, 2022 10:21

ujfalusi force-pushed the peter/sof/pr/dtrace_first_update_race_01 branch from eb80144 to f96008a Compare March 18, 2022 10:21

ujfalusi force-pushed the peter/sof/pr/dtrace_first_update_race_01 branch from f96008a to c1f95e0 Compare April 5, 2022 08:08

ujfalusi requested review from bardliao, ajitkupandey, kuanhsuncheng and yaochunhung as code owners April 5, 2022 08:08

ujfalusi force-pushed the peter/sof/pr/dtrace_first_update_race_01 branch from c1f95e0 to 2fc5773 Compare April 5, 2022 08:33

ujfalusi force-pushed the peter/sof/pr/dtrace_first_update_race_01 branch from 2fc5773 to 9d50941 Compare May 4, 2022 07:02

plbossart reviewed May 9, 2022

View reviewed changes

ujfalusi mentioned this pull request May 10, 2022

ASoC: SOF: trace: sdev->host_offset management changes #3516

Merged

ujfalusi force-pushed the peter/sof/pr/dtrace_first_update_race_01 branch from 9d50941 to 7af8fff Compare May 10, 2022 12:06

plbossart approved these changes May 10, 2022

View reviewed changes

bardliao approved these changes May 19, 2022

View reviewed changes

plbossart merged commit 82828fb into thesofproject:topic/sof-dev May 19, 2022

ujfalusi deleted the peter/sof/pr/dtrace_first_update_race_01 branch November 18, 2022 07:37

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ASoC: SOF: trace: Make sure we are not missing the first host_offset … #3523

ASoC: SOF: trace: Make sure we are not missing the first host_offset … #3523

ujfalusi commented Mar 16, 2022

ujfalusi commented Mar 16, 2022 •

edited

Loading

dbaluta commented Mar 16, 2022

ujfalusi commented Mar 16, 2022

dbaluta commented Mar 16, 2022

ujfalusi commented Mar 16, 2022

marc-hb commented Mar 16, 2022

XiaoyunWu6666 commented Mar 17, 2022

ujfalusi commented Mar 17, 2022

dbaluta commented Mar 17, 2022

dbaluta commented Mar 17, 2022

marc-hb commented Mar 17, 2022 •

edited

Loading

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022 •

edited

Loading

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022 •

edited

Loading

ujfalusi commented Mar 21, 2022

ujfalusi commented Apr 5, 2022

ujfalusi commented May 4, 2022

plbossart May 9, 2022

ujfalusi May 10, 2022

ujfalusi commented May 10, 2022

plbossart commented May 17, 2022

ASoC: SOF: trace: Make sure we are not missing the first host_offset … #3523

ASoC: SOF: trace: Make sure we are not missing the first host_offset … #3523

Conversation

ujfalusi commented Mar 16, 2022

ujfalusi commented Mar 16, 2022 • edited Loading

dbaluta commented Mar 16, 2022

ujfalusi commented Mar 16, 2022

dbaluta commented Mar 16, 2022

ujfalusi commented Mar 16, 2022

marc-hb commented Mar 16, 2022

XiaoyunWu6666 commented Mar 17, 2022

ujfalusi commented Mar 17, 2022

dbaluta commented Mar 17, 2022

dbaluta commented Mar 17, 2022

marc-hb commented Mar 17, 2022 • edited Loading

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022 • edited Loading

ujfalusi commented Mar 18, 2022

ujfalusi commented Mar 18, 2022 • edited Loading

ujfalusi commented Mar 21, 2022

ujfalusi commented Apr 5, 2022

ujfalusi commented May 4, 2022

plbossart May 9, 2022

Choose a reason for hiding this comment

ujfalusi May 10, 2022

Choose a reason for hiding this comment

ujfalusi commented May 10, 2022

plbossart commented May 17, 2022

ujfalusi commented Mar 16, 2022 •

edited

Loading

marc-hb commented Mar 17, 2022 •

edited

Loading

ujfalusi commented Mar 18, 2022 •

edited

Loading

ujfalusi commented Mar 18, 2022 •

edited

Loading