[BUG] FW replied with error. Error code: -12

[kkarask]

Describe the bug
During test 19_00_TestAsrcPlayback8000Hz32b32b2ch error code was found.
FW replied with error. Error code: -12 0x00000005 0x00000000 0x00004000

Topology

 +---------------------------------+
    +------+    | +---+  +----+  +---+  +-------+ |
    | Host |----->|Buf|->|Asrc|->|Buf|->|SSP Dai|---+
    +------+    | +---+  +----+  +---+  +-------+ | |
                +---------------------------------+ |
                                                    |
                +------------------+                |
    +------+    | +---+  +-------+ |                |
    | Host |<-----|Buf|<-|SSP Dai|<-----------------+
    +------+    | +---+  +-------+ |
                +------------------+

To Reproduce
Run test 19_00_TestAsrcPlayback8000Hz32b32b2ch with Diagnostic driver.

Reproduction Rate
100% on APL RVP

Environment

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

Screenshots or console output

[     2814093.072917] (        6672.916504) c0 ipc                  src/ipc/ipc3/handler.c:536  ipc: dai 1.0 -> config 
[     2814099.270833] (           6.197917) c0 dai                           src/lib/dai.c:164  dai_get type 1 index 0 new sref 3
[     2814104.791667] (           5.520833) c0 ssp-dai      1.0   /drivers/intel/ssp/ssp.c:279  ssp_set_config(), config->format = 0x4304
[     2814112.968750] (           8.177083) c0 ssp-dai      1.0   /drivers/intel/ssp/ssp.c:706  ssp_set_config(), sscr0 = 0xc1d0003f, sscr1 = 0xd0400004, ssto = 0x00000000, sspsp = 0x2010005
[     2814117.968750] (           5.000000) c0 ssp-dai      1.0   /drivers/intel/ssp/ssp.c:708  ssp_set_config(), sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000, ssioc = 0x00000020
[     2814122.656250] (           4.687500) c0 ssp-dai      1.0   /drivers/intel/ssp/ssp.c:710  ssp_set_config(), ssrsa = 0x00000003, sstsa = 0x00000003
[     2814128.072917] (           5.416667) c0 dai                           src/lib/dai.c:188  dai_put type 1 index 0 new sref 2
[     2814133.177083] (           5.104167) c0 ipc                      src/ipc/ipc3/dai.c:159  ipc_comp_dai_config() dai type = 1 index = 0
[     2814138.333333] (           5.156250) c0 dai          1.2         src/ipc/ipc3/dai.c:223  dai_config() dai type = 1 index = 0 dd 0xbe04d080
[     2814148.697917] (          10.364583) c0 dai          2.7         src/ipc/ipc3/dai.c:223  dai_config() dai type = 1 index = 0 dd 0xbe04d480
[     2876223.645833] (       62074.949219) c0 pipe         1.5   ....../pipeline-params.c:215  pipe params dir 0 frame_fmt 2 buffer_fmt 0 rate 8000
[     2876228.906250] (           5.260417) c0 pipe         1.5   ....../pipeline-params.c:219  pipe params stream_tag 1 channels 2 sample_valid_bytes 4 sample_container_bytes 4
[     2876262.343750] (          33.437500) c0 asrc         1.0      src/audio/asrc/asrc.c:382  asrc_params()
[     2876268.281250] (           5.937500) c0 asrc         1.0      src/audio/asrc/asrc.c:419  asrc_params(), source_rate=8000, sink_rate=8000, source_frames_max=18, sink_frames_max=18
[     2876274.062500] (           5.781250) c0 dai          1.2         src/ipc/ipc3/dai.c:84   dai_data_config() dai type = 1 index = 0 dd 0xbe04d080
[     2876291.302083] (          17.239584) c0 dai          1.2            src/audio/dai.c:346  dai_playback_params() dest_dev = 2 stream_id = 0 src_width = 4 dest_width = 4
[     2876296.510417] (           5.208333) c0 dai          1.2            src/audio/dai.c:352  dai_playback_params() fifo 0x8010
[     2876305.312500] (           8.802083) c0 pipe         1.5   ....../pipeline-params.c:297  pipe prepare
[     2876319.791667] (          14.479167) c0 asrc         1.0      src/audio/asrc/asrc.c:570  asrc_prepare()
[     2876332.864583] (          13.072917) c0 asrc         1.0      src/audio/asrc/asrc.c:671  ERROR asrc_prepare(), allocation fail for size 2684
[     2876342.083333] (           9.218750) c0 pipe         1.5   ....../pipeline-params.c:304  ERROR pipeline_prepare(): ret = -12, dev->comp.id = 1
[     2876346.979167] (           4.895833) c0 ipc                  src/ipc/ipc3/handler.c:280  ERROR ipc: pipe 1 comp 1 prepare failed -12
[     2876351.614583] (           4.635417) c0 pipe         1.5   ......./pipeline-graph.c:341  pipe reset
[     2876380.468750] (          28.854166) c0 asrc         1.0      src/audio/asrc/asrc.c:889  asrc_reset()
[     2876385.364583] (           4.895833) c0 asrc         1.0      src/audio/asrc/asrc.c:891  asrc_reset(), skew_min=0, skew_max=0
[     2876390.885417] (           5.520833) c0 asrc         1.0      src/audio/component.c:63   comp_set_state(), state already set to 1
[     2876398.281250] (           7.395833) c0 dai          1.2            src/audio/dai.c:687  dai_reset()
[     2876417.135417] (          18.854166) c0 dai          1.2      src/audio/component.c:63   comp_set_state(), state already set to 1

APL_19_00.zip

[lgirdwood]

Looks like we are OOM here. @keyonjie fyi, probably a good idea to dump heap (from alloc.c) when we fail to alloc memory.
@kkarask I'm assuming this was the only topology loaded ? Did other ASRC tests work on this platform ?

[lgirdwood]

@kkarask oh, I see there is a fix. Can you try this test again with #4521 locally merged.

[keyonjie]

hi @lgirdwood @kkarask we are quite difficult to allocate big runtime blocks on APL, here looks the request of 2684 Bytes failed for asrc, I am adding more useful logs to print out the heap blocks usage when needed: #4548

[juimonen]

just curious, is this the only format/samplerate that fails, or are there others?

[kkarask]

@lgirdwood unfortunately PR #4521 doesn't fix this issue. Results are exactly the same with #4521 and without it.

@juimonen all tests with sample rate 24/32 and 32/32 failed.

Results:

[keyonjie]

@lgirdwood @kakulesza we need to get #4548 merged first to capture more valuable logs for this issue.

[wszypelt]

unsupported platform
on TGL issue does not occur
Tested FW hash: 4943aaa