ASoC q6asm race condition when stopping and preparing the stream

Hi,

There seems to be a race condition in q6asm when stopping the stream (with uncompressed PCM). When receiving SNDRV_PCM_TRIGGER_STOP, the driver sets the state to Q6ASM_STREAM_STOPPED and sends CMD_EOS to the ADSP. If userspace decides to prepare the stream again in q6asm_dai_prepare before receiving ASM_CLIENT_EVENT_CMD_EOS_DONE, the memory-mapped region appears to still be in use and fails to map again.

I believe this race was observed since commit 81c53b52de21 ("ASoC: qcom:
qdsp6: q6asm-dai: set 10 ms period and buffer alignment."), but would need to verify. On sdm670, we are coping downstream by keeping the state as Q6ASM_STREAM_RUNNING until receiving CMD_EOS_DONE.

Can the ADSP emit DATA_WRITE_DONE or DATA_READ_DONE before CMD_EOS_DONE? We might need an extra stopping state between CMD_EOS and CMD_EOS_DONE so the driver doesn't request more data transfers.

Quoted 9 lines · Richard Acayan

Hi,

There seems to be a race condition in q6asm when stopping the stream (with uncompressed PCM). When receiving SNDRV_PCM_TRIGGER_STOP, the driver sets the state to Q6ASM_STREAM_STOPPED and sends CMD_EOS to the ADSP. If userspace decides to prepare the stream again in q6asm_dai_prepare before receiving ASM_CLIENT_EVENT_CMD_EOS_DONE, the memory-mapped region appears to still be in use and fails to map again.

Quoted 4 lines

I believe this race was observed since commit 81c53b52de21 ("ASoC: qcom:
qdsp6: q6asm-dai: set 10 ms period and buffer alignment."), but would need to verify. On sdm670, we are coping downstream by keeping the state as Q6ASM_STREAM_RUNNING until receiving CMD_EOS_DONE.

Do you have a reproducer or specific steps to test/reproduce the issue?

Quoted 10 lines · Alexey Klimov

Quoted 9 lines · Richard Acayan

Hi,

There seems to be a race condition in q6asm when stopping the stream (with uncompressed PCM). When receiving SNDRV_PCM_TRIGGER_STOP, the driver sets the state to Q6ASM_STREAM_STOPPED and sends CMD_EOS to the ADSP. If userspace decides to prepare the stream again in q6asm_dai_prepare before receiving ASM_CLIENT_EVENT_CMD_EOS_DONE, the memory-mapped region appears to still be in use and fails to map again.

Quoted 4 lines

Quoted 4 lines

I believe this race was observed since commit 81c53b52de21 ("ASoC: qcom:
qdsp6: q6asm-dai: set 10 ms period and buffer alignment."), but would need to verify. On sdm670, we are coping downstream by keeping the state as Q6ASM_STREAM_RUNNING until receiving CMD_EOS_DONE.

Quoted 1 line

Do you have a reproducer or specific steps to test/reproduce the issue?

I don't really have an easy way to reproduce. On a device with a Qualcomm SoC and q6asm, running postmarketOS with Phosh and without the workaround, waiting a few hours usually reproduces it.

Hi,

Quoted 11 lines · Richard Acayan

Quoted 10 lines · Alexey Klimov

Quoted 9 lines · Richard Acayan

Hi,

There seems to be a race condition in q6asm when stopping the stream (with uncompressed PCM). When receiving SNDRV_PCM_TRIGGER_STOP, the driver sets the state to Q6ASM_STREAM_STOPPED and sends CMD_EOS to the ADSP. If userspace decides to prepare the stream again in q6asm_dai_prepare before receiving ASM_CLIENT_EVENT_CMD_EOS_DONE, the memory-mapped region appears to still be in use and fails to map again.

Quoted 6 lines

Quoted 6 lines

Quoted 6 lines

I believe this race was observed since commit 81c53b52de21 ("ASoC:
qcom:
qdsp6: q6asm-dai: set 10 ms period and buffer alignment."), but would need to verify. On sdm670, we are coping downstream by keeping the state
as Q6ASM_STREAM_RUNNING until receiving CMD_EOS_DONE.

Are we sure that's only a workaround and not the correct solution? Thank you for mentioning it, in any case!

Quoted 4 lines

Quoted 1 line

Do you have a reproducer or specific steps to test/reproduce the issue?

I don't really have an easy way to reproduce. On a device with a Qualcomm SoC and q6asm, running postmarketOS with Phosh and without the workaround, waiting a few hours usually reproduces it.

I haven't seen this happen "randomly".. at least not with PulseAudio, but after switching to PipeWire and properly configuring phone calls(*) on my phone (sm7325-motorola-dubai) I have encountered what I think is the exact same issue many times while doing this simple sequence:

- boot phone, playback and recording work fine
- start a phone call, cancel when hearing dial tone (Wireplumber has switched UCM profile to VoiceCall and then back to HiFi)
- try to record mic sound (using the GNOME sound recorder app or whatever else)

Actually just now I managed to hit this right after reboot, without any calls..!

So it might just be "try to record audio through PipeWire and you'll hit it quickly enough".

(*) using the current infamous q6voice patchset, Wireplumber's script to switch between HiFi/VoiceCall, and a better setup for starting the dummy streams exposed by q6voice: https://gitlab.postmarketos.org/
postmarketOS/q6voiced/-/work_items/3#note_553107

The log is usually something like this:

kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais:
Buffer already allocated
kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais: cmd = 0x10db4 returned error = 0x9
kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais: DSP returned error[9]

pipewire[5347]: [E][02:30:35.781627] spa.alsa     | [ alsa-pcm.c: 2722 do_prepare()] hw:Motoroladubai,2c: snd_pcm_prepare error: Invalid argument pipewire[5347]: [W][02:30:35.781714] spa.alsa     | [ alsa-pcm.c: 2885 get_avail()] hw:Motoroladubai,2c: (0 suppressed) snd_pcm_avail after
recover: File desc>
pipewire[5347]: [E][02:30:35.781771] spa.alsa     | [ alsa-pcm.c: 2832 alsa_recover()] hw:Motoroladubai,2c: recover from error state SETUP pipewire[5347]: [E][02:30:35.781801] spa.alsa     | [ alsa-pcm.c: 2722 do_prepare()] hw:Motoroladubai,2c: snd_pcm_prepare error: Invalid argument pipewire[5347]: [E][02:30:35.781821] spa.alsa     | [ alsa-pcm.c: 2832 alsa_recover()] hw:Motoroladubai,2c: recover from error state SETUP pipewire[5347]: [E][02:30:35.781837] spa.alsa     | [ alsa-pcm.c: 2722 do_prepare()] hw:Motoroladubai,2c: snd_pcm_prepare error: Invalid argument pipewire[5347]: [E][02:30:35.786869] spa.alsa     | [ alsa-pcm.c: 2832 alsa_recover()] hw:Motoroladubai,2c: recover from error state SETUP pipewire[5347]: [E][02:30:35.786949] spa.alsa     | [ alsa-pcm.c: 2722 do_prepare()] hw:Motoroladubai,2c: snd_pcm_prepare error: Invalid argument
kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais:
q6asm_dai_prepare: q6asm_open_write failed
kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais: ASoC error (-22): at snd_soc_pcm_component_prepare() on 3700000.remoteproc:glink-edge:apr:servi>
kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais:
q6asm_dai_prepare: private data null or audio client freed
kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais: ASoC error (-22): at snd_soc_pcm_component_prepare() on 3700000.remoteproc:glink-edge:apr:servi>
kernel: q6asm-dai 3700000.remoteproc:glink-edge:apr:service@7:dais:
q6asm_dai_prepare: private data null or audio client freed
…

"Buffer already allocated", error 9 which is ADSP_EALREADY, so the state is desynchronized.

Thanks,
~val

Quoted 9 lines · Richard Acayan

Hi,

There seems to be a race condition in q6asm when stopping the stream (with uncompressed PCM). When receiving SNDRV_PCM_TRIGGER_STOP, the driver sets the state to Q6ASM_STREAM_STOPPED and sends CMD_EOS to the ADSP. If userspace decides to prepare the stream again in q6asm_dai_prepare before receiving ASM_CLIENT_EVENT_CMD_EOS_DONE, the memory-mapped region appears to still be in use and fails to map again.

Quoted 4 lines

I believe this race was observed since commit 81c53b52de21 ("ASoC: qcom:
qdsp6: q6asm-dai: set 10 ms period and buffer alignment."), but would need to verify. On sdm670, we are coping downstream by keeping the state as Q6ASM_STREAM_RUNNING until receiving CMD_EOS_DONE.

Do you have a reproducer or specific steps to test/reproduce the issue?

Quoted 4 lines

Can the ADSP emit DATA_WRITE_DONE or DATA_READ_DONE before CMD_EOS_DONE? We might need an extra stopping state between CMD_EOS and CMD_EOS_DONE so the driver doesn't request more data transfers.

Thanks,
Alexey

Hi,

There seems to be a race condition in q6asm when stopping the stream (with uncompressed PCM). When receiving SNDRV_PCM_TRIGGER_STOP, the driver sets the state to Q6ASM_STREAM_STOPPED and sends CMD_EOS to the ADSP. If userspace decides to prepare the stream again in q6asm_dai_prepare before receiving ASM_CLIENT_EVENT_CMD_EOS_DONE, the memory-mapped region appears to still be in use and fails to map again.

I believe this race was observed since commit 81c53b52de21 ("ASoC: qcom:
qdsp6: q6asm-dai: set 10 ms period and buffer alignment."), but would need to verify. On sdm670, we are coping downstream by keeping the state as Q6ASM_STREAM_RUNNING until receiving CMD_EOS_DONE.

Can the ADSP emit DATA_WRITE_DONE or DATA_READ_DONE before CMD_EOS_DONE? We might need an extra stopping state between CMD_EOS and CMD_EOS_DONE so the driver doesn't request more data transfers.