[BUG][Smart_Amp] ipc timeout in smart_amp pipelines test

Describe the bug
Run command arecord -Dhw:0,2 -f dat /dev/null -vvv & aplay -Dhw:0,2 -f dat /dev/zero, Everything is fine at the first run. but io error in terminal and ipc timeout in dmesg at the second run. If you are lucky, you may see ipc time out at the first run. Once issue happened, playback on other pipeline fails with 'unable to install hw params'

To Reproduce

reboot
run command arecord -Dhw:0,2 -f dat /dev/null -vvv & aplay -Dhw:0,2 -f dat /dev/zero several times

Reproduction Rate
very very high

Impact
Hardware echo reference work abnormally.

Environment

Branch name and commit hash of the 2 repositories:
- Kernel: topic/sof-dev {12d64d62}
- SOF: master {131f0d4}
Name of the topology file
- Topology: {sof-tgl-nocodec-ci.tplg} you can try other tplg with HWEchoRef(DSM) enabled
Name of the platform(s) on which the bug is observed.
- Platform: {TGL nocodec with HWEchoRef enabled}

dmesg.txt
sof-logger.txt

@aiChaoSONG

@aiChaoSONG This is because echo reference capture only works when playback has data output first.

"aplay & arecord " will start at same time, might arecord first also. So got this issue.
So need using command "aplay & sleep 0.5; arecord " for echo reference test.
Such as aplay -Dhw:0,0 -f s16_le -c 2 -r 48000 sine_48k_16bit_10s_stereo_l5_r2.wav & sleep 0.5; arecord -Dhw:0,6 -f s16_le -c 2 -r 48000 echorefe.wav -d 7

Do we able to close this?

@ClarexZhou

Do we able to close this?

@ClarexZhou No, This is in fact DSM, Pierre give it the name HW EchoRef, Echo reference is actually FWEchoRef

@aiChaoSONG

@aiChaoSONG
Are you able to reproduce it also with codec topology (sof-tgl-max98373-rt5682.tplg)?
Is sof-tgl-codec-ci.tplg on master? Is this the same as sof-tgl-codec.tplg?

@bkokoszx

@bkokoszx I tried on TGL with codec and sof-tgl-max98373-rt5682.tplg, issue also reproduced. sof-tgl-codec-ci.tplg is here: #3212

error message when issue reproduced on TGL with codec
dmesg.txt

@bkokoszx

@bkokoszx if you cannot reproduce this issue with the command in the description, Please try our test case.

clone https://github.com/thesofproject/sof-test, and cd sof-test
apt install python3-numpy python3-scipy
copy sof-tgl.ldc to /etc/sof
config NOPASSWD for current user. sudo visudo, change %sudo ALL=(ALL:ALL) ALL to %sudo ALL=(ALL:ALL) NOPASSWD:ALL
make sure sof-logger in PATH
run test case : TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-max98373-rt5682.tplg test-case/check-smart-amplifier.sh

@aiChaoSONG

@aiChaoSONG
Did you build firmware for chrome configuration?

Is there any special konfig for building above kernel? Is below command sufficient?
bash ./scripts/kconfig/merge_config.sh .config $KCONFIG_PATH/base-defconfig $KCONFIG_PATH/sof-defconfig $KCONFIG_PATH/sof-mach-driver-defconfig $KCONFIG_PATH/hdaudio-codecs-defconfig

Thanks

PS
I see following error during topology build with #3212 :
https://sof-ci.01.org/sofpr/PR3212/build6794/build/tools.txt
Is there a special way to build it?

@aiChaoSONG

@aiChaoSONG
Did you build firmware for chrome configuration?

Is there any special konfig for building above kernel? Is below command sufficient?
bash ./scripts/kconfig/merge_config.sh .config $KCONFIG_PATH/base-defconfig $KCONFIG_PATH/sof-defconfig $KCONFIG_PATH/sof-mach-driver-defconfig $KCONFIG_PATH/hdaudio-codecs-defconfig

We are using force-nocodec mode for this testing, just use the kconfig-sof-nocodec.sh below directly for the kconfig:
https://github.com/thesofproject/kconfig/blob/master/kconfig-sof-nocodec.sh

Thanks

PS
I see following error during topology build with #3212 :
https://sof-ci.01.org/sofpr/PR3212/build6794/build/tools.txt
Is there a special way to build it?

I don't think so, usually we just run ./scripts/build-tools.sh to build it, @xiulipan can you help to check this?

@keyonjie

@keyonjie @aiChaoSONG
In attached dmesg file we can observe:

[   27.319356] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   27.320102] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   27.320112] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   27.827455] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 2 dir 1 cmd 0
[   27.827464] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   28.331286] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[   28.331293] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   28.331301] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005

Do you know why we see trigger stop ipc just after trigger start?

usually it is because of there is no data captured after started for e.g. 500ms timeout.

@keyonjie

@keyonjie

I've added following trace points to the firmware master.

diff --git a/src/drivers/intel/cavs/ipc.c b/src/drivers/intel/cavs/ipc.c
index 7d335fce6..3a33d5c41 100644
--- a/src/drivers/intel/cavs/ipc.c
+++ b/src/drivers/intel/cavs/ipc.c
@@ -67,6 +67,8 @@ static void ipc_irq_handler(void *arg)
        struct ipc *ipc = arg;
        uint32_t dipcctl;

+       trace_point(0x5000);
+
 #if CAVS_VERSION == CAVS_VERSION_1_5
        uint32_t dipct;
        uint32_t dipcie;
@@ -85,7 +87,7 @@ static void ipc_irq_handler(void *arg)
        dipcida = ipc_read(IPC_DIPCIDA);
        dipcctl = ipc_read(IPC_DIPCCTL);

-       tr_dbg(&ipc_tr, "ipc: irq dipctdr 0x%x dipcida 0x%x dipcctl 0x%x",
+       tr_err(&ipc_tr, "ipc: irq dipctdr 0x%x dipcida 0x%x dipcctl 0x%x",
               dipctdr, dipcida, dipcctl);
 #endif

@@ -178,6 +180,8 @@ static struct sof_ipc_cmd_hdr *ipc_compact_read_msg(void)

 enum task_state ipc_platform_do_cmd(void *data)
 {
+       trace_point(0x5100);
+
 #if !CONFIG_SUECREEK
        struct ipc *ipc = data;
 #endif
diff --git a/src/ipc/handler.c b/src/ipc/handler.c
index d6a3fe307..56a398664 100644
--- a/src/ipc/handler.c
+++ b/src/ipc/handler.c
@@ -415,9 +415,11 @@ static int ipc_stream_trigger(uint32_t header)

        switch (ipc_cmd) {
        case SOF_IPC_STREAM_TRIG_START:
+               trace_point(0x6000);
                cmd = COMP_TRIGGER_START;
                break;
        case SOF_IPC_STREAM_TRIG_STOP:
+               trace_point(0x7000);
                cmd = COMP_TRIGGER_STOP;
                break;
        case SOF_IPC_STREAM_TRIG_PAUSE:
@@ -449,7 +451,7 @@ static int ipc_stream_trigger(uint32_t header)
 static int ipc_glb_stream_message(uint32_t header)
 {
        uint32_t cmd = iCS(header);
-
+       trace_point(0x5300);
        switch (cmd) {
        case SOF_IPC_STREAM_PCM_PARAMS:
                return ipc_stream_pcm_params(header);
@@ -1255,6 +1257,8 @@ void ipc_cmd(struct sof_ipc_cmd_hdr *hdr)

I've made arecord & aplay and reproduced issue. After root@audiodspTGL:~# hexdump /sys/kernel/debug/sof/regs
I get:

0000000 0005 0000 0000 0000 6000 0000 0000 0000
0000010 0000 0000 0000 0000 01c0 0251 4000 0000
0000020 0000 0000 0000 0000 0000 0000 0000 0000

, which means that the latest trace point value is 0x6000 (TRIGGER_START). I have suspicion
that TRIGGER_STOP mentioned in previous comment, did not come to the FW. Is it
possible?

, which means that the latest trace point value is 0x6000 (TRIGGER_START). I have suspicion
that TRIGGER_STOP mentioned in previous comment, did not come to the FW. Is it
possible?

I would suspect that the firmware is somehow hang or crashed after trigger started so didn't get the subsequent trigger stop IPC, need more debugging about what has happened after trigger started.

@bkokoszx

@bkokoszx @keyonjie @aiChaoSONG the timing between START and STOP is small suggesting a XRUN (i.e. position has not moved so driver automatically stops the stream).
@keyonjie can you add debug in driver to check is stream position updates at all ?

@lgirdwood

Hi @lgirdwood I think @bkokoszx has found the cause here, the FW hangs on demux_copy() after trigger started, that's why the STOP IPC got timeout. We had PR like #2788 previously on release branch to avoid the format un-alignment and this kind of hang issues, we might need similar logic for the master.

@keyonjie

As @keyonjie wrote, we have misalignment in buffer's frame_fmt parameters. We have hardcoded format for feedback buffer:

	/* TODO:
	 * ATM feedback buffer frame_fmt is hardcoded to s32_le. It should be
	 * removed when parameters negotiation between pipelines will prepared
	 */
	sad->feedback_buf->stream.frame_fmt = SOF_IPC_FRAME_S32_LE

as ATM our pipeline propagation do not cover whole DSM topology case (parameters do not reach feedback buffer).

@aiChaoSONG
Could you try to test master + PR #2788 in order to reproduce this issue?

@bkokoszx

@bkokoszx @keyonjie I tried #2788, and I think situation become worse. DSP panic at the very beginning of running the DSM case, sof-logger exit immediately without showing any trace message.

sof_error.log

@aiChaoSONG

@aiChaoSONG
Did you rebase it with master or use #2788 directly? If you do not use rebased version, you can try: https://github.com/bkokoszx/sof/tree/pr2788-rebased
I do not have platform yet, I will try it also as soon as possible.

@bkokoszx

@bkokoszx I tried your pr2788-rebased tree, test result is pretty good. But if I apply #2788 directly to master, test result is worse like I described above. Seems your commit bkokoszx@27906fb makes a lot of difference.

@aiChaoSONG

@aiChaoSONG
Yes, I've removed in this commit hardcoded frame format value for smart amplifier.
It should be merged just after #2788

@bkokoszx

@bkokoszx @aiChaoSONG is it fixed with #2788 ?

With #2788 and #3404, issue fixed. close

Navigation Menu

Repository navigation

[BUG][Smart_Amp] ipc timeout in smart_amp pipelines test #3249

5 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG][Smart_Amp] ipc timeout in smart_amp pipelines test #3249

Description

Activity

ClarexZhou commented on Jul 29, 2020

ClarexZhou commented on Jul 29, 2020

aiChaoSONG commented on Jul 29, 2020

bkokoszx commented on Aug 10, 2020

aiChaoSONG commented on Aug 11, 2020

aiChaoSONG commented on Aug 11, 2020

bkokoszx commented on Aug 11, 2020

keyonjie commented on Aug 12, 2020

5 remaining items

keyonjie commented on Aug 18, 2020

bkokoszx commented on Aug 18, 2020

keyonjie commented on Aug 19, 2020

lgirdwood commented on Aug 20, 2020

keyonjie commented on Aug 20, 2020

bkokoszx commented on Aug 25, 2020

aiChaoSONG commented on Aug 25, 2020

bkokoszx commented on Aug 26, 2020

aiChaoSONG commented on Aug 27, 2020

bkokoszx commented on Aug 27, 2020

jajanusz commented on Sep 15, 2020

aiChaoSONG commented on Sep 15, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions