[BUG] 07_06_TestKdMemLeak DSP PANIC and Keyword detection notification timeout

[wszypelt]

Describe the bug
Bug was found in:
07_06_TestKdMemLeakStaticPipelines

the content of the error:
Keyword detection notification timeout
DSP panic

Topology

                pipe_plb
               +------------------+
        +----+ | +---+  +-------+ |
        |Host|-->|Buf|->|SSP Dai|----------------------------------+
        +----+ | +---+  +-------+ |                                |
               +----------------- +                                |
                                                                   |
                   +-------------------------+                     |
        +--------+ | +---+   +-----+   +---+ |                     |
        |KD Dummy|<->|Buf|<->|ChSel|<->|Buf|<->+                   |
        +--------+ | +---+   +-----+   +---+ | |  pipe_cap         |
                   +-------------------------+ |                   |
                                               |                   |
                             +-----------------+                   |
        +--------------------|-----------------------------------+ |
        |+----+  +------+  +---+  +---+  +---+  +---+  +-------+ | |
        ||Host|<-|Buffer|<-|Kpb|<-|Buf|<-|Vol|<-|Buf|<-|SSP Dai|---+
        |+----+  +------+  +---+  +---+  +---+  +---+  +-------+ |
        +--------------------------------------------------------+

Description:
Test keyword detection feature with full topology and memory leak verification, using SSP loopback.

To Reproduce
Run tests with diagnostic driver
07_06_TestKdMemLeakStaticPipelines

Reproduction Rate
100%

Environment

1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
   • SOF BRANCH: main HASH: b06f2cf
2. Name of the platform(s) on which the bug is observed.
   • Platform: ICL RVP, WHL RVP, TGL RVP, APL RVP
3. Test environment:
   BRANCH: master HASH: 19a82964d354d5d600d430b1d3dbf3c4f834418d

Screenshots or console output

[     1337332.500000] (          95.708336) c0 memory                      src/lib/alloc.c:597  INFO heap: buffer status
[     1337376.750000] (          44.250000) c0 dma-trace                 src/trace/trace.c:138  INFO Suppressed 6 similar messages:  heap: 0x%x size %d blocks %d caps 0x%x
[     1337381.541667] (           4.791667) c0 memory                      src/lib/alloc.c:599  INFO heap: runtime status
[     1337390.833333] (           9.291667) c0 dma-trace                 src/trace/trace.c:138  INFO Suppressed 6 similar messages:   used %d free %d
[     1337395.500000] (           4.666667) c0 memory                      src/lib/alloc.c:567  INFO  heap: 0xbe1b0000 size 524288 blocks 7 caps 0x45
[     1337404.583333] (           9.083333) c0 memory                      src/lib/alloc.c:569  INFO   used 1664 free 522624
[     1337474.875000] (          70.291664) c0 memory                      src/lib/alloc.c:602  INFO heap: runtime shared status
[     1337483.666667] (           8.791667) c0 memory                      src/lib/alloc.c:567  INFO  heap: 0x9e09e000 size 917504 blocks 5 caps 0x45
[     1337492.541667] (           8.875000) c0 memory                      src/lib/alloc.c:569  INFO   used 7872 free 909632
[     1337545.500000] (          52.958332) c0 memory                      src/lib/alloc.c:604  INFO heap: system shared status
[     1337554.708333] (           9.208333) c0 memory                      src/lib/alloc.c:567  INFO  heap: 0x9e17e000 size 5376 blocks 0 caps 0x45
[     1337564.000000] (           9.291667) c0 memory                      src/lib/alloc.c:569  INFO   used 3904 free 1472
[     1337577.166667] (          13.166667) c0 dma-trace                 src/trace/trace.c:138  INFO Suppressed 22 similar messages:   block %d base 0x%x size %d
[     1337581.958333] (           4.791667) c0 memory                      src/lib/alloc.c:955  ERROR failed to alloc 0x41900 bytes zone 0x3 caps 0x8 flags 0x0
[     1337593.708333] (          11.750000) c0 memory                      src/lib/alloc.c:955  ERROR failed to alloc 0x41800 bytes zone 0x3 caps 0x8 flags 0x0
[     1337604.083333] (          10.375000) c0 dma-trace                 src/trace/trace.c:138  INFO Suppressed 22 similar messages:    count %d free %d
[     1337610.458333] (           6.375000) c0 memory                      src/lib/alloc.c:955  ERROR failed to alloc 0x41700 bytes zone 0x3 caps 0x8 flags 0x0
[     1337622.750000] (          12.291667) c0 memory                      src/lib/alloc.c:955  ERROR failed to alloc 0x41600 bytes zone 0x3 caps 0x8 flags 0x0
[     1338119.875000] (         497.125000) c0 sa                          src/lib/agent.c:56   INFO perf sys_load peak plat 24241 cpu 399148
[     1339120.333333] (        1000.458313) c0 sa                          src/lib/agent.c:56   INFO perf sys_load peak plat 24241 cpu 400320
[     1344027.333333] (        4907.000000) c0 kpb                         src/audio/kpb.c:299  INFO kpb new memory block: 65024
[     1344281.708333] (         254.375000) c0 dma-trace                 src/trace/trace.c:138  INFO Suppressed 791 similar messages: failed to alloc 0x%x bytes zone 0x%x caps 0x%x flags 0x%x
[     1344288.875000] (           7.166667) c0 sa                          src/lib/agent.c:56   INFO perf sys_load peak plat 27934 cpu 465684
[     1344297.625000] (           8.750000) c0 sa                          src/lib/agent.c:83   WARN validate(), ll drift detected, delta = 27933
[     1344319.125000] (          21.500000) c0 kpb                         src/audio/kpb.c:299  INFO kpb new memory block: 203776
[     1344328.041667] (           8.916667) c0 kpb                         src/audio/kpb.c:348  INFO kpb_allocate_history_buffer(): allocated 268800 bytes
[     1344336.875000] (           8.833333) c0 kpb                         src/audio/kpb.c:1529 INFO kpb_reset_history_buffer()
[     1344346.000000] (           9.125000) c0 kpb                         src/audio/kpb.c:1444 INFO kpb_clear_history_buffer()
[     1344818.291667] (         472.291656) c0 dai          1.3            src/audio/dai.c:620  INFO dai_prepare()
[     1344828.333333] (          10.041667) c0 dai          1.3            src/audio/dai.c:587  INFO dai_config_prepare(), channel = 0
[     1344837.666667] (           9.333333) c0 dw-dma                 src/drivers/dw/dma.c:192  INFO dw_dma_channel_get(): dma 0 request channel 0
[     1344847.500000] (           9.833333) c0 dai          1.3            src/audio/dai.c:606  INFO dai_config_prepare(): new configured dma channel index 0
[     1346533.583333] (        1686.083374) c0 ipc                  src/ipc/ipc3/handler.c:1579 INFO ipc: new cmd 0x60010000
[     1346548.083333] (          14.500000) c0 pipe         2.12  ....../pipeline-params.c:222  INFO pipe params dir 1 frame_fmt 1 buffer_fmt 0 rate 16000
[     1346557.208333] (           9.125000) c0 pipe         2.12  ....../pipeline-params.c:226  INFO pipe params stream_tag 0 channels 1 sample_valid_bytes 3 sample_container_bytes 4
[     1346582.416667] (          25.208334) c0 selector     2.8   ..../selector/selector.c:221  INFO selector_params()
[     1346602.875000] (          20.458334) c0 kpb          1.1            src/audio/kpb.c:454  ERROR kpb_params(): kpb has been already configured.
[     1346612.708333] (           9.833333) c0 pipe         2.12  ....../pipeline-params.c:308  INFO pipe prepare
[     1346630.708333] (          18.000000) c0 kd-test      2.9   ..../audio/detect_test.c:671  INFO test_keyword_prepare()
[     1346659.833333] (          29.125000) c0 selector     2.8   ..../selector/selector.c:429  INFO selector_prepare()

LAST WORKING MASTER: 0eda430

Logs

07_06_MemoryLeak.zip

[lgirdwood]

@kfrydryx any update ? This wont be a blocker for v2.1-rc1 since Keyword is not enabled for Linux.

[keqiaozhang]

I can reproduce this issue on my TGL UP Xtreme i11 board with sof-hda-generic-4ch-kwd.tplg.

This issue only happens with loopback mode. In other words, it happens when running sof playback and kwd capture at same time.
If I use a USB sound card as input to trigger KWD, this error will not happen.

I did the bisection and found that this is a regression and caused by c04b7fc13eb64ff70795ac16dab6dee37f50bb63

commit c04b7fc13eb64ff70795ac16dab6dee37f50bb63
Author: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>
Date:   Wed Feb 16 11:10:14 2022 +0100

    pipeline: fix aborting STOP or PAUSE propagation

    When trigger.aborted is set, pipeline_trigger_run() also returns
    PPL_STATUS_PATH_STOP. So the current test for trigger.aborted in
    pipeline_task_cmd() after pipeline_trigger_run() is a left-over from
    an earlier implementation and is never entered with the current flow.
    In the current implementation, a typical playback topology like
    [pipeline A] PCM -> ... - [pipeline B] mixer -> ... -> DAI
    when a pause is triggered mixer will stop its propagation, set
    trigger.aborted on pipeline B to true and return
    PPL_STATUS_PATH_STOP. pipeline_task_cmd() is still running in the
    context of pipeline A, so it will detect PPL_STATUS_PATH_STOP, check
    that trigger.aborted is not set and terminate the task. Then the
    scheduler will run the task for pipeline B, that one will verify,
    that trigger.host == NULL, then find the trigger.aborted to be true
    and will keep the task running.

    In a topology, where the PCM, the mixer and the DAI all belong to the
    same pipeline, when PAUSE is triggered, the whole pipeline should be
    left running which is what this patch achieves by checkint
    trigger.aborted when PPL_STATUS_PATH_STOP is returned by
    pipeline_trigger_run().

    BugLink: https://github.com/thesofproject/sof/issues/5257
    Signed-off-by: Guennadi Liakhovetski <guennadi.liakhovetski@linux.intel.com>

 src/audio/pipeline/pipeline-schedule.c | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)

This issue cannot be reproduced after reverting this commit on tip main branch.

[lgirdwood]

@lyakh fyi - another stop/pause issue.

[lyakh]

interesting, that it's caused by my above commit, but the log has "ERROR failed to alloc 0x41900 bytes zone 0x3 caps 0x8 flags 0x0" in it

[lyakh]

I can reproduce this issue on my TGL UP Xtreme i11 board with sof-hda-generic-4ch-kwd.tplg.

@keqiaozhang how do you reproduce it? Which test do you run? If you have a panic message - can you see where it panics?

[lgirdwood]

@keqiaozhang are you also able to get FW dump/trace/dmesg when panic() occurs ?