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

[XiaoyunWu6666]

@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

[lgirdwood]

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

[marc-hb]

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

[marc-hb]

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.

[marc-hb]

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