Repository navigation
[BUG] KWD pipeline hang when DSP enters to D0i3 #3800
Description
Describe the bug
This is a regression and CI detected this issue from last Friday. After triggering, KWD pipeline will hang after DSP entered to D0i3.
To Reproduce
- run kwd:
$arecord -Dhw:0,7 -M -N -r 16000 -c 2 -f S16_LE --buffer-size=96000 -d 10 /tmp/wov_S16_record.wav - trigger the pipeline
- check the dmesg and console output
Reproduction Rate
100%
Environment
- Kernel Branch: topic/sof-dev
- Kernel Commit: 6fa085f3
- SOF Branch: master
- SOF Commit: cb92499
- platform: TGL_RVP_HDA
Screenshots or console output
2021-02-01 08:17:43 UTC [COMMAND] arecord -Dhw:0,7 -M -N -r 16000 -c 2 -f S16_LE --buffer-size=96000 -d 10 /tmp/wov_S16_record.wav
Recording WAVE '/tmp/wov_S16_record.wav' : Signed 16 bit Little Endian, Rate 16000 Hz, Stereo
Hardware PCM card 0 'sof-hda-dsp' device 7 subdevice 0
Its setup is:
stream : CAPTURE
access : MMAP_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 16000
exact rate : 16000 (16000/1)
msbits : 16
buffer_size : 96000
period_size : 24000
period_time : 1500000
tstamp_mode : NONE
tstamp_type : MONOTONIC
period_step : 1
avail_min : 24000
period_event : 0
start_threshold : 1
stop_threshold : 96000
silence_threshold: 0
silence_size : 0
boundary : 6755399441055744000
appl_ptr : 0
hw_ptr : 0
mmap_area[0] = 0x7fd466b3b000,0,32 (16)
mmap_area[1] = 0x7fd466b3b000,16,32 (16)
Max peak (48000 samples): 0x0000046d # 3%
Max peak (16000 samples): 0x0000046d # 3%
Max peak (3824 samples): 0x000011ac ### 13%
Max peak (3200 samples): 0x000011ac ### 13%
Max peak (3200 samples): 0x000011ad ### 13%
Max peak (3200 samples): 0x000011ac ### 13%
Max peak (3200 samples): 0x000011ae ### 13%
Max peak (3200 samples): 0x000011ae ### 13%
Max peak (3200 samples): 0x000011ae ### 13%
Max peak (3200 samples): 0x000011ae ### 13%
Max peak (3200 samples): 0x000011ad ### 13%
Max peak (2576 samples): 0x000011ae ### 13%
Max peak (624 samples): 0x000011ac ### 13%
Max peak (3200 samples): 0x000011ad ### 13%
Max peak (3200 samples): 0x000011ad ### 13%
Max peak (2560 samples): 0x000011af ### 13%
There are no obvious errors in dmesg or trace.
dmesg
[ 750.505150] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 750.507853] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 750.507855] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 791136
[ 750.507913] sof-audio-pci 0000:00:1f.3: received event 1 for widget DETECT12.0
[ 750.507920] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 750.508319] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 750.508323] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 750.508604] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 750.508606] sof-audio-pci 0000:00:1f.3: received event 2 for widget DETECT12.0
[ 750.508942] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 7 dir 1 cmd 1
[ 750.509201] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[ 750.509206] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 750.509635] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 750.509640] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 750.509678] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 751.009779] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 751.009834] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 751.509716] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 751.509775] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 752.509722] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 752.509779] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 754.449740] sof-audio-pci 0000:00:1f.3: ipc rx: 0x50050048: GLB_COMP_MSG: unknown type
[ 754.449752] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x50050048: GLB_COMP_MSG: unknown type
[ 755.009653] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 755.009714] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 755.509642] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 755.509697] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 755.724264] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40080000: GLB_PM_MSG: unknown type
[ 755.724578] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40080000: GLB_PM_MSG: unknown type
[ 755.724588] sof-audio-pci 0000:00:1f.3: Current DSP power state: D0I3
Activity
keqiaozhang commentedon Feb 2, 2021
This issue also can be reproduced on TGL-SDW Chromebook,
ranj063 commentedon Feb 2, 2021
@keqiaozhang how do you know the DSP has hung? There's nothing in the issue that suggests that?
ranj063 commentedon Feb 2, 2021
BTW have you disabled the system agent in the config when building the FW?
keqiaozhang commentedon Feb 2, 2021
@ranj063 ， it's the kwd pipeline hang, not the DSP hang. the kwd pipeline stops recording and hang when DSP enters to D0i3 mode.
This issue has nothing to do with the system agent. because we are using the default config to build FW in CI, for tgplp_defconfig, system agent is enabled as default, I tried it on TGL_RVP_HDA, issue can be preproduced. I also tried the override.config to disable the system agent and tested on TGL_VOLT_SDW and issue still can be reproduced. Since this issue happened from last Friday. I will try to bisect next.
keqiaozhang commentedon Feb 2, 2021
This issue is introduced by:8a5bcd9 "timer: scheduler: make all timer IO atomic in scheduler"
[-][BUG] KWD hang when DSP enters to D0i3[/-][+][BUG] KWD pipeline hang when DSP enters to D0i3[/+]keqiaozhang commentedon Feb 4, 2021
This issue is fixed by 70b447b