Re: [Sound-open-firmware] ASoC: SOF: Race condition in ipc.c

From: noman pouigt
Date: Wed Jun 22 2022 - 16:47:57 EST

Next message: Christoph Böhmwalder: "[PATCH] drbd: bm_page_async_io: fix spurious bitmap "IO error" on large volumes"
Previous message: Rodrigo Vivi: "Re: [Intel-gfx] i915: crash with 5.19-rc2"
In reply to: Pierre-Louis Bossart: "Re: [Sound-open-firmware] ASoC: SOF: Race condition in ipc.c"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Tue, Jun 21, 2022 at 6:38 AM Pierre-Louis Bossart
<pierre-louis.bossart@xxxxxxxxxxxxxxx> wrote:
>
>
>
> On 6/20/22 21:46, noman pouigt wrote:
> > Folks,
> >
> > I have borrowed part of SOF architecture for my own DSP
> > framework development as the memory on the DSP is
> > extremely small and wouldn't be able to support SOF.
>
> You're providing very little context here. Of course it's open-source
> and you can do whatever you want with the code, but it's not clear if
> the 'borrowed' code can deal with your specific case.

I have borrowed the entire SOF ipc communication architecture however
I have tweaked it a bit to suit my needs.

>
> > Currently I am running into a race condition as below:
> >
> > CPU DSP
> > PCM_TRIGGER_START
> > sof_ipc_send_msg ---->
> >
> > <------Immediate ACK
> > ipc3_wait_tx_done
> > (wait_event_timeout)
> > <------ POSITION update
> >
> > snd_pcm_period_elapsed
> >
> >
> > As you can see TRIGGER_START didn't even finish
> > and waiting for it to complete in ipc3_wait_tx_done
> > function. However, before it could complete the position
> > interrupt was issued which results in calling period_elapsed
> > function.
> >
> > In order to fix this I assume below is called in SOF framework:
> > schedule_work(&spcm->stream[substream->stream].period_elapsed_work);
> >
> > How is this design working? If the interrupt is coming too fast
> > from the DSP than the associated function with this schedule_work
> > will not get called as the scheduler will not get time to schedule the
> > workqueue and elapsed function will not be called thereby not increasing
> > the hw_ptr. How is the flow control for data transfer achieved?
>
> The schedule_work was added by this commit, and the explanations are
> rather straightforward:
>
> commit e2803e610aecb36ea4fec5a04861547664580d0c
>
> Author: Keyon Jie <yang.jie@xxxxxxxxxxxxxxx>
>
> Date: Tue Apr 30 18:09:25 2019 -0500
>
>
>
>
> ASoC: SOF: PCM: add period_elapsed work to fix race condition in
> interrupt context
>
> "
> The IPC implementation in SOF requires sending IPCs serially: we should
> not send a new IPC command to the firmware before we get an ACK (or time
> out) from firmware, and the IRQ processing is complete.
>
> snd_pcm_period_elapsed() can be called in interrupt context before
> IRQ_HANDLED is returned. When the PCM is done draining, a STOP
> IPC will then be sent, which breaks the expectation that IPCs are
> handled serially and leads to IPC timeouts.
>
> This patch adds a workqueue to defer the call to snd_pcm_elapsed() after
> the IRQ is handled.
> "
>
> I am not sure what the problem you have really is.

I am using QEMU to develop the playback driver and the design( borrowed
from SOF with some tweaks) as below:

1. In PCM_PARAMS, number of period and period size information is shared
with DSP.
2. TRIGGER (in SOF every IPC requires an ack but for this command DSP
doesn't send ack) is sent by the CPU to DSP to start playback. I am not calling
wait_event_timeout for this command from the CPU side.
3. Whenever DSP is done with a period it sends an interrupt.
4. CPU calls the elapsed function whenever an interrupt is received
and this repeats.

With the above design things are running smoothly but sometimes I am
running into
an UNDERRUN issue. Complete logs copied at the end of the mail.
Questions:
a. Do I just need to play with different period sizes to get this right?
b. What I have noticed is below when the issue happens.

[ 505.493600][ T123] sdev_dev sdev_dev: ipc tx: 0x60040000:
GLB_STREAM_MSG: TRIG_START
[ 505.493961][ T100] sdev_dev sdev_dev: ipc rx: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.494228][ T100] event_handler irq_pos 12000
[ 505.494541][ T123] sdev_dev sdev_dev: ipc tx succeeded:
0x60040000: GLB_STREAM_MSG: TRIG_START

"event_handler irq_pos" if this line (it calls elapsed function) comes
before trig_start succeeds
as shown above then the UNDERRUN issue happens otherwise not.

c. Is there any relation to the above sequence of logs to the underrun issue?

>
> It's not really surprising that the first period is consumed
> immediately, the flow will become more steady-state afterwards.
>
> The DMAs should be primed to deal with more than one period, and the
> schedule_work() will only signal that the application can refill the
> ring buffer. There's all kinds of delays that will happen depending on
> load and scheduling, and if the POSITION_UPDATE was received immediately
> then there's should be still plenty of time to provide a new buffer.
>
> >
> > I am facing the above problem in my design.
> >
> > I am wondering if I can simply add one more IPC command(don't call
> > wait_event_interruptible for this) after TRIGGER_START to start the
> > streaming.This way schedule_work for updating period_elapsed function
> > can be avoided and it can be called in an interrupt context.
>
> See commit above, this won't work because you'll be sending an IPC while
> dealing with an IPC.
Understood but as explained above for the trigger command there is no reply.

stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 1
rate : 48000
exact rate : 48000 (48000/1)
msbits : 16
buffer_size : 24000
period_size : 6000
period_time : 125000
tstamp_mode : NONE
tstamp_type : MONOTONIC
period_step : 1
avail_min : 6000
period_event : 0
start_threshold : 24000
stop_threshold : 24000
silence_threshold: 0
silence_size : 0
boundary : 6755399441055744000
appl_ptr : 0
hw_ptr : 0
[ 505.489005][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 0
[ 505.489361][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 6000
[ 505.489635][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 6000
[ 505.490172][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 6000
[ 505.490592][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 12000
[ 505.490868][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 12000
[ 505.491464][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 12000
[ 505.491777][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 18000
[ 505.492053][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 18000
[ 505.492652][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 18000
[ 505.492965][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 24000
[ 505.493242][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 24000
[ 505.493600][ T123] sdev_dev sdev_dev: ipc tx: 0x60040000:
GLB_STREAM_MSG: TRIG_START
[ 505.493961][ T100] sdev_dev sdev_dev: ipc rx: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.494228][ T100] event_handler irq_pos 12000
[ 505.494541][ T123] sdev_dev sdev_dev: ipc tx succeeded:
0x60040000: GLB_STREAM_MSG: TRIG_START
[ 505.494844][ T123] snd_pcm_playback_avail hw_ptr 0 buffer_size
24000 appl_ptr 24000
[ 505.495173][ T100] sof_pcm_pointer 346 moving by 6000
[ 505.495479][ T100] IRQ: pos=6000, old=0, base=0, period=6000, buf=24000
[ 505.495519][ T100] snd_pcm_playback_avail hw_ptr 6000 buffer_size
24000 appl_ptr 24000
[ 505.496020][ T100] sdev_dev sdev_dev: ipc rx done: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.496481][ T100] sdev_dev sdev_dev: ipc rx: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.496748][ T100] event_handler irq_pos 24000
[ 505.496934][ T100] sof_pcm_pointer 346 moving by 12000
[ 505.497147][ T100] IRQ: pos=12000, old=6000, base=0, period=6000, buf=24000
[ 505.497188][ T100] snd_pcm_playback_avail hw_ptr 12000 buffer_size
24000 appl_ptr 24000
[ 505.497754][ T100] sdev_dev sdev_dev: ipc rx done: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.498170][ T100] sdev_dev sdev_dev: ipc rx: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.498522][ T100] event_handler irq_pos 36000
[ 505.498707][ T100] sof_pcm_pointer 346 moving by 18000
[ 505.498921][ T100] IRQ: pos=18000, old=12000, base=0, period=6000, buf=24000
[ 505.498961][ T100] snd_pcm_playback_avail hw_ptr 18000 buffer_size
24000 appl_ptr 24000
[ 505.499522][ T100] sdev_dev sdev_dev: ipc rx done: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.499937][ T100] sdev_dev sdev_dev: ipc rx: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.500204][ T100] event_handler irq_pos 0
[ 505.500432][ T100] sof_pcm_pointer 346 moving by 0
[ 505.500637][ T100] IRQ: pos=0, old=18000, base=0, period=6000, buf=24000
[ 505.500678][ T100] snd_pcm_playback_avail hw_ptr 24000 buffer_size
24000 appl_ptr 24000
[ 505.501547][ T100] sdev_dev sdev_dev: ipc tx: 0x60050000:
GLB_STREAM_MSG: TRIG_STOP
[ 505.501840][ T100] sdev_dev sdev_dev: ipc tx succeeded:
0x60050000: GLB_STREAM_MSG: TRIG_STOP
[ 505.502161][ T100] sdev_dev sdev_dev: ipc rx done: 0x600a0000:
GLB_STREAM_MSG: POSITION
[ 505.502822][ T123] snd_pcm_playback_avail hw_ptr 24000 buffer_size
24000 appl_ptr 24000
underrun!!! (at least 0.972 ms long)
Status:
state : XRUN
trigger_time: 505.482872
tstamp : 0.000000
delay : 0
avail : 24000
avail_max : 24000

Next message: Christoph Böhmwalder: "[PATCH] drbd: bm_page_async_io: fix spurious bitmap "IO error" on large volumes"
Previous message: Rodrigo Vivi: "Re: [Intel-gfx] i915: crash with 5.19-rc2"
In reply to: Pierre-Louis Bossart: "Re: [Sound-open-firmware] ASoC: SOF: Race condition in ipc.c"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]