[Bug][DSM][tgl v7.0-rc7]Runtime PM keeps active after i2s max98373 DSM capture #3147
Description
Describe the bug
This issue is split from #3145. Runtime PM keeps active after DSM
To Reproduce
- Boot up system
- cat "/sys/bus/pci/devices/0000:00:1f.3/power/runtime_status" to check, runtime PM is suspended succesfully
- Run "aplay -Dhw:0,0 -f s32_le -c 2 -r 48000 sine_48k_32bit_10s_stereo_l5_r2.wav -d 5 & arecord -Dhw:0,0 -f s32_le -c 4 -r 48000 record.wav -d 5"
- Wait for a while and cat "/sys/bus/pci/devices/0000:00:1f.3/power/runtime_status" to check again, runtime PM keeps active
Reproduction Rate
5/5
Expected behavior
Runtime PM should go to suspend
Impact
Runtime PM keeps active
Environment
Kernel:https://github.com/thesofproject/linux/commits/topic/sof-dev (commit: 1b2f260)
- ASoC: hdac_hda: fix deadlock after PCM open error linux#2208 for DP fix
- ASoC: SOF: Intel: fix the suspend procedure to support s0ix entry linux#2184 for wov S0i2
+ASoC: codec: max98373-sdw: fix initialization issue when codec resumes linux#2238 for max98373-sdw jack switc - 0001-hack-hack-98373-for-feedback-data-validation.patch.txt
FW: https://github.com/thesofproject/sof/tree/releases/tgl/v7.0-rc7 commit: 33cfa90
TPLG:sof-tgl-max98373-rt5682.tplg
Platform:Chromebook with codec 98373 in I2S mode.
dmesg_PMactiveAfterDSM.txt
sof_trace_PMactiveAfterDSM.txt
capture_audio.zip
ipc timed out in dmesg
[ 145.052709] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[ 145.052712] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 145.055282] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 145.055285] SSP1-Codec: ASoC: trigger BE SSP1-Codec cmd 1
[ 148.800245] SSP1-Codec: ASoC: trigger BE SSP1-Codec cmd 0
[ 148.813595] smart373-spk: ASoC: post trigger FE smart373-spk cmd 0
[ 148.813607] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 148.813621] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 149.314297] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[ 149.314304] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[ 149.314311] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 149.314414] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 149.314423] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000083 rirb 00
[ 149.314425] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 149.314430] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 149.314432] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 149.315328] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[ 149.315350] smart373-spk: ASoC: trigger FE cmd: 0 failed: -110
[ 149.315422] smart373-spk: ASoC: hw_free FE smart373-spk
[ 149.315432] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 149.315442] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 149.317894] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 149.317924] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 149.317940] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 149.317959] SSP1-Codec: ASoC: hw_free BE SSP1-Codec
[ 149.318085] SSP1-Codec: ASoC: close BE SSP1-Codec
[ 149.318101] smart373-spk: ASoC: close FE smart373-spk
[ 149.318110] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 149.318121] SSP1-Codec: ASoC: BE SSP1-Codec event 2 dir 0
[ 149.318221] smart373-spk: ASoC: BE playback disconnect check for SSP1-Codec
[ 149.318224] smart373-spk: freed DSP playback path smart373-spk -> SSP1-Codec
no error trace. But below info in sof-trace:
[494536141.770833] ( 2441.666748) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 220 uS 8468 ticks
[494538581.510417] ( 2439.739502) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 220 uS 8456 ticks
[494541019.895833] ( 2438.385498) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 219 uS 8417 ticks
[494543464.635417] ( 2444.739502) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 222 uS 8538 ticks
[494545827.708333] ( 2363.072998) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 181 uS 6960 ticks
[494548283.645833] ( 2455.937500) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 228 uS 8766 ticks
[494550743.333333] ( 2459.687500) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 229 uS 8825 ticks
[494553048.958333] ( 2305.625000) c0 ll-schedule /schedule/timer_domain.c:35 ERROR timer_report_delay(): timer 3 delayed by 152 uS 5868 ticks
[494735251.770833] ( 182202.812500) c0 dma-trace src/trace/dma-trace.c:480 ERROR dtrace_add_event(): number of dropped logs = 74
[494736160.885417] ( 909.114563) c0 dma-trace src/trace/dma-trace.c:480 ERROR dtrace_add_event(): number of dropped logs = 13
[494736144.114583] ( nan) c0 pipe 1.6 src/audio/pipeline.c:864 pipe reset
[494736359.843750] ( 215.729172) c0 smart_amp-test 1.1 ./audio/smart_amp_test.c:487 smart_amp_reset()
[494736386.770833] ( 26.927084) c0 smart_amp-test 1.1 src/audio/component.c:182 ERROR comp_set_state(): wrong state = 5, COMP_TRIGGER_RESET
[494736514.010417] ( 127.239586) c0 dai 1.5 src/audio/component.c:182 ERROR comp_set_state(): wrong state = 5, COMP_TRIGGER_RESET
[497896501.041667] ( 3159987.000000) c0 pipe 11.66 src/audio/pipeline.c:784 pipe trigger cmd 0
[497896536.875000] ( 35.833332) c0 hda-dma ..../intel/hda/hda-dma.c:545 hda-dmac: 4 channel 1 -> stop
[497896569.375000] ( 32.500000) c0 demux 11.62 src/audio/mux/mux.c:497 mux_trigger(), command = 0
[497896604.270833] ( 34.895832) c0 dw-dma src/drivers/dw/dma.c:406 dw_dma_stop(): dma 1 channel 0 stop
[497896641.145833] ( 36.875000) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:760 ssp_trigger() cmd 0
[497896787.083333] ( 145.937500) c0 ssp-dai 1.1 /drivers/intel/ssp/ssp.c:721 ssp_stop(), RX stop
[497896824.635417] ( 37.552082) c0 ll-schedule ./schedule/ll_schedule.c:421 task cancel 0xbe081e00 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[497896855.052083] ( 30.416666) c0 ll-schedule ./schedule/ll_schedule.c:279 num_tasks 2 total_num_tasks 2