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

@marc-hb

@marc-hb EDIT: after making testing more deterministic in thesofproject/sof-test#710, now reproduced 100% on BDW and BYT, see any recent test results like for instance this one: https://sof-ci.01.org/softestpr/PR720/build763/devicetest/?model=BYT_MB_NOCODEC&testcase=check-sof-logger

Describe the bug
inner daily 4532 ; model=TGLU_RVP_HDA (and many others, see below); testcase=check-sof-logger

To Reproduce
TPLG=sof-hda-generic-4ch-kwd.tplg ~/sof-test/test-case/check-sof-logger.sh

Reproduction Rate
100%

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: 57440285
SOF Branch: main
SOF Commit: 73df644
Topology:sof-hda-generic-4ch-kwd.tplg
Platform: TGLU_RVP_HDA

Screenshots or console output

2021-06-10 21:24:17 UTC N kill 4320 # DMA trace
2021-06-10 21:24:17 UTC [REMOTE_ERROR] Initial ERROR FW ABI message not found in /home/ubuntu/sof-test/logs/check-sof-logger/2021-06-10-21:24:15-18859/logger.data.txt


2021-06-10 21:24:17 UTC N Log data BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT	ktime=102.780s  @  2021-06-10 21:24:15 +0000 UTC
2021-06-10 21:24:17 UTC N ::END data


2021-06-10 21:24:17 UTC N Log etrace BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT	ktime=104.787s  @  2021-06-10 21:24:17 +0000 UTC
[     9558057.954] (           0.000) c0 dma-trace             src/trace/dma-trace.c:343  ERROR FW ABI 0x3012001 DBG ABI 0x5003000 tag v1.8-rc1-184-g73df64444b75 src hash 0xb1c22c73 (ldc hash 0xb1c22c73)
Skipped 8144 bytes after the last statement.
2021-06-10 21:24:17 UTC N ::END etrace


2021-06-10 21:24:17 UTC N Log error BEG::
2021-06-10 21:24:17 UTC N ::END error


2021-06-10 21:24:17 UTC N Log etrace_stderr BEG::
2021-06-10 21:24:17 UTC N ::END etrace_stderr
2021-06-10 21:24:17 UTC [REMOTE_ERROR] Initial ERROR FW ABI message not found in /home/ubuntu/sof-test/logs/check-sof-logger/2021-06-10-21:24:15-18859/logger.data.txt

https://thesofproject.github.io/latest/developer_guides/firmware/drivers/dma/intel/hda-dma.html

@XiaoyunWu6666

@XiaoyunWu6666 I assume you are using latest logger (built using same commit ID as FW) ?
@marc-hb assigning, but please re-assign if it turns out not to be a logger update issue.

I just rewrote that test in thesofproject/sof-test#666, before that it was not checking anything. So it is not obvious whether the lack of DMA trace is a recent regression (for instance caused by recent #4327), or it has always been a problem and we never noticed (green failure...)

I logged into the storage server to explore the generic_test results and I found that the DMA trace on TGLU_RVP_HDA has been empty 20% of the time; 50 times out of 250 runs. So this is NOT a recent regression and there is no reason to revert the #4327 fixes.

There is a reason why thesofproject/sof-test#666 was called "rewrite check-sof-logger so it can actually find (existing) bugs". Don't shoot the messenger.

The DMA trace on TGLU_RVP_HDA has more specifically been empty in these test runs:

wc -l */TGLU_RVP_HDA/check-sof-logger/logger.data.log | sed -e 's#/# #g' | awk '$1 == 1 { print $2 }' | sort -u -n | tr '\n' ' '

706 715 717 722 723 732 762 779 788 789 800 802 812 817 829 853 863 871 881 990 995 1022 1139 1288 1293 1305 1326 1429 1720 1897 1964 1995 2284 2290 2308 2320 2377 2491 2596 2810 3961 4081 4137 4171 4191 4276 4290 4346 4359 4398 4408

706 is the oldest TGLU_RVP_HDA failure and it's dated 2020-11-09 21:27:08 UTC

Overall 706 is the 3rd oldest record I found so I think this issue is older than these records - possibly been here since TGLU_RVP_HDA existed?

In fact DMA traces from the check-sof-logger have been randomly empty in many different TGL product (not just TGLU_RVP_HDA):

