Fix pm_runtime_put_autosuspend() failed issues in sof driver

[keyonjie]

There might be wrong usage to pm_runtime_put_autosuspend() in SOF driver, previously I saw dmesg errors like "error: pcm close failed to idle -16" on UP2, and know another similar errors happens on CML platforms on every boots:

[ 5.651129] sof-audio-pci 0000:00:1f.3: firmware boot complete
[ 5.717502] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.717659] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.717847] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.718040] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.718223] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.718405] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.718594] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.718794] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.719013] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16

This is not critical but there might be some PM issues hidden there, can anybody help to investigate and fix it?

[ranj063]

@keyonjie there are no reproduction steps here? And what platform?

[keyonjie]

@keyonjie there are no reproduction steps here? And what platform?

The errors happens on CML platforms on every boots.

[plbossart]

We'd need to know if this is specific to CML or if this also applies to Up2. Not sure how to start debugging for now?

[ranj063]

@plbossart this is not seen onUp2 or even the CML chromebook. Seems specific to CML with HDA

[wenqingfu]

@ranj063 can you reproduce this on your WHL?

[ranj063]

@wenqingfu sorry I've been a bit busy with a couple of other issues. Let me check on this tonight.
I should be able to reproduce this on my WHL

[ranj063]

@lgirdwood @kv2019i I could use some help from you here: Basically, the error that happens during volume get autosuspend doesnt occur every single time. The logs below show 3 sets of the volume command being sent to the driver for all the 9 volume components that are in topology. The first set and the third set do not show the error. But the 2nd one, all of them fail. The only difference between the 3 is that the first and the third times happen after a PCM stream is opened. In the case of the second one, there is no PCM open when the volume commands are sent. I've highlighted all the volume command IPC's in bold below.

And of course I think it is pulseaudio at work here. Can you please enlighten me with what pulseaudio is even trying to do here opening a stream, setting the kcontrols andclosing the stream so many times?

[ 6.757928] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 6.757933] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.757936] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.757938] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.758224] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.758234] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[ 6.758240] sof-audio-pci 0000:00:1f.3: generating page table for 000000002a2194d2 size 0x4b00 pages 5
[ 6.758264] sof-audio-pci 0000:00:1f.3: period_bytes:0x12c0
[ 6.758267] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.758286] sof-audio-pci 0000:00:1f.3: stream_tag 1
[ 6.758301] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.758482] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.758487] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790604
[ 6.765055] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.765286] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.765312] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.765551] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.765602] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.765830] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.765879] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766052] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766079] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766255] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766282] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766503] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766552] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766784] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.766835] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.767023] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.767050] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.767229] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.767570] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 6.767576] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.767721] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.767809] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 6.814828] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 6.814834] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.814837] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.814839] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.815110] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.815122] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[ 6.815128] sof-audio-pci 0000:00:1f.3: generating page table for 000000002a2194d2 size 0x4b00 pages 5
[ 6.815158] sof-audio-pci 0000:00:1f.3: period_bytes:0x12c0
[ 6.815161] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.815179] sof-audio-pci 0000:00:1f.3: stream_tag 1
[ 6.815194] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.815400] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.815412] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790604
[ 6.821799] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[ 6.821801] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.821802] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.821802] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.821887] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.821890] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[ 6.821892] sof-audio-pci 0000:00:1f.3: generating page table for 000000006e515b85 size 0x4b00 pages 5
[ 6.821915] sof-audio-pci 0000:00:1f.3: period_bytes:0x12c0
[ 6.821915] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.821924] sof-audio-pci 0000:00:1f.3: stream_tag 2
[ 6.821929] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.822235] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.822238] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790528
[ 6.825486] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 1
[ 6.825490] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.825679] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.825719] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[ 6.825876] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[ 6.825878] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.825879] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.825880] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.825968] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.825974] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[ 6.825976] sof-audio-pci 0000:00:1f.3: generating page table for 000000006e515b85 size 0x4b00 pages 5
[ 6.825999] sof-audio-pci 0000:00:1f.3: period_bytes:0x12c0
[ 6.825999] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.826010] sof-audio-pci 0000:00:1f.3: stream_tag 2
[ 6.826016] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.826159] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.826161] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790528
[ 6.826196] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 6.826198] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.826275] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.826296] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 6.826330] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 1
[ 6.826333] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.826451] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.826490] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[ 6.873914] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 6.873919] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.873922] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.873925] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.874195] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.874207] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[ 6.874212] sof-audio-pci 0000:00:1f.3: generating page table for 000000002a2194d2 size 0x4b00 pages 5
[ 6.874243] sof-audio-pci 0000:00:1f.3: period_bytes:0x12c0
[ 6.874245] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.874264] sof-audio-pci 0000:00:1f.3: stream_tag 1
[ 6.874279] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.874420] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.874422] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790604
[ 6.881192] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[ 6.881198] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.881201] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.881203] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.881479] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.881496] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[ 6.881505] sof-audio-pci 0000:00:1f.3: generating page table for 000000006e515b85 size 0x4b00 pages 5
[ 6.881539] sof-audio-pci 0000:00:1f.3: period_bytes:0x12c0
[ 6.881543] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.881564] sof-audio-pci 0000:00:1f.3: stream_tag 2
[ 6.881581] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.881791] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.881797] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790528
[ 6.884456] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 1
[ 6.884465] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.884629] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.884709] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[ 6.885097] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[ 6.885103] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.885107] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.885110] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.885370] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.885383] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[ 6.885390] sof-audio-pci 0000:00:1f.3: generating page table for 000000006e515b85 size 0x4b00 pages 5
[ 6.885430] sof-audio-pci 0000:00:1f.3: period_bytes:0x12c0
[ 6.885434] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.885455] sof-audio-pci 0000:00:1f.3: stream_tag 2
[ 6.885471] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.885635] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.885641] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790528
[ 6.885754] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 6.885761] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.885919] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.885997] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0
[ 6.886066] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 1
[ 6.886073] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.886228] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 6.886294] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[ 6.889004] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889167] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889169] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.889180] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889353] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889355] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.889366] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889537] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889539] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.889550] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889710] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889711] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.889721] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889890] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.889892] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.889902] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890064] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890065] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.890075] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890238] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890239] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.890249] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890417] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890419] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.890429] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890599] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.890601] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 6.933938] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[ 6.933944] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.933947] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.933949] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.934193] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.934205] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 0
[ 6.934211] sof-audio-pci 0000:00:1f.3: generating page table for 000000002a2194d2 size 0xffc0 pages 16
[ 6.934242] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 6.934244] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.934263] sof-audio-pci 0000:00:1f.3: stream_tag 1
[ 6.934278] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.934457] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.934463] sof-audio-pci 0000:00:1f.3: pcm: stream dir 0, posn mailbox offset is 790604
[ 6.940832] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941106] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941123] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941338] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941350] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941573] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941591] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941776] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.941791] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942003] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942016] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942183] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942196] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942372] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942388] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942564] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942578] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.942766] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.946829] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 1
[ 6.946835] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 6.946958] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 6.946961] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 6.947164] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[ 6.947165] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 6.947166] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 6.947167] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 6.947235] sof-audio-pci 0000:00:1f.3: format_val=49, rate=48000, ch=2, format=10
[ 6.947238] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[ 6.947240] sof-audio-pci 0000:00:1f.3: generating page table for 000000006e515b85 size 0xffc0 pages 16
[ 6.947256] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 6.947257] sof-audio-pci 0000:00:1f.3: periods:4
[ 6.947266] sof-audio-pci 0000:00:1f.3: stream_tag 2
[ 6.947270] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.947456] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[ 6.947459] sof-audio-pci 0000:00:1f.3: pcm: stream dir 1, posn mailbox offset is 790528
[ 6.948947] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 6.948965] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 6.950499] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.950664] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.950679] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.950792] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.950805] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.950993] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951007] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951169] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951182] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951346] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951361] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951528] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951542] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951708] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951721] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951962] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.951975] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.952144] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[ 6.955299] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 1
[ 6.955308] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 6.955449] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 6.955452] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=1
[ 7.449011] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 7.449029] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 7.639612] rfkill: input handler disabled
[ 7.827407] mce: CPU5: Core temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827408] mce: CPU1: Core temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827430] mce: CPU4: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827431] mce: CPU0: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827432] mce: CPU1: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827435] mce: CPU5: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827436] mce: CPU6: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827438] mce: CPU2: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827439] mce: CPU7: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827440] mce: CPU3: Package temperature above threshold, cpu clock throttled (total events = 1)
[ 7.827748] mce: CPU5: Core temperature/speed normal
[ 7.827749] mce: CPU1: Core temperature/speed normal
[ 7.827749] mce: CPU2: Package temperature/speed normal
[ 7.827750] mce: CPU4: Package temperature/speed normal
[ 7.827751] mce: CPU7: Package temperature/speed normal
[ 7.827752] mce: CPU3: Package temperature/speed normal
[ 7.827753] mce: CPU0: Package temperature/speed normal
[ 7.827754] mce: CPU6: Package temperature/speed normal
[ 7.827754] mce: CPU1: Package temperature/speed normal
[ 7.827755] mce: CPU5: Package temperature/speed normal
[ 7.948933] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[ 7.948954] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[ 11.965006] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 0
[ 11.965021] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 11.965215] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 11.965224] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[ 11.965261] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 1
[ 11.965266] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 11.965491] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 11.965607] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 1
[ 11.966910] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 0 dir 0 cmd 0
[ 11.966926] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 11.967057] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 11.967065] sof-audio-pci 0000:00:1f.3: In hda_link_pcm_trigger cmd=0
[ 11.967109] sof-audio-pci 0000:00:1f.3: pcm: free stream 0 dir 0
[ 11.967114] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 11.967246] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[ 11.967352] sof-audio-pci 0000:00:1f.3: pcm: close stream 0 dir 0

[juimonen]

@ranj063 pulseaudio is "probing" alsa to get all possible pcm format combination's that actually "work".

[ranj063]

@juimonen thanks. That explains the dmesg log but does it also set the kcontrol values during this probe?

[juimonen]

@ranj063 yes there's separate volume_probe... pulseaudio developers we're pretty pissed of many non-working alsa drivers reporting all kind of volume ranges etc. which don't make sense/work, so this kind of probing is a consequence of that. git clone the pulseaudio code and check alsa-mixer.c...

[juimonen]

@ranj063 I think you can actually turn the probing off from pulse config files, but I would suggest us fixing the issues as it is usually "on" and it is actually testing that the driver works with reasonable functionality.

[ranj063]

@lgirdwood @plbossart I spent some time tracking this bug and I have the cause but dont have a solution. So I could use some help.

What I found was that when a PCM stream is closed, the hdac codec runtime suspend callback gets called which is responsible for suspending the codec, the link and turning off display power (if applicable). After this is complete, the hdac codec decrements its parent device's child_count. This parent device is the SOF PCI device.

What happens in the logs shown below is that the PCM stream is closed, the sof device gets the pcm close ioctl followed by the hdac codec runtime suspend call. But before the hdac codec runtime suspend finishes, pulse audio sends the commands to get the volume kcontrol values. And so when the volume get IO completes and the SOF device's usage count hits 0, it tried to suspend and this is where we see the -EBUSY error. This is because the hdac audio device being a child of the SOF device is holding the child_count.

But this does no harm to the overall runtime PM or system suspend later on as the usage count for the SOF device is maintained and after the hdac codec decrements its parent's child_count (shown in bold at the end of the logs), things go back to normal.

[ 5.558235] ranjani: hdac_codec.c codec_suspend
[ 5.558237] snd-soc-dummy snd-soc-dummy: ranjani: returning value -13
[ 5.558239] ranjani: alc269suspend
[ 5.560027] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560269] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560272] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.560274] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.560275] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.560276] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.560297] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560513] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560515] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.560515] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.560516] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.560517] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.560530] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560706] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560707] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.560708] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.560708] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.560709] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.560717] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560882] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.560883] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.560884] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.560884] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.560885] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.560893] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561058] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561059] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.561060] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.561060] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.561061] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.561069] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561280] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561282] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.561283] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.561284] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.561284] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.561300] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561509] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561510] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.561511] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.561511] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.561512] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.561525] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561697] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561698] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.561699] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.561699] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.561700] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.561707] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561879] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50020000: GLB_COMP_MSG: GET_VALUE
[ 5.561879] sof-audio-pci 0000:00:1f.3: ranjani: in rpm_suspend
[ 5.561880] sof-audio-pci 0000:00:1f.3: ranjani: conditions are wrong -EBUSY
[ 5.561880] sof-audio-pci 0000:00:1f.3: ranjani: returning value -16
[ 5.561881] sof-audio-pci 0000:00:1f.3: error: volume get failed to idle -16
[ 5.571752] ranjani: hdac_codec.c codec_suspend finish
[ 5.571758] snd_hda_codec_realtek ehdaudio0D0: ranjani: hdac_codec_runtime_suspend finish
[ 5.571759] snd_hda_codec_realtek ehdaudio0D0: ranjani: decrementing parent
[ 5.571760] sof-audio-pci 0000:00:1f.3: ranjani: decrementing parent

[ranj063]

I found a "solution" to get rid of the errors:
If we avoid resuming (calling pm_runtime_get_sync) the DSP when it is already runtime active, then it will avoid the suspend call that happens before the hdac codec finishes suspending.

But, I also think that this error is harmless and it doesnt affect the runtime PM in the SOF driver. So, we could also replace the error message with a warning instead.

@plbossart @lgirdwood please let me know what you think