[BUG][APL][PCM512X]EQ-test occur ipc error for 0x60010000 size 20

[dengyangchao]

Describe the bug
EQ-test occur ipc error for 0x60010000 size 20

To Reproduce

1. Reboot system via "sudo reboot".
2. Wait 5s make runtime PM to suspend
3. cd /sof-test-fix-add_eq_test/test-case
4. Run "export TPLG=/lib/firmware/intel/sof-tplg/sof-apl-pcm512x.tplg"
5. Execute command "./check-audio-equalizer.sh"

Reproduction Rate
3/3

Expected behavior
EQ-test pass

Impact
IPC error for 0x60010000 size 20

Environment
Platform: APL UP2 with PCM512X in I2S mode
Firmware: 53d35e4 https://github.com/thesofproject/sof/commits/master
Kernel: b2d9823 https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-apl-eq-pcm512x.tplg rename to sof-apl-pcm512x.tplg

Dmesg

[   54.395166] sof-audio-pci 0000:00:0e.0: rate_min: 48000 rate_max: 48000
[   54.395168] sof-audio-pci 0000:00:0e.0: channels_min: 2 channels_max: 2
[   54.395174] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 0 dir 0
[   54.395178] sof-audio-pci 0000:00:0e.0: generating page table for 00000000630fbb49 size 0xffc0 pages 16
[   54.395187] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x40000 successful
[   54.395202] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x40000 successful
[   54.395205] sof-audio-pci 0000:00:0e.0: period_bytes:0x3fc0
[   54.395207] sof-audio-pci 0000:00:0e.0: periods:4
[   54.395216] sof-audio-pci 0000:00:0e.0: stream_tag 1
[   54.395223] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   54.395622] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60010000 size 20
[   54.395631] sof-audio-pci 0000:00:0e.0: error: hw params ipc failed for stream 1
[   54.395635] sof-audio-pci 0000:00:0e.0: ASoC: 0000:00:0e.0 hw params failed: -22
[   54.395642]  Port5: ASoC: hw_params FE failed -22
[   54.397407] sof-audio-pci 0000:00:0e.0: pcm: free stream 0 dir 0
[   54.400129] sof-audio-pci 0000:00:0e.0: pcm: close stream 0 dir 0
[   54.437766] sof-audio-pci 0000:00:0e.0: ipc tx: 0x50030000: GLB_COMP_MSG: SET_DATA
[   54.437893] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x50030000: GLB_COMP_MSG: SET_DATA
[   54.453726] pcm512x i2c-104C5122:00: No SCLK, using BCLK: -2
[   54.454537] sof-audio-pci 0000:00:0e.0: pcm: open stream 0 dir 0
[   54.454541] sof-audio-pci 0000:00:0e.0: period min 192 max 16384 bytes
[   54.454543] sof-audio-pci 0000:00:0e.0: period count 2 max 16
[   54.454544] sof-audio-pci 0000:00:0e.0: buffer max 65536 bytes
[   54.454882] sof-audio-pci 0000:00:0e.0: rate_min: 48000 rate_max: 48000
[   54.454885] sof-audio-pci 0000:00:0e.0: channels_min: 2 channels_max: 2
[   54.454888] sof-audio-pci 0000:00:0e.0: rate_min: 48000 rate_max: 48000
[   54.454890] sof-audio-pci 0000:00:0e.0: channels_min: 2 channels_max: 2
[   54.454897] sof-audio-pci 0000:00:0e.0: rate_min: 48000 rate_max: 48000
[   54.454898] sof-audio-pci 0000:00:0e.0: channels_min: 2 channels_max: 2
[   54.454903] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 0 dir 0

Sof-error-trace

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1         COMP 1.2      54390101.145833  54390100.000000 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54390105.156250         4.010417 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54390108.697917         3.541667    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP 1.2      54449815.729167     59707.031250 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54449819.687500         3.958333 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54449823.177083         3.489583    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP          54485567.239583     35744.062500 udio/eq_iir/eq_iir.c:413 	eq_iir_init_coef(), ch 0 is set to bypass
    0      1         COMP          54485570.781250         3.541667 udio/eq_iir/eq_iir.c:413 	eq_iir_init_coef(), ch 1 is set to bypass
    0      1         COMP 1.2      54485574.583333         3.802083 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54485578.072917         3.489583 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54485581.614583         3.541667    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP 1.2      54518611.666667     33030.050781 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54518615.729167         4.062500 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54518619.218750         3.489583    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP 1.2      54556008.906250     37389.687500 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54556012.864583         3.958333 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54556016.406250         3.541667    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP 1.2      54600105.937500     44089.531250 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54600110.000000         4.062500 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54600113.645833         3.645833    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP 1.2      54639018.281250     38904.636719 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54639022.395833         4.114583 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54639025.885417         3.489583    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP 1.2      54675128.593750     36102.707031 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54675132.500000         3.906250 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54675135.937500         3.437500    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22
    0      1         COMP 1.2      54708594.375000     33458.437500 udio/eq_iir/eq_iir.c:859 	eq_iir_prepare(), No proc func
    0      1         PIPE          54708598.229167         3.854167 src/audio/pipeline.c:499 	pipeline_prepare() error: ret = -22, dev->comp.id = 0
    0      1          IPC          54708601.822917         3.593750    src/ipc/handler.c:311 	ipc: pipe 1 comp 0 prepare failed -22

amixer.txt
dmesg.log
logger.log
sof-error-trace.log

add test scripts here:
sof-test-fix-add_eq_test.zip

[dengyangchao]

Caused by master de73e60 , @bkokoszx please help to check

[lgirdwood]

Looks like a dupe of #2379 and some others on the same bisect commit

[bkokoszx]

@dengyangchao
Can you check whether PR #2414 fixes this issue?

[dengyangchao]

@bkokoszx Tried #2414 and still failed

[   65.718750] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000010 at  00000044
[   65.718757] sof-audio-pci 0000:00:0e.0: Turning i915 HDAC power 0
[   65.718803] sof-audio-pci 0000:00:0e.0: New DSP state 4 substate 0
[   94.364270] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for Passthrough Playback 0
[   94.364279] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for PCM0P
[   94.364281] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for BUF1.0
[   94.364284] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for EQIIR1.0
[   94.364287] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for BUF1.1
[   94.364289] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for EQFIR1.0
[   94.364292] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for BUF1.2
[   94.364294] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for PGA1.0
[   94.364296] sof_pcm512x sof_pcm512x: ASoC: can't get playback BE for BUF1.3
[   94.376232] sof-audio-pci 0000:00:0e.0: Turning i915 HDAC power 1
[   94.381184] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000000 at  00000044

dmesg.log
logger.log

[dengyangchao]

@dengyangchao
I've tried to reproduce with recipe from here: #2401 (comment)
And I did not have reproduction. Here are my logs:
dmesg.txt
logger.txt

Maybe are there any updates in sof-test-fix-add_eq_test.zip test scripts?

@bkokoszx I got the scripts from here, thesofproject/sof-test#63.
if you use the sof-test-fix-add_eq_test.zip, before setp 4 you need run "export TPLG=/lib/firmware/intel/sof-tplg/sof-apl-pcm512x.tplg"(I've updated the reproduce steps).
BTW, the tplg is sof-apl-eq-pcm512x.tplg rename to sof-apl-pcm512x.tplg

[bkokoszx]

@dengyangchao
I've checked with new recipe and test passed (please look at: test_log.txt file):
logger.txt
test_log.txt
dmesg.txt

Firmware: #2414
Kernel: https://github.com/thesofproject/linux/tree/861c30871ef1b7f328839de9559f4ff58998234e
Test scripts from zip you have attached.

Can you try to reproduce it once more?