[Stress test] HDA-DMA preload timeout causes IPC timeout when running multiple pipelines

This is more like a regression. We met this issue before, but fixed on glk branch.

How to reproduce:

run test scripts under tools/test/qa/tests/stability_test/:
./multiplex_pipeline-test.sh pcm0p pcm1p
or use audiofuntest tool, test script as below:

#!/bin/bash

int=0
while [ $int -lt 100000 ]
do
        echo "Test $int"
        audiofuntest -P "aplay -D hw:0,0 -r 48000 -f s16 -t raw -c 2 -B 0 -" -R "arecord -D hw:0,99 -r 48000 -f s16 -t raw -c 4 -B 0 -" -r 48000 -T 5 -a 0 -m "0,1" -c 4 -g 100
        if [ $? != 0 ]; then
                echo "test failed at $int."
                exit 1
        fi
        sleep 0.2
        echo $int
        let int++
done

error message：
aplay: pcm_write:2051: write error: Input/output error

dmesg:

[  303.909613] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 99 dir 1 cmd 0
[  303.909678] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000
[  304.212216] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60050000 size 0xc
[  304.212267] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  304.212439] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  304.212444] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  304.212477]  DMIC01: ASoC: trigger FE failed -110
[  304.212527] sof-audio-pci 0000:00:0e.0: pcm: free stream 99 dir 1
[  304.516128] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 0xc
[  304.516158] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  304.516328] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  304.516334] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  304.517561] sof-audio-pci 0000:00:0e.0: pcm: close stream 99 dir 1
[  305.131853] sof-audio-pci 0000:00:0e.0: pcm: trigger stream 0 dir 0 cmd 0
[  305.435650] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60050000 size 0xc
[  305.435681] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  305.435850] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  305.435856] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  305.435889]  Speakers: ASoC: trigger FE failed -110
[  305.435941] sof-audio-pci 0000:00:0e.0: pcm: free stream 0 dir 0
[  305.739373] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x60030000 size 0xc
[  305.739401] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  305.739591] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  305.739594] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  305.751792] sof-audio-pci 0000:00:0e.0: pcm: close stream 0 dir 0
[  308.058380] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x40010000 size 0x4c
[  308.058431] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  308.058606] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  308.058632] sof-audio-pci 0000:00:0e.0: error: ctx_save ipc error during suspend -110
[  308.058692] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010303 successful
[  308.059772] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x303 successful
[  308.059791] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 0 : core_mask 3
[  308.059827] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000010 at  00000044

Trace:
No obverses trace error, trace log is attached.

Test recipe:
sof-master: 82d29e0
kernel: topic/cros-sof-v4.14-rebase-b61733c

dmesg.log
logger-t.log

This issue can also be reproduced on UP2 with PCM512x.
No dmesg error trace, but there're some error trace logs.

sof-logger:

test@cd-apl-up2-pcm512x-02:~$ sudo sof-logger -l /etc/sof/sof-apl.ldc
 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1          DMA         109193447.343750 109193448.000000 intel/cavs/hda-dma.c:346    hda-dmac: 5 preload timeout
    0      1         HOST         109193453.802083         6.458333     src/audio/host.c:726    host_copy_int() error: dma_set_config() or dma_start() failed, ret = 4294967234
    0      1          IPC         109193459.791667         5.989583 src/audio/pipeline.c:623    pipeline_copy() error: ret = -62, dev->comp.id = 16, dir = 1
    0      1         PIPE 3.17    109193466.145833         6.354167 src/audio/pipeline.c:739    pipeline_xrun_recover()
    0      1         COMP         109193478.281250        12.135417 rc/audio/component.c:192    comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE         109193483.802083         5.520833 src/audio/pipeline.c:350    pipeline_prepare() error: ret = -22,dev->comp.id = 12
    0      1         PIPE 3.17    109193489.687500         5.885417 src/audio/pipeline.c:746    pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 3.17    109193495.000000         5.312500 src/audio/pipeline.c:821    pipeline_task(): xrun recover failed! pipeline will be stopped!
    0      1          DAI 3.16    109195775.416667      2280.416748      src/audio/dai.c:114    dai_buffer_process() error: Insufficient bytes for next period. comp_underrun()

step:

./multiplex_pipeline-test.sh pcm0p pcm2p

Test env:
sof master: 82d29e0
kernel sof-dev: ee19d24
tplg: sof-apl-pcm512x.tplg

@slawblauciak

I think this commit 3dbd1fb reintroduced this, please check. @slawblauciak may have more info on this.

@RanderWang

@RanderWang here the BF bit not set error we met:

0 1 DMA 109193447.343750 109193448.000000 intel/cavs/hda-dma.c:346 hda-dmac: 5 preload timeout

Can we please make sure this test is run by the QA team on a regular basis? Between broken scripts and regressions something is not quite right here.

@plbossart

@plbossart
We will add this test to our daily test basis and @stevyan is working on the broken scripts under tools/test/qa/tests/.

@keqiaozhang

@keqiaozhang there have been a few recent component and pipeline updates. Can you re-check.

@lgirdwood

@lgirdwood
This issue still can be reproduced with latest code base. Error trace logs are same.

    0      1          DMA          41334491.614583       224.479172 intel/cavs/hda-dma.c:344    hda-dmac: 5 preload timeout
    0      1         HOST          41334497.812500         6.197917     src/audio/host.c:766    host_copy() error: dma_set_config() or dma_start() failed, ret = 4294967234
    0      1         PIPE          41334503.593750         5.781250 src/audio/pipeline.c:658    pipeline_copy() error: ret = -62, start->comp.id = 5, dir = 1
    0      1         PIPE 1.6      41334510.208333         6.614583 src/audio/pipeline.c:766    pipeline_xrun_recover()
    0      2         PIPE 1.6      41334514.843750         4.635417 src/audio/pipeline.c:345    pipeline_prepare()
    0      2         HOST          41334518.697917         3.854167     src/audio/host.c:617    host_prepare()
    0      1         COMP          41334522.395833         3.697917 rc/audio/component.c:192    comp_set_state() error: wrong state = 5, COMP_TRIGGER_PREPARE
    0      1         PIPE          41334528.177083         5.781250 src/audio/pipeline.c:352    pipeline_prepare() error: ret = -22,dev->comp.id = 1
    0      1         PIPE 1.6      41334533.906250         5.729167 src/audio/pipeline.c:773    pipeline_xrun_recover() error: pipeline_prepare() failed, ret = -22
    0      1         PIPE 1.6      41334538.958333         5.052083 src/audio/pipeline.c:842    pipeline_task(): xrun recover failed! pipeline will be stopped!

Test recipe:
sof master: 2dbe69
kernel cros-sof-v4.14-rebase: b178744d

@keqiaozhang

@keqiaozhang would it be possible to try this with linux PR#695?

@dabekjakub

@dabekjakub looks like a HDA DMA timeout is being cascaded into other timeouts.

@slawblauciak

@slawblauciak looks like @RanderWang is also working on this within kernel too. thesofproject/linux#705. Can you guys align as this may need kernel and FW fix. Thanks

@ranj063

@ranj063
There're some conflicts when applying PR#695 to cros-sof-v4.14-rebase.
So I applied this PR to sof-dev branch and tested this issue on GLK chromebook with UbuntuOS.
This PR can reduce the probability of this issue but can't not be completely fixed. Before the probability is about 15%, now is reduce to 1%.

@keqiaozhang

@keqiaozhang thanks for checking

fixed by ASoC:sof:hda: fix hda preload issue thesofproject/linux#705

Navigation Menu

[Stress test] HDA-DMA preload timeout causes IPC timeout when running multiple pipelines #1050

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[Stress test] HDA-DMA preload timeout causes IPC timeout when running multiple pipelines #1050

Description

Activity

Jiangxinx commented on Feb 26, 2019

wwittbrx commented on Feb 26, 2019

keyonjie commented on Feb 26, 2019

plbossart commented on Feb 26, 2019

keqiaozhang commented on Feb 27, 2019

lgirdwood commented on Mar 11, 2019

keqiaozhang commented on Mar 12, 2019

ranj063 commented on Mar 12, 2019

lgirdwood commented on Mar 12, 2019

lgirdwood commented on Mar 12, 2019

keqiaozhang commented on Mar 12, 2019

ranj063 commented on Mar 12, 2019

RanderWang commented on Mar 20, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions