[BUG] FW status on IPC timeout in test 07_05_TestKdDmicD0ix16000Hz16b16b2ch

[kkarask]

Describe the bug
Tests 07_05_TestKdDmicD0ix16000Hz16b16b2ch and 07_05_TestKdDmicD0ix16000Hz24b32b2ch failed wit error:
ERROR failed to alloc 0x2ea00 bytes zone 0x3 caps 0x8 flags 0x0

To Reproduce
Run test 07_05_TestKdDmicD0ix16000Hz16b16b2ch or 07_05_TestKdDmicD0ix16000Hz24b32b2ch with Diagnostic driver

Reproduction Rate
100%

Environment

1. Firmware branch name and commit.
   • SOF: Branch: main, Hash: b0cb159
2. Name of the platform(s) on which the bug is observed.
   • Platform: TGL RVP

Screenshots or console output

[      996808.255208] (          10.286458) c0 dma-trace                 src/trace/trace.c:135  Suppressed 19 similar messages:   block %d base 0x%x size %d
[      996812.994792] (           4.739583) c0 memory                      src/lib/alloc.c:958  ERROR failed to alloc 0x2ed00 bytes zone 0x3 caps 0x8 flags 0x0
[      996821.848958] (           8.854167) c0 dma-trace                 src/trace/trace.c:135  Suppressed 19 similar messages:    count %d free %d
[      996828.411458] (           6.562500) c0 memory                      src/lib/alloc.c:958  ERROR failed to alloc 0x2ec00 bytes zone 0x3 caps 0x8 flags 0x0
[      996839.270833] (          10.859375) c0 memory                      src/lib/alloc.c:958  ERROR failed to alloc 0x2eb00 bytes zone 0x3 caps 0x8 flags 0x0
[      996848.750000] (           9.479167) c0 memory                      src/lib/alloc.c:958  ERROR failed to alloc 0x2ea00 bytes zone 0x3 caps 0x8 flags 0x0
[      999899.140625] (        3050.390625) c0 dma-trace                 src/trace/trace.c:135  Suppressed 494 similar messages: failed to alloc 0x%x bytes zone 0x%x caps 0x%x flags 0x%x
[      999909.427083] (          10.286458) c0 sa                          src/lib/agent.c:79   WARN validate(), ll drift detected, delta = 47614
Skipped 56724 bytes after the last statement.

Logs:
TGL_07_05_TestKdDmicD0ix16000Hz16b16b2ch.zip
TGL_07_05_TestKdDmicD0ix16000Hz24b32b2ch.zip

[lgirdwood]

@kkarask can you bisect. There has not been any memory updates this week, but a few weeks back there was some updates merged. @keyonjie fyi.

[kkarask]

Bisect done.
Last working commit: 5b4ea83
First bad commit: bec163c

[keyonjie]

I believe this error message actually doesn't impact the KD functionality?
This is for the KPB history buffer allocation, when fails we will retry with smaller size and the request is from LPSRAM where we have 64KB only on TGL. So I think we actually should always see this but the allocation eventually succeed so no impact in functionality. @mrajwa FYI.

[keyonjie]

BTW @marc-hb the filter feature is very annoying here that it kills useful logs for us:
"Suppressed 19 similar messages: block %d base 0x%x size %d"

[marc-hb]

We can discuss turning TRACE_FILTERING_ADAPTIVE off by default as long as that change is:

• not buried / hidden in the middle of something unrelated like trace: fixes to help for heap allocation debugging #4548
• not confused with TRACE_FILTERING_VERBOSITY as in trace: fixes to help for heap allocation debugging #4548
• well tested and not triggering a regression like [BUG] DMA trigger stop failed when suspend-resume during capturing on CML-SKU0983-SDW #4779
• not overrunning the ring buffer and thrashing (causing more logs in a positive feedback loop)
• the PR is not mislabeled "Minor Fixes" as non-minor Minor fixes #4860 and others

Even before discussing it, anyone can submit a draft PR that turns it off just to get test results and more verbose logs.

[bkokoszx]

Hi @keyonjie
I misled you during bugscrub - it looks like we have another problem here (some timeout). @kkarask is checking that. We will make an update later.

[kkarask]

@keyonjie There is timeout on IPC:

Exception TimeoutError occurred at 'C:\work\KK\cavs_scripts-py\utilities\ipc_driver.py':603
FW status on IPC timeout after 5.0 seconds:
0x00000005 0x00000000 0x00004000

Sending PmGate (40080000, 00000000)
Payload:
00000020 40080000 0000000E 00000000 

when test passed with working commit there is a response from that IPC:

Sending PmGate (40080000, 00000000)
Payload:
00000020 40080000 0000000E 00000000 
00000000 00000000 00000000 00000000 

Response ReplyMsg (10000000, 0000000C)
Payload:
0000000C 10000000 00000000  received!

The error: ERROR failed to alloc 0x2ec00 bytes zone 0x3 caps 0x8 flags 0x0 was not the real reason test failed, so I change the title

[marc-hb]

The error: ERROR failed to alloc 0x2ec00 bytes zone 0x3 caps 0x8 flags 0x0 was not the real reason test failed, so I change the title

Just to be sure: the bisect result is still the same?

[kkarask]

@marc-hb yes, bisect result is still the same with reproduction rate 100%.

[lgirdwood]

@keyonjie any update ?

[keyonjie]

Looks we are quite lack of KWD coverage in our CI now, check-keyword-detection.sh event can't run on any of our 29 daily models, @keqiaozhang @aiChaoSONG @mengdonglin FYI.
Without that, we don't have this PM_GATE IPC validation at all, need to re-enable that and debug what happens here, with the latest main.