Skip to content

[Stress] IPC timed out after ~1000 times of aplay on APL with PCM512x. #784

Closed
Closed
[Stress] IPC timed out after ~1000 times of aplay on APL with PCM512x.#784
Assignees
wwittbrx
Labels
APLApplies to Apollolake platformP1Blocker bugs or important featuresbugSomething isn't working as expected

Description

@markyang
markyang
opened on Dec 28, 2018

Summary:
IPC timed out after 967 times aplay on APL with PCM512x.
sof-logger is empty. sof-logger -t log is attached below.
dmesg:

[ 3296.899229] sof-audio sof-audio: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 3296.899430] sof-audio sof-audio: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 3296.913495] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 1
[ 3296.913523] sof-audio sof-audio: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 3296.913808] sof-audio sof-audio: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 3298.633775] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 0
[ 3298.633810] sof-audio sof-audio: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 3298.937260] sof-audio sof-audio: error: ipc timed out for 0x60050000 size 0xc
[ 3298.937273] sof-audio sof-audio: status: fw entered - code 00000005
[ 3298.937418] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 3298.937423] sof-audio sof-audio: error: waking up any trace sleepers
[ 3298.937449]  Port5: ASoC: trigger FE failed -110
[ 3298.937502] sof-audio sof-audio: pcm: free stream 0 dir 0
[ 3299.241262] sof-audio sof-audio: error: ipc timed out for 0x60030000 size 0xc
[ 3299.241275] sof-audio sof-audio: status: fw entered - code 00000005
[ 3299.241421] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 3299.241426] sof-audio sof-audio: error: waking up any trace sleepers
[ 3299.256441] sof-audio sof-audio: pcm: close stream 0 dir 0

Test steps:

1. aplay-10000.sh

Test env:
sof master: a2e6f82
kernel sof-dev: 62aa569
tplg: sof-apl-pcm512x.tplg

Log:
logger-t.txt
aplay_error_967.log
aplay-10000.sh.txt

Activity

  1. markyang
    added
    bugSomething isn't working as expected
    APLApplies to Apollolake platform
    on Dec 28, 2018

  2. keyonjie commented on Dec 28, 2018

    @keyonjie
    keyonjie
    on Dec 28, 2018
    Contributor

    good reporting, thanks, @markyang

  3. mengdonglin
    added
    P1Blocker bugs or important features
    on Jan 2, 2019
  4. mengdonglin
    changed the title [-][Stress test]: IPC timed out after 967 times aplay on APL with PCM512x.[/-] [+][Stress]: IPC timed out after 967 times aplay on APL with PCM512x.[/+] on Jan 2, 2019
  5. mengdonglin
    changed the title [-][Stress]: IPC timed out after 967 times aplay on APL with PCM512x.[/-] [+][Stress] IPC timed out after 967 times aplay on APL with PCM512x.[/+] on Jan 2, 2019
  6. mengdonglin
    changed the title [-][Stress] IPC timed out after 967 times aplay on APL with PCM512x.[/-] [+][Stress] IPC timed out after ~1000 times of aplay on APL with PCM512x.[/+] on Jan 14, 2019
  7. lgirdwood
    assigned
    dabekjakub
    on Jan 23, 2019

  8. lgirdwood commented on Jan 23, 2019

    @lgirdwood
    lgirdwood
    on Jan 23, 2019
    Member

    @markyang I wonder if this is IPC related (since the FW has not crashed afaict). Do you have a similar stress test that can be run on same HW that changes a volume control value 10000 times.

  9. dabekjakub
    assigned
    wwittbrx
    and unassigned
    dabekjakub
    on Jan 24, 2019

  10. dabekjakub commented on Jan 24, 2019

    @dabekjakub
    dabekjakub
    on Jan 24, 2019
    Member

    @markyang can it be reproduced on Yorp ?

    @wwittbrx please try to reproduce it in our test enviroment

  11. lgirdwood commented on Jan 24, 2019

    @lgirdwood
    lgirdwood
    on Jan 24, 2019
    Member

    @dabekjakub I have a feeling these similar IPC timeout issues we are seeing today are related to scheduling. i.e. the IPC reply is scheduled but not run since we don't see any exception.

  12. dabekjakub commented on Jan 24, 2019

    @dabekjakub
    dabekjakub
    on Jan 24, 2019
    Member

    @lgirdwood You are probably right and we are waiting for @bkokoszx to finish scheduler changes

  13. markyang commented on Jan 25, 2019

    @markyang
    markyang
    on Jan 25, 2019
    Author

    @lgirdwood yes, I got a similar IPC timeout after changing a volume control value about 1000 times.

    Test steps:

    1. aplay -Dhw:0,0 -c2 -fS16_LE -vv -i music.wav # Terminal 1