173 174 178 182 186 190 194 198 203 207 211 215 219 223 227 231 235 239 245 249 256 267 272 276 297 331 332 338 340 343 347 348 351 354 356 357 358 362 370 374 377 382 385 388 391 394 402 406 407 408 412 415 421 431 432 437 438 439 440 441 444 446 447 451 454 457 460 464 473 482 489 495 498 504 507 513 519 524 527 531 538 548 558 564 566 567 573 590 594 606 607 610 613 620 627 628 633 640 643 675 683 706 715 717 722 723 727 732 750 755 762 779 788 789 800 802 812 817 822 828 829 843 850 853 863 871 881 886 891 912 990 995 1022 1059 1082 1118 1139 1145 1288 1293 1305 1326 1351 1361 1366 1391 1397 1408 1429 1441 1456 1510 1539 1547 1568 1616 1668 1679 1720 1734 1735 1807 1828 1868 1893 1897 1926 1933 1937 1950 1964 1995 2020 2026 2050 2081 2096 2118 2131 2150 2154 2164 2171 2177 2190 2220 2256 2275 2284 2290 2302 2305 2308 2320 2357 2367 2377 2491 2596 2810 3610 3664 3685 3688 3711 3961 4081 4137 4171 4191 4276 4290 4346 4359 4398 4408

Run 173 (TGL_RVP_HDA) is dated 2020-07-23

For some unknown reason it's been rare with TGLU_RVP_SDW 5 runs out of 2628! (runs: 788 1868 1893 2256 3664) and rare with TGL_RVP_SDW too: 1 run out of 124, (run 447)

While at it I checked other platforms and the most numerous failures happened (by far) on BYT_MB_NOCODEC (but only 15% of the time)

awk '{print $3}' all_empty_DMA_traces | sort | uniq -c | sort -nr

553/3349 BYT_MB_NOCODEC
  89/116 TGL_RVP_HDA
  51/251 TGLU_RVP_HDA
   48/90 TGLU_SKU09FB_HDA
  40/173 APL_UP2_PCM512X
 33/3481 GLK_BOB_DA7219
   29/61 TGL_SHURI_HDA
 25/3396 BDW_WSB_RT286
   16/31 TGLU_SHUR_HDA
  16/106 BYT_MB_RT5682
 16/2177 BSW_CYN_MAX98090
  8/2287 TGLH_RVP_HDA
  5/2628 TGLU_RVP_SDW
    5/12 ADLP_RVP_SDW
  4/2910 CML_HEL_RT5682
  3/3452 APL_UP2_NOCODEC
  3/3323 APL_UP2_HDA
    2/42 TGL_RVP_NOCODEC
  2/2338 ICL_RVP_HDA
  2/2782 CML_SKU0955_HDA
  2/2813 CML_RVP_SDW
   1/124 TGL_RVP_SDW

We noticed this issue on BYT (and others) a long time ago, see "byt: trace out of sync" email thread and this is why I made this "DMA nudge" test change to hide it: thesofproject/sof-test#663

However this "DMA nudge" applies only to generic log collection at the end of every "normal" test, it does not take effect for check-sof-logger that is specifically invoking sof-logger.

@lgirdwood

While working on some Zephyr issues I discovered that ipc_send_queued_msg() is run like this:

enum task_state task_main_primary_core(void *data)
{
	/* main audio processing loop */
	while (1) {
		/* sleep until next IPC or DMA */
		wait_for_interrupt(0);

		if (!ipc->pm_prepare_D3)
			ipc_send_queued_msg();

	}
}

This seems strange to me: could this cause some IPCs to be delayed for a very long time? I'm not considering Zephyr in this bug. See #4356

Cc: @lgirdwood , @lyakh , @kv2019i , @keyonjie , @plbossart

@marc-hb

@marc-hb the LL scheduler on SOF will tick so this is not an issue, however we run Zephyr in tickless mode so all IPC work should be done in IPC threads.

IPC command from host - we wake our IPC command thread and do the command from host. This is preemptable.
IPC notifications to host - we wake our IPC notification thread and sent the message to host. This is preemptable.

e.g something like the below would work for 1 & 2. @lyakh may already have some example code.

while (1) {
    if (ipc_is pending())
        do_ipc()
    else
        sleep();
}

@marc-hb

@marc-hb, on my machine the bootup is pretty silent

Switch everything to the shared memory etrace using CONFIG_TRACEM and you will see that's incomplete.

And yes, the trace can be incomplete,

OK :-)

I see now, the nudge is local to check-sof-logger.sh.

It's used in other tests but in other tests it makes no PASS/FAIL difference.

All it does is to force the DSP to boot up (because the trace will wake up the DSP if you send a filter update, we have discussed this already).

The test is currently waiting for the DSP to go to sleep. We can remove that to make it simpler, it should be a one-line change. What do you think?

The DMA trace got stuck on 2 platforms and it the nudge was enough to make the test pass only on one:

Similar results in daily run 11164: empty on 3 systems ADLP_GMB_I2S_ZEPHYR, ICL_RVP_HDA and ADLP_RVP_NOCODEC, test "rescued" by the nudge except on ADLP_GMB_I2S_ZEPHYR

Start Time: 2022-03-17 21:28:49 UTC

It would be interesting to have thesofproject/linux#3523 merged and observe the daily results for couple of days.

@marc-hb

@marc-hb, it looks like we have two types of missing dtrace data:

the host_offset update comes too early and it is ignored by the kernel

will be fixed by ASoC: SOF: trace: Make sure we are not missing the first host_offset … linux#3523

No read is issued from user space to debugfs/sof/trace file for some unknown reason:

[ 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

check-sof-logger.sh reports failure for the last iteration (banner not found in logger.data.txt), but if we run it (sof-logger directly) again manually we get the data out just fine:

[ 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)

Binaries from thesofproject/linux#3526 can be used with identical prints if there is an interest.

@marc-hb

@marc-hb, pushed one more commit to thesofproject/linux#3526 to track the trace file open and release as well.
fwiw, on my machine it looks like this:

# dmesg | grep "trace\: "
[  518.703117] sof-audio-pci-intel-tgl 0000:00:1f.3: snd_sof_init_trace: dma_trace_pages: 16
[  518.703215] sof-audio-pci-intel-tgl 0000:00:1f.3: snd_sof_enable_trace: stream_tag: 1
[  518.704245] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: new host_offset: 0x80
[  523.594868] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: sof_dfsentry_trace_open: ENTER
[  523.595031] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[  523.595038] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: copy to user from offset : 0x0, count: 0x80
[  523.595112] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 128)
[  523.595115] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: nothing to copy
[  523.595172] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: sof_dfsentry_trace_open: ENTER
[  523.595178] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: sof_dfsentry_trace_release: ENTER
[  523.595180] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: new host_offset: 0x0
[  523.595188] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[  525.594176] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: nothing to copy
[  525.594285] sof-audio-pci-intel-tgl 0000:00:1f.3: trace: sof_dfsentry_trace_release: ENTER

@marc-hb

@marc-hb, I have managed to reproduce the issue (on jf-byt-mb-nocodec-1) with the kernel from thesofproject/linux#3526 :

2022-03-23 07:29:59 UTC Sub-Test: [INFO] Waiting a few seconds for the DSP to fully boot and then suspend
2022-03-23 07:30:03 UTC Sub-Test: [INFO] Trying to get the DMA trace log with background sof-logger ...
2022-03-23 07:30:03 UTC Sub-Test: [COMMAND] sudo /usr/local/bin/sof-logger  -t -f 3 -l  /etc/sof/sof-byt.ldc  -o  /home/ubuntu/sof-test/logs/check-sof-logger/2022-03-23-07:29:54-4132/logger.data.txt  2>  /home/ubuntu/sof-test/logs/check-sof-logger/2022-03-23-07:29:54-4132/logger.error.txt  &
2022-03-23 07:30:11 UTC Sub-Test: [INFO] Trying to get the etrace mailbox ...
2022-03-23 07:30:11 UTC Sub-Test: [COMMAND] sudo /usr/local/bin/sof-logger    -f 3 -l  /etc/sof/sof-byt.ldc  2>  /home/ubuntu/sof-test/logs/check-sof-logger/2022-03-23-07:29:54-4132/logger.etrace_stderr.txt  -o  /home/ubuntu/sof-test/logs/check-sof-logger/2022-03-23-07:29:54-4132/logger.etrace.txt

2022-03-23 07:30:11 UTC Sub-Test: [ERROR] Log header not found in /home/ubuntu/sof-test/logs/check-sof-logger/2022-03-23-07:29:54-4132/logger.data.txt

2022-03-23 07:30:11 UTC Sub-Test: [INFO] Log file logger.data.txt BEG::
2022-03-23 07:30:11 UTC Sub-Test: [INFO] ::END log file logger.data.txt


2022-03-23 07:30:11 UTC Sub-Test: [INFO] Log file logger.etrace.txt BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT       ktime=300.868s  @  2022-03-23 07:30:11 +0000 UTC
[   288253210.160] (           0.000) c0 dma-trace             src/trace/dma-trace.c:422  INFO SHM: FW ABI 0x3014000 DBG ABI 0x5003000 tag v2.0 src hash 0x927ffc8c (ldc hash 0x927ffc8c)
Skipped 848 bytes after the last statement.
2022-03-23 07:30:11 UTC Sub-Test: [INFO] ::END log file logger.etrace.txt


2022-03-23 07:30:11 UTC Sub-Test: [INFO] Log file logger.error.txt BEG::
GOOD: logger.error.txt was empty, no stderr output from that sof-logger instance
2022-03-23 07:30:11 UTC Sub-Test: [INFO] ::END log file logger.error.txt


2022-03-23 07:30:11 UTC Sub-Test: [INFO] Log file logger.etrace_stderr.txt BEG::
GOOD: logger.etrace_stderr.txt was empty, no stderr output from that sof-logger instance
2022-03-23 07:30:11 UTC Sub-Test: [INFO] ::END log file logger.etrace_stderr.txt

2022-03-23 07:30:11 UTC Sub-Test: [ERROR] Log header not found in /home/ubuntu/sof-test/logs/check-sof-logger/2022-03-23-07:29:54-4132/logger.data.txt
2022-03-23 07:30:11 UTC Sub-Test: [ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-03-23 07:30:11 UTC Sub-Test: [ERROR]  print_logs_exit()  @  /home/ubuntu/sof-test/test-case/check-sof-logger.sh
2022-03-23 07:30:11 UTC Sub-Test: [ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-sof-logger.sh:201
2022-03-23 07:30:11 UTC Sub-Test: [ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-sof-logger.sh:231
2022-03-23 07:30:12 UTC Sub-Test: [INFO] Test Result: FAIL!

The dmesg have this to say about the runs:

# successful run
[  186.496554] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[  186.496693] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[  186.997608] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xff4
[  191.072270] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_open: ENTER
[  191.072813] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[  191.072826] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xff4
[  191.081454] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 4084)
[  193.070735] sof-audio-acpi-intel-byt 80860F28:00: trace: nothing to copy
[  193.071211] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_release: ENTER
...
# successful runs
...
# successful run
[  265.152479] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[  265.152539] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[  265.653319] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xff4
[  277.608813] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_open: ENTER
[  277.609471] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[  277.609484] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xff4
[  277.619388] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 4084)
[  279.607347] sof-audio-acpi-intel-byt 80860F28:00: trace: nothing to copy
[  279.607573] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_release: ENTER
...
# The last, failed run:
[  288.075033] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_init_trace: dma_trace_pages: 16
[  288.075144] sof-audio-acpi-intel-byt 80860F28:00: snd_sof_enable_trace: stream_tag: 0
[  288.576010] sof-audio-acpi-intel-byt 80860F28:00: trace: new host_offset: 0xff4

# running sof-logger manually
[  896.931802] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_open: ENTER
[  896.932272] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 0)
[  896.932289] sof-audio-acpi-intel-byt 80860F28:00: trace: copy to user from offset : 0x0, count: 0xff4
[  896.941216] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_read: ENTER (count: 4096, lpos: 4084)
[  900.897926] sof-audio-acpi-intel-byt 80860F28:00: trace: nothing to copy
[  900.898275] sof-audio-acpi-intel-byt 80860F28:00: trace: sof_dfsentry_trace_release: ENTER

The reason for the Log header not found in logger.data.txt failure is that sof-logger does not even open the trace file.

@ujfalusi

In Intel daily test run 12177 I see a clear IPC failure in setting up the logger (ADLP_GMB_I2S_ZEPHYR):

[ 89.504320] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x90030000: GLB_TRACE_MSG: DMA_PARAMS_EXT
[ 90.007325] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x90030000 (msg/reply size: 80/12)
[ 90.007363] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context

This seems quite different from the cases @ujfalusi you've last seen on BYT... right?

@kv2019i

@kv2019i, I think it is the same issue as #5733, it is under investigation

check-sof-logger.sh: do not wait for D3 suspend

Close as this issue cannot be reproduced in recent daily testing.

It can be reproduced, there's a workaround to ignore the error.

Navigation Menu

Repository navigation

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

48 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

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

Description

Activity

lgirdwood commented on Jun 11, 2021

marc-hb commented on Jun 11, 2021

marc-hb commented on Jun 12, 2021

marc-hb commented on Jun 15, 2021

lgirdwood commented on Jun 16, 2021

48 remaining items

marc-hb commented on Mar 18, 2022

marc-hb commented on Mar 18, 2022

ujfalusi commented on Mar 18, 2022

ujfalusi commented on Mar 18, 2022

ujfalusi commented on Mar 18, 2022

ujfalusi commented on Mar 23, 2022

kv2019i commented on Apr 29, 2022

ujfalusi commented on Apr 29, 2022

mengdonglin commented on Sep 6, 2022

marc-hb commented on Sep 6, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions