Repository navigation
[BUG][CML] IPC error for '0x60040000: GLB_STREAM_MSG: TRIG_START' #1477
Description
Describe the bug
ipc error , but not timed out, for '0x60040000: GLB_STREAM_MSG: TRIG_START' during S3 with playback stress test.
To Reproduce
Run S3 with playback stress test "aplay -Dhw:0,0 -r48000 -c2 -fs16_le /dev/zero & sudo ./stress-s3.sh 500 1 1"
Expected behavior
Aplay stopped at 23th and ipc error can be found in dmesg
Frequency:1/25
Impact
aplay should be continued and no ipc error
Environment
Kernel: 9453da1 https://github.com/lyakh/linux/tree/ipc-timeout (with PR895)
FW:b527fd7 https://github.com/lyakh/sof/tree/ipc-timeout (with PR1354)
Topology:Same as above FW repo, file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg
kconfig:https://drive.google.com/open?id=1U4pR28-g_OlCZFFpXzWpy2uMKnvV8i-C
unset CONFIG_SND_SOC_SOF_DEBUG_ENABLE_DEBUGFS_CACHE
error logger:
CORE LEVEL COMP_ID TIMESTAMP DELTA FILE_NAME CONTENT
0 1 COMP 20790619313.697918 nan rc/audio/component.c:140 comp_set_state() error: wrong state = 1, COMP_TRIGGER_START
0 1 IPC 20790619320.156250 6.458333 src/audio/pipeline.c:606 pipeline_trigger() error: ret = -22, host->comp.id = 1, cmd = 1
0 1 IPC 20790619326.875000 6.718750 src/ipc/handler.c:513 ipc: comp 1 trigger 0x40000 failed -22
0 1 COMP 20790619549.270836 222.395828 rc/audio/component.c:161 comp_set_state() error: wrong state = 1, COMP_TRIGGER_STOP
0 1 IPC 20790619555.312500 6.041667 src/audio/pipeline.c:606 pipeline_trigger() error: ret = -22, host->comp.id = 1, cmd = 0
0 1 IPC 20790619561.979168 6.666667 src/ipc/handler.c:513 ipc: comp 1 trigger 0x50000 failed -22
0 1 DMA 20791375954.010418 756392.000000 intel/cavs/hda-dma.c:639 hda-dmac: 5 invalid channel -1
dmesg
[ 466.828495] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 5
[ 466.828501] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 466.828649] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 466.828653] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 466.828842] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 466.828846] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=5
[ 466.828849] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 466.829003] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[ 467.444918] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 467.444953] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 467.845591] PM: Some devices failed to suspend, or early wake event detected
[ 467.845713] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[ 467.845773] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[ 467.845788] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 7:0
[ 468.050234] iwlwifi 0000:00:14.3: BIOS contains WGDS but no WRDS
[ 468.054954] OOM killer enabled.
[ 468.054954] Restarting tasks ... done.
[ 468.070838] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[ 468.070846] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 468.071004] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60040000 size 12
[ 468.071007] HDA Analog: ASoC: trigger FE failed -22
[ 468.071009] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 468.071035] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 468.071154] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x60050000 size 12
[ 468.071155] HDA Analog: ASoC: trigger FE failed -22
[ 468.131436] PM: suspend exit
[ 468.676149] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 468.676158] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 468.676441] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 468.676474] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[ 468.676717] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[ 468.676842] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 468.944943] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 468.945059] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 469.444901] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 469.445014] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
Attach failed 23th logs and previous 22th logs
test_22.log
test_23.log
s3_test_23_logger_all.log
s3_test_23_logger_error.log
s3_test_22_logger_all.log
Activity
ClarexZhou commentedon May 27, 2019
Track ipc timed out in #1396
[-][BUG][CML]IPC error for '0x60040000: GLB_STREAM_MSG: TRIG_START' [/-][+][BUG][CML] IPC timed out error for '0x60040000: GLB_STREAM_MSG: TRIG_START' [/+][-][BUG][CML] IPC timed out error for '0x60040000: GLB_STREAM_MSG: TRIG_START' [/-][+][BUG][CML] IPC error for '0x60040000: GLB_STREAM_MSG: TRIG_START' [/+]ranj063 commentedon May 28, 2019
This is a very misleading error title. The problem is not that the IPC error occurred after resume.
The problem is that the sof-audio-pci device failed to suspend (as below):
[ 467.845591] PM: Some devices failed to suspend, or early wake event detected
This of course leads to the IPC error upon resume because the stream was never suspended and therefore it doesnt get the prepare() ioctl.
ranj063 commentedon May 28, 2019
And this should be a kernel bug.
ClarexZhou commentedon May 28, 2019
@ranj063 thanks. Close current issue and track in thesofproject/linux#984