2. ./vol-change-10000.sh 21 0 1000  # Terminal 2

    Test env:
    sof master: 724d267
    kernel sof-dev: 359bf51
    tplg: sof-apl-pcm512x.tplg

    Scripts
    vol-change-10000.sh.txt

  14. markyang commented on Jan 25, 2019

    @markyang
    markyang
    on Jan 25, 2019
    Author

    @dabekjakub sorry, I have no Yorp.

  15. markyang commented on Jan 28, 2019

    @markyang
    markyang
    on Jan 28, 2019
    Author

    Summary:
    w/ playback stream, volume change passed 10000 iterations

    Test steps:

    1. aplay -Dhw:0,0 -c2 -fS16_LE -vv -i music.wav # Terminal 1
    2. ./vol-change-10000.sh # Terminal 2

    Test env:
    sof master: 1f5a965
    kernel sof-dev: 7b67e0b
    tplg: sof-apl-pcm512x.tplg

  16. markyang commented on Jan 28, 2019

    @markyang
    markyang
    on Jan 28, 2019
    Author

    Summary:
    After volume change passed 10000 iterations, this issue can also be reproduced after 64 iterations on APL with PCM512x

    Test steps:

    1. ./aplay-loop.sh 
======== aplay: 64 times ========

    Test env:
    sof master: 1f5a965
    kernel sof-dev: 7b67e0b
    tplg: sof-apl-pcm512x.tplg

    Log:
    aplay-loop.sh.txt

  17. wenqingfu commented on Jan 29, 2019

    @wenqingfu
    wenqingfu
    on Jan 29, 2019

    @markyang , can you please help to test with non-SMP configuration as @keqiaozhang did at issue 780. I feel they are very likely to be the same. Thank you in advance for the testing!

  18. markyang commented on Jan 29, 2019

    @markyang
    markyang
    on Jan 29, 2019
    Author

    @wenqingfu w/ playback stream on APL with PCM512x, volume change passed 10000 iterations with the latest non-SMP firmware built by ./scripts/xtensa-build-all.sh -l -u -j apl.

    Test steps:

    1. aplay -Dhw:0,0 -c2 -fS16_LE -vv -i /dev/zero  # in terminal 1
2. ./volume-change-loop.sh # in terminal 2, run 10000 times

    Test env:
    sof master: f9e5bba
    kernel sof-dev: 7b67e0b
    tplg: sof-apl-pcm512x.tplg

    Scripts
    volume-change-loop.sh.txt

  19. markyang commented on Jan 29, 2019

    @markyang
    markyang
    on Jan 29, 2019
    Author

    Summary:
    this issue can also be reproduced after 18 iterations on APL with PCM512x, with the latest non-SMP firmware built by ./scripts/xtensa-build-all.sh -l -u -j apl.

    dmesg:

    [ 6593.140563] sof-audio sof-audio: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 6593.444448] sof-audio sof-audio: error: ipc timed out for 0x60050000 size 0xc
[ 6593.444469] sof-audio sof-audio: status: fw entered - code 00000005
[ 6593.444618] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 6593.444626] sof-audio sof-audio: error: waking up any trace sleepers
[ 6593.444648]  Port5: ASoC: trigger FE failed -110
[ 6593.444697] sof-audio sof-audio: pcm: free stream 0 dir 0
[ 6593.748429] sof-audio sof-audio: error: ipc timed out for 0x60030000 size 0xc
[ 6593.748451] sof-audio sof-audio: status: fw entered - code 00000005
[ 6593.748599] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 6593.748606] sof-audio sof-audio: error: waking up any trace sleepers
[ 6593.763584] sof-audio sof-audio: pcm: close stream 0 dir 0
[ 6596.580410] sof-audio sof-audio: error: ipc timed out for 0x40010000 size 0x4c
[ 6596.580432] sof-audio sof-audio: status: fw entered - code 00000005
[ 6596.580581] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 6596.580595] sof-audio sof-audio: error: ctx_save ipc error during suspend -110
[ 6596.580622] sof-audio sof-audio: FW Poll Status: reg=0x1010303 successful
[ 6596.581429] sof-audio sof-audio: FW Poll Status: reg=0x303 successful
[ 6596.581441] sof-audio sof-audio: DSP core(s) enabled? 0 : core_mask 3

    Test steps:

    1. ./aplay-loop.sh
======== aplay: 18 times ========

    Test env:
    sof master: f9e5bba
    kernel sof-dev: 7b67e0b
    tplg: sof-apl-pcm512x.tplg

    Log:
    dmesg-aplay-loop-fail.txt
    logger-t.txt

  20. lgirdwood commented on Jan 29, 2019

    @lgirdwood
    lgirdwood
    on Jan 29, 2019
    Member

    this issue can also be reproduced after 18 iterations on APL with PCM512x, with the latest non-SMP firmware built by ./scripts/xtensa-build-all.sh -l -u -j apl.

    @markyang could you increase the time (in aplay-loop.sh) between playbacks and see if this impacts the result. I would suspect that increased delay would lessen the bug frequency but reducing the delay would increase the bug frequency ?

  21. markyang commented on Jan 30, 2019

    @markyang
    markyang
    on Jan 30, 2019
    Author

    Summary:
    This issue can also be reproduced on APL with PCM512x using the latest daily build.

    Test steps:

    $ sudo dmesg -C
$ ./aplay-loop.sh 1
======== aplay: 70 times ========
$ sudo dmesg -C
$ ./aplay-loop.sh 2
======== aplay: 43 times ========
$ sudo dmesg -C
$ ./aplay-loop.sh 4
======== aplay: 37 times ========
$ sudo dmesg -C
$ ./aplay-loop.sh 8
======== aplay: 5 times ========

    vi aplay-loop.sh:

    #!/bin/bash

function error_check(){
    local sof_error=$(dmesg | grep sof-audio | grep -E "error|failed|timed out|panic|oops")
    if [ ! -z "$sof_error" ]; then
        dmesg > dmesg-aplay-loop-fail.txt
        return 1
    fi
    return 0
}

function aplay_loop(){
    local sleep_sec=${1:-1}
    local times=${2:-10000}
    local i=0
    while [ $i -lt $times ]; do
        i=$((i + 1))
        printf "aplay: %d \r" $i
        aplay -Dhw:0,0 -c 2 -r 48000 -f s16_le -d 1 ~/Music/WAV_PCM_48000Hz_stereo_16bit.wav 2> /dev/null
        [ $sleep_sec -gt 0 ] && sleep $sleep_sec
        error_check
        [ $? -ne 0 ] && break
    done
    printf "======== aplay: %d times ========\n" $i
}

aplay_loop $@

    Test env:
    sof master: 365b132
    kernel sof-dev: 7b67e0b
    tplg: sof-apl-pcm512x.tplg

  22. lgirdwood commented on Jan 30, 2019

    @lgirdwood
    lgirdwood
    on Jan 30, 2019
    Member

    @markyang ok, just to confirm failure increases with delay between aplay ? I would expected the opposite.

  23. markyang commented on Jan 31, 2019

    @markyang
    markyang
    on Jan 31, 2019
    Author

    @lgirdwood According to the following test results, it seems has nothing to do with the delay between aplays, and the dmesg is a little different.

    dmesg:

    [  611.482853] sof-audio sof-audio: booting DSP firmware completed
[  611.482864] sof-audio sof-audio: ipc rx done: 0x70000000: FW_READY
[  611.482911] sof-audio sof-audio: firmware boot complete
[  611.482921] sof-audio sof-audio: Debug PCIR: 00000000 at  00000048
[  611.482927] sof-audio sof-audio: Debug PCIW: 00000002 at  00000048
[  611.482934] sof-audio sof-audio: Debug PCIR: 00000004 at  00000044
[  611.482939] sof-audio sof-audio: Debug PCIW: 00000000 at  00000044
[  611.482960] sof-audio sof-audio: period_bytes:0x0
[  611.482963] sof-audio sof-audio: periods:1
[  611.482972] sof-audio sof-audio: stream_tag: 1
[  611.482999] sof-audio sof-audio: ipc tx: 0x90010000: GLB_TRACE_MSG
[  611.483630] sof-audio sof-audio: error: ipc error for 0x90010000 size 0xc
[  611.483656] sof-audio sof-audio: error: can't set params for DMA for trace -22
[  611.483663] sof-audio sof-audio: warning: failed to init trace after resume -22
[  611.483688] sof-audio sof-audio: ipc tx: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  611.483853] sof-audio sof-audio: ipc tx succeeded: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  611.483883] sof-audio sof-audio: ipc tx: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  611.484029] sof-audio sof-audio: ipc tx succeeded: 0x30010000: GLB_TPLG_MSG: COMP_NEW

    Test steps:

    1. sudo dmesg -C
2. ./aplay-loop.sh 1
======== aplay: 50 times ========

3. rmmod & modprobe sof-audio modules
4. sudo dmesg -C
5. ./aplay-loop.sh 8
======== aplay: 38 times ========

6. rmmod & modprobe sof-audio modules
7. sudo dmesg -C
8. ./aplay-loop.sh 2
======== aplay: 47 times ========

9. rmmod & modprobe sof-audio modules
10. sudo dmesg -C
11. ./aplay-loop.sh 4
======== aplay: 15 times ========

12. rmmod & modprobe sof-audio modules
13. sudo dmesg -C
14. ./aplay-loop.sh 16
======== aplay: 10 times ========

15. sudo reboot
16. sudo dmesg -C
17. ./aplay-loop.sh 4
======== aplay: 60 times ========

  24. lgirdwood commented on Jan 31, 2019

    @lgirdwood
    lgirdwood
    on Jan 31, 2019
    Member

    @markyang @wwittbrx delays above 4 seconds will cause the driver/DSP to enter D3, so this errors > 4 seconds are probably kernel bug, but delay < 4 seconds are FW related. @wwittbrx any update at your end ?

  25. Jiangxinx commented on Mar 20, 2019

    @Jiangxinx
    Jiangxinx
    on Mar 20, 2019
    Contributor

    Passed on daily test
    Step:

    1. aplay-10000.sh

    Env:
    sof master: 6e88bdf
    kernel sof-dev: 95b2fab
    tplg: sof-apl-pcm512x.tplg

  26. lgirdwood
    closed this as completedon Mar 20, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

APLApplies to Apollolake platformP1Blocker bugs or important featuresbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions