[BUG] KWD pipeline hang when DSP enters to D0i3

[keqiaozhang]

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

1. 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
2. trigger the pipeline
3. check the dmesg and console output

Reproduction Rate
100%

Environment

1. Kernel Branch: topic/sof-dev
2. Kernel Commit: 6fa085f3
3. SOF Branch: master
4. SOF Commit: cb92499
5. 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

dmesg.txt
trace.txt

[keqiaozhang]

This issue also can be reproduced on TGL-SDW Chromebook,

[ranj063]

@keqiaozhang how do you know the DSP has hung? There's nothing in the issue that suggests that?

[ranj063]

BTW have you disabled the system agent in the config when building the FW?

[keqiaozhang]

@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]

This issue is introduced by:8a5bcd9 "timer: scheduler: make all timer IO atomic in scheduler"

[keqiaozhang]

This issue is fixed by 70b447b