Noise issue when XRUN injection for playback

[DarrenxWang]

Summary:
Noise issue when XRUN injection for playback
No error in dmesg
the result is empty when run 'sudo ./sof-logger -l sof-apl.ldc-master-gcc'
error log:
0 1 VOLUME 60263494.947917 49.895832 volume.c:463 xro
0 2 COMP 60263497.552083 2.604167 ../../src/include/sof/audio/component.h:414 Xov
0 2 unknown 60263499.895833 2.343750 ../../src/include/sof/audio/component.h:415 value 65536
0 2 unknown 60263502.343750 2.447917 ../../src/include/sof/audio/component.h:416 value 384
0 1 PIPE 60263508.697917 6.354167 pipeline.c:903 ePU
0 1 unknown 60263510.885417 2.187500 pipeline.c:904 value 4
0 1 PIPE 60263513.645833 2.760417 pipeline.c:1198 pxr

Reproduce step:

1. aplay -D hw:0,0 -c 2 -r 48000 -f s16_le Music/48California_Dreaming.wav -vv -i
2. sudo ./xrun_injection.sh
3. sudo ./sof-logger -l sof-apl.ldc-master-gcc -t > logger.txt

Test env:
sof-master: bc50ce1
soft-master: a1dfcb7
kernel sof-dev: 2996b7e8cd0d
tplg: sof-apl-pcm512x.tplg

Log:
logger.txt
dmesg.log

[mengdonglin]

@keqiaozhang Does GLK also have this issue?

[keqiaozhang]

@mengdonglin
Not sure whether we can do xrun injection on Yorp. For doing xrun injection, we need to enable the CONFIG_SND_PCM_XRUN_DEBUG in kernel config, but chrome is using the different way to build the kernel, I will give it a try tomorrow to see if we can enable XRUN_DEBUG in chrome kernel config.

[lgirdwood]

@keqiaozhang please ask @cujomalainey if you get stuck enabling this on Chrome.

[keqiaozhang]

Thanks @lgirdwood
Today I checked the chrome kernel config, but there's no CONFIG_SND_PCM_XRUN_DEBUG item, so there may be some dependencies that need to be selected first.
@cujomalainey Can you help on this, since "make menuconfig" doesn't work.

[cujomalainey]

Apologies for the delay, I was flying back yesterday.
To do menu config on chrome run the following ./chromeos/scripts/kernelconfig editconfig from the root of the kernel repo.

[ZhendanYang]

On CNL with nocodec has the similar error log:

0      1   VOLUME 993921232.447917        71.250000             volume.c:463 	xro
0      2     COMP 993921235.208333         2.760417 ../../src/include/sof/audio/component.h:418 	Xov
0      2  unknown 993921238.125000         2.916667 ../../src/include/sof/audio/component.h:419 	value 65536
0      2  unknown 993921240.989583         2.864583 ../../src/include/sof/audio/component.h:420 	value 192
0      1     PIPE 993921248.281250         7.291667           pipeline.c:903 	ePU
0      1  unknown 993921250.885417         2.604167           pipeline.c:904 	value 4
0      1     PIPE 993921254.010417         3.125000           pipeline.c:1198	pxr

Test env:
sof-master: e101263
soft-master: b5eb15
kernel sof-dev: 03cadf8
tplg: test-ssp0-mclk-0-I2S-volume-s16le-s16le-48k-24000k-nocodec.tplg

logger.txt
logger-t.txt

[lgirdwood]

Looks like the volume component has had an overrun in each case (i.e. there is no space in the buffer)

[keqiaozhang]

Thanks @cujomalainey, now I can do xrun injection on Yorp.
This issue also can be reproduced on Yorp with xrun injection.

[lgirdwood]

@michalgrodzicki I guess you can reproduce on Yorp too ?

[keqiaozhang]

This issue still can be reproduced on new debug/cros-v4.14-rebase kernel branch.
Tested-config:
kernel-debug/cros-v4.14-rebase: 90eee4
sof-master: 43da169+ revert 62c568
soft-master: 4ac9248

How to reproduce:

1. enable XRUN debug in chromeos-intel-pineview.flavour.config:
   +CONFIG_SND_DEBUG=y
   +CONFIG_SND_DEBUG_VERBOSE=y
   +CONFIG_SND_PCM_XRUN_DEBUG=y
2. build and update kernel
3. sudo su -switch to supper user
4. aplay -Dhw:0,1 -f dat -c 2 audio.wav
5. Inject xrun during the playback: echo 1 > /proc/asound/card0/pcm1p/sub0/xrun_injection

[Jiangxinx]

Still can be reproduced with kernel branch debug/v4.19-backport, on APL UP2 platfrom.

STEP:
1.aplay -Dhw:0,0 audio.wav
2.sudo ./xrun_injection.sh

Test env:
hardware version: UP2
sof-master: 43da169
soft-master: 4ac9248
kernel debug/v4.19-backport: 925637e3
tplg: sof-apl-pcm512x.tplg

[markyang]

This issue can't be reproduced on UP2.

STEP:
1.aplay -Dhw:0,0 audio.wav
2.sudo ./xrun_injection.sh

Test env:
hardware version: UP2
sof-master: 43da169
soft-master: 4ac9248
kernel debug/v4.14-backport: 94f7a53e
tplg: sof-apl-pcm512x.tplg

[lgirdwood]

@markyang @Jiangxinx ok so you have same HW, FW and topology. What about your kernel configs. Can you both paste the output of

cd linux
grep -rn SOF .config

This will show which SOF options are enabled/disabled.

[bardliao]

@lgirdwood I can reproduce it on UP2. The output of "grep -rn SOF .config" is

845:CONFIG_HAVE_ARCH_SOFT_DIRTY=y
1029:CONFIG_MEM_SOFT_DIRTY=y
1791:CONFIG_CAN_SOFTING=m
1792:CONFIG_CAN_SOFTING_CS=m
4746:CONFIG_SOFT_WATCHDOG=m
4747:CONFIG_SOFT_WATCHDOG_PRETIMEOUT=y
6050:# CONFIG_VGACON_SOFT_SCROLLBACK is not set
6213:CONFIG_SND_SOC_SOF_PCI=m
6214:CONFIG_SND_SOC_SOF=m
6215:CONFIG_SND_SOC_SOF_NOCODEC=m
6216:CONFIG_SND_SOC_SOF_DEBUG=y
6217:# CONFIG_SND_SOC_SOF_FORCE_NOCODEC_MODE is not set
6218:# CONFIG_SND_SOC_SOF_DEBUG_XRUN_STOP is not set
6219:# CONFIG_SND_SOC_SOF_DEBUG_VERBOSE_IPC is not set
6220:CONFIG_SND_SOC_SOF_DEBUG_FORCE_IPC_POSITION=y
6221:CONFIG_SND_SOC_SOF_INTEL=m
6222:# CONFIG_SND_SOC_SOF_SPIDSP is not set
6223:# CONFIG_SND_SOC_SOF_BAYTRAIL is not set
6224:# CONFIG_SND_SOC_SOF_HASWELL is not set
6225:# CONFIG_SND_SOC_SOF_BROADWELL is not set
6226:CONFIG_SND_SOC_SOF_APOLLOLAKE=m
6227:# CONFIG_SND_SOC_SOF_GEMINILAKE is not set
6228:# CONFIG_SND_SOC_SOF_CANNONLAKE is not set
6229:# CONFIG_SND_SOC_SOF_KABYLAKE is not set
6230:# CONFIG_SND_SOC_SOF_SKYLAKE is not set
6231:# CONFIG_SND_SOC_SOF_ICELAKE is not set
6232:CONFIG_SND_SOC_SOF_HDA_COMMON=m
6233:CONFIG_SND_SOC_SOF_HDA=m
6234:CONFIG_SND_SOC_SOF_XTENSA=m
6455:CONFIG_HID_MICROSOFT=m
6658:# CONFIG_USB_DWC2_TRACK_MISSED_SOFS is not set
7580:CONFIG_SPEAKUP_SYNTH_SOFT=m
8566:CONFIG_ZISOFS=y
9311:CONFIG_SOFTLOCKUP_DETECTOR=y
9312:# CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC is not set
9313:CONFIG_BOOTPARAM_SOFTLOCKUP_PANIC_VALUE=0
9400:# CONFIG_IRQSOFF_TRACER is not set

It looks like alsa's xrun handling will cause firmware's xrun.
After ipc: msg rx -> 0x60050000 and ipc: msg rx -> 0x60040000, firmware will go into xrun.
Below is a part of logger message. Full logger log is attached.

 0      2          IPC          27667259.739583  20374412.000000            apl-ipc.c:111 	ipc: msg rx -> 0x60050000
    0      2          IPC          27667264.375000         4.635417            handler.c:417 	ipc_stream_trigger()
    0      2         PIPE 2.11     27667269.843750         5.468750           pipeline.c:774 	pipeline_trigger()
    0      2         HOST          27667273.125000         3.281250               host.c:277 	trg
    0      2          DMA          27667276.666667         3.541667            hda-dma.c:567 	hda-dmac: 5 channel 0 -> stop
    0      2       VOLUME          27667280.052083         3.385417             volume.c:429 	trg
    0      2          DAI          27667283.020833         2.968750                dai.c:540 	dai_comp_trigger(), command = 0
    0      2          DAI          27667285.833333         2.812500                dai.c:610 	dai_comp_trigger(), PAUSE/STOP
    0      2          DMA          27667288.697917         2.864583            hda-dma.c:567 	hda-dmac: 7 channel 0 -> stop
    0      2          IPC          27684113.906250     16825.208984            apl-ipc.c:111 	ipc: msg rx -> 0x60040000
    0      2          IPC          27684118.229167         4.322917            handler.c:417 	ipc_stream_trigger()
    0      2         PIPE 2.11     27684123.489583         5.260417           pipeline.c:774 	pipeline_trigger()
    0      2         HOST          27684126.614583         3.125000               host.c:277 	trg
    0      2          DMA          27684129.895833         3.281250            hda-dma.c:468 	hda-dmac: 5 channel 0 -> start
    0      2          DMA          27684133.437500         3.541667            hda-dma.c:317 	hda-dmac: 5 channel 0 -> enable
    0      2       VOLUME          27684169.895833        36.458332             volume.c:429 	trg
    0      2          DAI          27684172.916667         3.020833                dai.c:540 	dai_comp_trigger(), command = 1
    0      2          DAI          27684175.781250         2.864583                dai.c:548 	dai_comp_trigger(), START
    0      2          DMA          27684178.697917         2.916667            hda-dma.c:468 	hda-dmac: 7 channel 0 -> start
    0      1       VOLUME          27684230.781250        52.083332             volume.c:463 	xro
    0      2         COMP          27684235.520833         4.739583 ../../src/include/sof/audio/component.h:421 	Xov
    0      2      unknown          27684238.072917         2.552083 ../../src/include/sof/audio/component.h:422 	value 458752
    0      2      unknown          27684240.625000         2.552083 ../../src/include/sof/audio/component.h:423 	value 384
    0      1         PIPE          27684248.437500         7.812500           pipeline.c:926 	pipeline_copy_from_upstream() error: err = -5, current->comp.id = 10
    0      1         PIPE 2.11     27684254.062500         5.625000           pipeline.c:1221	pipeline_xrun_recover()
    0      2         PIPE 2.11     27684258.333333         4.270833           pipeline.c:774 	pipeline_trigger()

logger.txt

[lgirdwood]

@bardliao I've edited your above post using the markdown to make it easier to read. Does the FW recover from the XRUN and play correctly in this case/config/pipeline ?

[bardliao]

@lgirdwood No, it doesn't always play correctly after the XRUN. I record the output by my cell phone and attach it for your reference. I hit the keyboard at around 2.8 sec in the recorded file, and XRUN happens after that.
2018-11-21_08-54-36_8690.zip

[lgirdwood]

@bardliao can you capture this will a line in cable on a PC/laptop (quality is bad from a phone). There are also guidelines for reporting audio quality issues that @mengdonglin recently updated. Please follow these on the website.

[bardliao]

@lgirdwood Thanks @keqiaozhang The recording file is attached. The file is done by loopback on GLK. We do xrun_injection in every 5 sec and there is a short pop when we do xrun_injection. Ideally, playback will recover after the short pop but sometimes it doesn't. We can see the spectrogram has changed after XRUN. I think we can invite firmware folks to check it.
noise.zip

[markyang]

The content of xrun_injection.sh:

#!/bin/bash 

file=$(find /proc/asound/card0/ -name "*injection*")

int=0
while [ $int -lt 100000 ]
do
	for i in $file
	do
		echo 0 > $i
	done
	sleep 5
	echo $int
	let int++
done

[mengdonglin]

@slawblauciak Here are the steps used by Bard to reproduce this issue:

1. enable XRUN debug in chromeos-intel-pineview.flavour.config:
   +CONFIG_SND_DEBUG=y
   +CONFIG_SND_DEBUG_VERBOSE=y
   +CONFIG_SND_PCM_XRUN_DEBUG=y
2. build and update kernel
3. sudo su -switch to supper user
4. aplay -Dhw:0,1 -f dat -c 2 audio.wav
5. Inject xrun during the playback: echo 1 > /proc/asound/card0/pcm1p/sub0/xrun_injection

@bardliao Thanks for sharing

[xiulipan]

@ranj063 @keyonjie @lgirdwood
One hint from scheduler refine:
For the pipeline_task, the pipeline_xrun_recover will schedule a task from pipeline_trigger COMP_TRIGGER_START that will be ignored since the xrun recovery is called from pipeline_task.

Following is the workaround added by @tlauda f396500 #125 (discussion about the fix is here)

        /* for playback copy it here, because scheduling won't work
         * on this interrupt level
         */
        if (p->sched_comp->params.direction == SOF_IPC_STREAM_PLAYBACK) {
                ret = pipeline_copy(p->sched_comp);
                if (ret < 0) {
                        trace_pipe_error_with_ids(p, "pipeline_xrun_recover() "
                                                  "error: pipeline_copy() "
                                                  "failed, ret = %d", ret);
                        return ret;
                }
        }

So if the task is going to accepted running task to be added. You need to remove the above code or add more check in the pipeline_trigger

[mengdonglin]

This is a duplicate of issue reported by Google: #752
It seems we may need a similar workaround of @tlauda to fix FW XRUN recovery or avoid XRUN on STOP/START.

[keqiaozhang]

Verified that this issue is fixed on glk-005-drop-stable branch.
Tested with: glk-005-drop-stable/4d7904d.

@markyang
Please help to confirm it on other platforms.

[markyang]

Summary:
This issue cannot be reproduced on APL with PCM512x.

Test steps:

1. enable XRUN debug in .config:
  +CONFIG_SND_DEBUG=y
  +CONFIG_SND_DEBUG_VERBOSE=y
  +CONFIG_SND_PCM_XRUN_DEBUG=y
2. build and update kernel
3. aplay -Dhw:0,0 -c2 -fS32_LE -vv -i audio.wav
4. sudo su switch to root # in a new terminal
5. inject xrun during the playback: 
   echo 1 > /proc/asound/card0/pcm0p/sub0/xrun_injection

Test env:
sof master: da9ab07
kernel sof-dev: cac0c10
tplg: sof-apl-pcm512x.tplg