[Stress] IPC times out during the volume change

This is a low probability issue, I only met it once and very hard to reproduce. I file it in here, hope we can find some potential risk form it.

Test scenario:

do audio playback on speaker in one terminal
change the volume(alsamixer -c 0) during the playing in another terminal.

dmesg:

[ 3396.979786] sof-audio sof-audio: ipc tx succeeded: 0x50010000
[ 3396.979821] sof-audio sof-audio: ipc tx: 0x50020000
[ 3396.979991] sof-audio sof-audio: ipc rx: 0x90020000
[ 3396.980006] sof-audio sof-audio: ipc rx done: 0x90020000
[ 3396.980044] sof-audio sof-audio: ipc tx succeeded: 0x50020000
[ 3396.980092] sof-audio sof-audio: ipc tx: 0x50010000
[ 3397.285708] sof-audio sof-audio: error: ipc timed out for 0x50010000 size 0x6c
[ 3397.285731] sof-audio sof-audio: status: fw entered - code 00000005
[ 3397.285895] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[ 3397.285902] sof-audio sof-audio: error: waking up any trace sleepers
[ 3397.285938] sof-audio sof-audio: error: failed to set control 2 values
[ 3397.589561] sof-audio sof-audio: error: ipc timed out for 0x50020000 size 0x6c
[ 3397.589583] sof-audio sof-audio: status: fw entered - code 00000005
[ 3397.589782] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000

dmesg.log
logger-t.log

Test recipe:
SOF firmware: glk-005-drop-stable/4d7904d19
Kernel driver: cros-sof-v4.14-rebase/2aa548de0

@keqiaozhang

@keqiaozhang @markyang can someone create a stress test for IPC. i.e. to send a volume change IPC command 10000 times with and without an active playback stream. This could be related to #784

@lgirdwood

@lgirdwood
I wrote a script for ipc stress test and reproduced this issue after 125 iterations. I tested volume change with an active playback/capture stream at this time. I will test it without the playback or capture stream next.
firmware branch: glk-005-drop-stable
dmesg:

[  839.402009] sof-audio sof-audio: ipc tx: 0x50020000
[  839.402294] sof-audio sof-audio: ipc tx succeeded: 0x50020000
[  839.402334] sof-audio sof-audio: ipc tx: 0x50010000
[  839.402362] sof-audio sof-audio: ipc rx: 0x90020000
[  839.402379] sof-audio sof-audio: ipc rx done: 0x90020000
[  839.402570] sof-audio sof-audio: ipc tx succeeded: 0x50010000
[  839.403353] sof-audio sof-audio: ipc tx: 0x50020000
[  839.704497] sof-audio sof-audio: error: ipc timed out for 0x50020000 size 0x6c
[  839.704528] sof-audio sof-audio: status: fw entered - code 00000005
[  839.704722] sof-audio sof-audio: error: unexpected fault 0x00000000 trace 0x00004000
[  839.704725] sof-audio sof-audio: error: waking up any trace sleepers
[  839.704738] sof-audio sof-audio: error: failed to get control 9 values

test script:

#!/bin/bash

MAXLOOP=10000

rand(){
        min=$1
        max=$(($2-$min+1))
        num=$(date +%s%N)
        echo $(($num%$max+$min))
}

err_check(){
        ERROR=$(dmesg | grep sof-audio | grep -E "error|failed|timed out|panic|oops")
        if [ ! -z "$ERROR" ]; then
                dmesg > boot_fail.log
                exit 1
        fi
}

int=0
while [ $int -lt $MAXLOOP ]
do
        echo "test $int"
        PGA_ID=$(rand 1 5)
        while [ $PGA_ID -eq 4 ]
        do
                PGA_ID=$(rand 1 5)
        done
        echo "Volume kctl ID: $PGA_ID"
        if [ $PGA_ID == 1 ] || [ $PGA_ID == 2 ] || [ $PGA_ID == 5 ]; then
                if [ $PGA_ID == 1 ]; then
                        pcmid=0
                elif [ $PGA_ID == 2 ]; then
                        pcmid=1
                else
                        pcmid=5
                fi
                aplay -Dhw:0,$pcmid -f dat -c 2 /dev/zero &
                PID=$!
                interval=$(rand 1 3)
                sleep 0.$interval
                kill $PID
                for volume in $(seq 0 32)
                do
                        amixer -c0 cset name='PGA'$PGA_ID'.0 Master Playback Volume '$PGA_ID'' $volume
                done
                sleep 0.$interval
                kill $PID
        else
                arecord -Dhw:0,1 -f dat -c 2 /dev/null &
                PID=$!
                interval=$(rand 1 3)
                sleep 0.$interval
                for volume in $(seq 0 32)
                do
                        amixer -c0 cset name='PGA'$PGA_ID'.0 Master Capture Volume '$PGA_ID'' $volume
                done
                sleep 0.$interval
                kill $PID
        fi
        sleep 0.5
        err_check
        let int++
done

dmesg.log
logger-t.log
sof-test-volume.txt

@keqiaozhang

@keqiaozhang pls upstream the script when you get time. Please provide the test results with and without the active playback stream. Can you also try this with @keyonjie scheduler PR #778 during playback.

@wwittbrx

@wwittbrx Please reproduce this in our test enviroment.

@lgirdwood

@lgirdwood
Without the active playback/capture, test failed at 5407th times.
trace:

 CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME    CONTENT
    0      1         DMIC             68615.156250     68615.156250               dmic.c:1155   dmic_set_config() error: prm driver_ipc_version = 1, prm->num_pdm_active = 16
    0      1         DMIC             68621.458333         6.302083               dmic.c:1159   dmic_set_config() error: pdmclk_min = 500000, pdmclk_max = 4800000, fifo_fs_a = 48000, fifo_fs_b = 2
    0      1         DMIC             68628.020833         6.562500               dmic.c:1163   dmic_set_config() error: prm fifo_bits_a = 3, fifo_bits_b = 0, duty_min = 3, duty_max = 0
    0      1         DMIC             68634.947917         6.927083               dmic.c:1173   dmic_set_config() error: fifo_bits_a EINVAL
    0      1          IPC             68645.833333        10.885417            handler.c:555    ipc: dai 2,0 config failed -22

dmesg:

[ 2095.808634] sof-audio sof-audio: ipc tx: 0x80010000
[ 2095.808761] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 2095.808784] sof-audio sof-audio: ipc tx: 0x80010000
[ 2095.808916] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 2095.808960] sof-audio sof-audio: ipc tx: 0x80010000
[ 2095.809147] sof-audio sof-audio: ipc tx succeeded: 0x80010000
[ 2095.809254] sof-audio sof-audio: ipc tx: 0x80010000
[ 2095.809398] sof-audio sof-audio: error: ipc error for 0x80010000 size 0xc
[ 2095.809598] sof-audio sof-audio: error: failed to set dai config for dmic01
[ 2095.809602] sof-audio sof-audio: error: failed to restore pipeline after resume -22
[ 2095.809610] sof-audio sof-audio: error: volume get failed to resume -16
[ 2095.821419] sof-audio sof-audio: error: volume get failed to resume -16
[ 2095.825173] sof-audio sof-audio: error: volume get failed to resume -16
[ 2095.836014] sof-audio sof-audio: error: volume get failed to resume -16
[ 2095.845296] sof-audio sof-audio: error: volume get failed to resume -16

dmesg.log
logger-t.log
logger.log

I will test with PR #778 tomorrow.

@keyonjie

@keyonjie @lgirdwood
Today I tested this issue with new sof branch sof-glk006-drop-stable, looks like this branch is much stable. w/o playback/capture stream, volume change passed 10000 iterations.
w/ playback/capture stream, volume change have passed 6000+ iterations, test is on going.
I will do more test to confirm it.
@markyang will help to test PR #778 first on UP2 board.

@keqiaozhang

@keqiaozhang thanks, good info. The differences between master and glk6 are

git log --left-right --graph --cherry-pick --oneline gh/master  ^gh/glk-006-drop-stable 
> 3dbd1fb5 (gh/master) pipeline: add a flag for FW xrun recovery disabling
> 724d2674 dw-dma: add start delay for timer driven capture streams
> 905bad42 scripts: xtensa-build-all: Add support to force build UP Arch
> 26a6541b GDB: Initialized from IPC handler + generalized debug addresses.
> c30f2fc2 GDB: Adjusted to new build system.
> cfdfcf56 GDB: Added packet parser.
> 9a3555e2 MEMORY: Enabled LP SRAM for ICL platform.
> d53466ad IPC: port PM D3 entry fixes to CNL, WHL & CML
>   cfaaa7ee Merge pull request #880 from plbossart/fix/kmod_scripts
|\  
| > 7f7e48e2 kmod_scripts: fix dependencies and add delays
>   0cd5fb06 Merge pull request #878 from jajanusz/update-cmocka-git
|\  
| > 97f3b70d cmake: update cmocka git
> 570ce065 Merge pull request #877 from dbaluta/master
> 7c375015 drivers: Remove unused host_msg field

Do you get the same results as master ?

@plbossart

@plbossart fyi

On 1/25/19 9:52 AM, Liam Girdwood wrote: @keqiaozhang <https://github.com/keqiaozhang> thanks, good info. The differences between master and glk6 are |git log --left-right --graph --cherry-pick --oneline gh/master ^gh/glk-006-drop-stable > 3dbd1fb (gh/master) pipeline: add a flag for FW xrun recovery disabling > 724d267 dw-dma: add start delay for timer driven capture streams > 905bad4 scripts: xtensa-build-all: Add support to force build UP Arch > 26a6541 GDB: Initialized from IPC handler + generalized debug addresses. > c30f2fc GDB: Adjusted to new build system. > cfdfcf5 GDB: Added packet parser. > 9a3555e MEMORY: Enabled LP SRAM for ICL platform. > d53466a IPC: port PM D3 entry fixes to CNL, WHL & CML > cfaaa7e Merge pull request #880 from plbossart/fix/kmod_scripts |\ | > 7f7e48e kmod_scripts: fix dependencies and add delays > 0cd5fb0 Merge pull request #878 from jajanusz/update-cmocka-git |\ | > 97f3b70 cmake: update cmocka git > 570ce06 Merge pull request #877 from dbaluta/master > 7c37501 drivers: Remove unused host_msg field | Do you get the same results as master ?

I don't quite get the diffs (redid them on my side), this telling me there are no outstanding patches on glk6 that aren't in master, and I don't quite see anything that looks related to IPC on Up2? Wondering what makes glk6 work better or if we are comparing the right things (same SMP configuration, etc)?

@plbossart

@plbossart I think the issues were reported on glk5, so I would expect glk6 to behave similar to master. Just need @keqiaozhang to confirm.

@keqiaozhang

@keqiaozhang btw, with the latest repo, you can use '-u' to force UP(non-SMP) building, such as:
./scripts/xtensa-build-all.sh -l -u -j apl

@keqiaozhang , I don't see you clearly responded Keyon's ask for non-SMP test results. The test results on 005 branch (the "bad" one) of non-SMP (with -u) and SMP (without -u) can provide important reference for developers on the two hot topics we're chasing, SMP and IPC timeout in simultaneous pipelines. previous issues like this one demonstrated that turning off SMP can dramatically reduce some failure of IPC errors (not timeout). There were speculations that it might be related with SMP. I think that's why Keyon asked you to test if non-SMP make differences on the "bad" one, even though people lean towards the root cause of IPC timeout is yet another undiscovered scheduler bug such as #778

@keqiaozhang

@keqiaozhang btw, with the latest repo, you can use '-u' to force UP(non-SMP) building, such as:
./scripts/xtensa-build-all.sh -l -u -j apl

@keqiaozhang , I don't see you clearly responded Keyon's ask for non-SMP test results. The test results on 005 branch (the "bad" one) of non-SMP (with -u) and SMP (without -u) can provide important reference for developers on the two hot topics we're chasing, SMP and IPC timeout in simultaneous pipelines. previous issues like this one demonstrated that turning off SMP can dramatically reduce some failure of IPC errors (not timeout). There were speculations that it might be related with SMP. I think that's why Keyon asked you to test if non-SMP make differences on the "bad" one, even though people lean towards the root cause of IPC timeout is yet another undiscovered scheduler bug such as #778

@wenqingfu @lgirdwood
Update the current status:

glk005 branch + smp: can reproduce this issue.
glk005 branch + up: not tested yet, will check it soon.
glk006 branch + smp: not tested yet, will check it soon.
glk006 branch + up: cannot reproduce this issue.
glk006 branch + up + PR scheduler: add pending_cnt for task to make pending scheduling possible #778: will check this PR soon.

@keqiaozhang

Hi @keqiaozhang, if we can't reproduce it with "master + up", then we don't need #778.

Updated:
glk005 branch + smp: can reproduce this issue.
glk005 branch + up: test is on going.
glk006 branch + smp: can reproduce this issueafter 895 iterations.
glk006 branch + up: cannot reproduce this issue.

I will do more tests with 'up' next.

@lgirdwood

@lgirdwood @wenqingfu
Update the test result:
glk005 branch + smp: can reproduce this issue.
glk005 branch + up: cannot reproduce this issue.
glk006 branch + smp: can reproduce this issue after 895 iterations.
glk006 branch + up: cannot reproduce this issue.

looks like this issue is related to 'smp', will do more tests to prove it.

Summary:
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

@lgirdwood

@lgirdwood @wenqingfu
non-smp is more stable, I only met failure once in the past 24 hours of testing.

@keqiaozhang

@keqiaozhang would you mind giving it a test refresh to see if this bug is still active? thanks!

Confirmed that this issue is fixed on glk-011-drop-stable branch. It can pass 10000 iterations without errors.
let's close this bug.

Navigation Menu

Repository navigation

[Stress] IPC times out during the volume change #780

4 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[Stress] IPC times out during the volume change #780

Description

Activity

lgirdwood commented on Jan 23, 2019

keqiaozhang commented on Jan 24, 2019

lgirdwood commented on Jan 24, 2019

dabekjakub commented on Jan 24, 2019

keqiaozhang commented on Jan 24, 2019

4 remaining items

keqiaozhang commented on Jan 25, 2019

lgirdwood commented on Jan 25, 2019

lgirdwood commented on Jan 25, 2019

plbossart commented on Jan 25, 2019

lgirdwood commented on Jan 25, 2019

wenqingfu commented on Jan 26, 2019

keqiaozhang commented on Jan 28, 2019

keyonjie commented on Jan 28, 2019

keqiaozhang commented on Jan 28, 2019

keqiaozhang commented on Jan 29, 2019

markyang commented on Jan 29, 2019

keqiaozhang commented on Jan 29, 2019

wenqingfu commented on Mar 28, 2019

keqiaozhang commented on Mar 28, 2019

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions