[PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
enables tx-complete interrupt.
however if the interrupt is executed after `get_a_tx_buf` and before
`rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
for the full 15 seconds.

in this case, so we re-try once before we really start to sleep

Signed-off-by: Tim Blechmann <tim@klingt.org>
---
 drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
 1 file changed, 15 insertions(+), 9 deletions(-)

diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
index 905ac7910c98..2a9d42225e60 100644
--- a/drivers/rpmsg/virtio_rpmsg_bus.c
+++ b/drivers/rpmsg/virtio_rpmsg_bus.c
@@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
 
 	/* no free buffer ? wait for one (but bail after 15 seconds) */
 	while (!msg) {
 		/* enable "tx-complete" interrupts, if not already enabled */
 		rpmsg_upref_sleepers(vrp);
 
-		/*
-		 * sleep until a free buffer is available or 15 secs elapse.
-		 * the timeout period is not configurable because there's
-		 * little point in asking drivers to specify that.
-		 * if later this happens to be required, it'd be easy to add.
-		 */
-		err = wait_event_interruptible_timeout(vrp->sendq,
-					(msg = get_a_tx_buf(vrp)),
-					msecs_to_jiffies(15000));
+		/* make sure to retry to grab tx buffer before we start waiting */
+		msg = get_a_tx_buf(vrp);
+		if (msg) {
+			err = 0;
+		} else {
+			/*
+			 * sleep until a free buffer is available or 15 secs elapse.
+			 * the timeout period is not configurable because there's
+			 * little point in asking drivers to specify that.
+			 * if later this happens to be required, it'd be easy to add.
+			 */
+			err = wait_event_interruptible_timeout(vrp->sendq,
+						(msg = get_a_tx_buf(vrp)),
+						msecs_to_jiffies(15000));
+		}
 
 		/* disable "tx-complete" interrupts if we're the last sleeper */
 		rpmsg_downref_sleepers(vrp);
 
 		/* timeout ? */
 		if (!err) {
-- 
2.34.1

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Arnaud POULIQUEN]

Hello Tim,

On 9/4/23 10:36, Tim Blechmann wrote:
> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
> enables tx-complete interrupt.
> however if the interrupt is executed after `get_a_tx_buf` and before
> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
> for the full 15 seconds.


Is there any reason why your co-processor is unable to release the TX RPMSG
buffers for 15 seconds? If not, you should first determine the reason why it is
stalled.

Regards,
Arnaud

> 
> in this case, so we re-try once before we really start to sleep
> 
> Signed-off-by: Tim Blechmann <tim@klingt.org>
> ---
>  drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
>  1 file changed, 15 insertions(+), 9 deletions(-)
> 
> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
> index 905ac7910c98..2a9d42225e60 100644
> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
>  
>  	/* no free buffer ? wait for one (but bail after 15 seconds) */
>  	while (!msg) {
>  		/* enable "tx-complete" interrupts, if not already enabled */
>  		rpmsg_upref_sleepers(vrp);
>  
> -		/*
> -		 * sleep until a free buffer is available or 15 secs elapse.
> -		 * the timeout period is not configurable because there's
> -		 * little point in asking drivers to specify that.
> -		 * if later this happens to be required, it'd be easy to add.
> -		 */
> -		err = wait_event_interruptible_timeout(vrp->sendq,
> -					(msg = get_a_tx_buf(vrp)),
> -					msecs_to_jiffies(15000));
> +		/* make sure to retry to grab tx buffer before we start waiting */
> +		msg = get_a_tx_buf(vrp);
> +		if (msg) {
> +			err = 0;
> +		} else {
> +			/*
> +			 * sleep until a free buffer is available or 15 secs elapse.
> +			 * the timeout period is not configurable because there's
> +			 * little point in asking drivers to specify that.
> +			 * if later this happens to be required, it'd be easy to add.
> +			 */
> +			err = wait_event_interruptible_timeout(vrp->sendq,
> +						(msg = get_a_tx_buf(vrp)),
> +						msecs_to_jiffies(15000));
> +		}
>  
>  		/* disable "tx-complete" interrupts if we're the last sleeper */
>  		rpmsg_downref_sleepers(vrp);
>  
>  		/* timeout ? */
>  		if (!err) {

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Mathieu Poirier]

On Mon, Sep 04, 2023 at 03:52:56PM +0200, Arnaud POULIQUEN wrote:
> Hello Tim,
> 
> On 9/4/23 10:36, Tim Blechmann wrote:
> > when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
> > enables tx-complete interrupt.
> > however if the interrupt is executed after `get_a_tx_buf` and before
> > `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
> > for the full 15 seconds.
> 
> 
> Is there any reason why your co-processor is unable to release the TX RPMSG
> buffers for 15 seconds? If not, you should first determine the reason why it is
> stalled.

Arnaud's concern is valid.  If the remote processor can't consume a buffer
within 15 seconds, something is probably wrong.

That said, I believe your assesment of the situation is correct.  *If* the TX
callback is disabled and there is no buffer available, there is a window of
opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
interrupt to arrive in function rpmsg_send_offchannel_raw().  

From here three things need to happen:

1) You send another version of this patch with a changelong that uses proper
english, i.e capital letters when they are needed and no spelling mistake.

2) Arnaud confirms our suspicions.

3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
soak.  No error are locks are reported due to this patch during that time. 

> 
> Regards,
> Arnaud
> 
> > 
> > in this case, so we re-try once before we really start to sleep
> > 
> > Signed-off-by: Tim Blechmann <tim@klingt.org>
> > ---
> >  drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
> >  1 file changed, 15 insertions(+), 9 deletions(-)
> > 
> > diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
> > index 905ac7910c98..2a9d42225e60 100644
> > --- a/drivers/rpmsg/virtio_rpmsg_bus.c
> > +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
> > @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
> >  
> >  	/* no free buffer ? wait for one (but bail after 15 seconds) */
> >  	while (!msg) {
> >  		/* enable "tx-complete" interrupts, if not already enabled */
> >  		rpmsg_upref_sleepers(vrp);
> >  
> > -		/*
> > -		 * sleep until a free buffer is available or 15 secs elapse.
> > -		 * the timeout period is not configurable because there's
> > -		 * little point in asking drivers to specify that.
> > -		 * if later this happens to be required, it'd be easy to add.
> > -		 */
> > -		err = wait_event_interruptible_timeout(vrp->sendq,
> > -					(msg = get_a_tx_buf(vrp)),
> > -					msecs_to_jiffies(15000));
> > +		/* make sure to retry to grab tx buffer before we start waiting */
> > +		msg = get_a_tx_buf(vrp);
> > +		if (msg) {
> > +			err = 0;
> > +		} else {
> > +			/*
> > +			 * sleep until a free buffer is available or 15 secs elapse.
> > +			 * the timeout period is not configurable because there's
> > +			 * little point in asking drivers to specify that.
> > +			 * if later this happens to be required, it'd be easy to add.
> > +			 */
> > +			err = wait_event_interruptible_timeout(vrp->sendq,
> > +						(msg = get_a_tx_buf(vrp)),
> > +						msecs_to_jiffies(15000));
> > +		}
> >  
> >  		/* disable "tx-complete" interrupts if we're the last sleeper */
> >  		rpmsg_downref_sleepers(vrp);
> >  
> >  		/* timeout ? */
> >  		if (!err) {

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

>>> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
>>> enables tx-complete interrupt.
>>> however if the interrupt is executed after `get_a_tx_buf` and before
>>> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
>>> for the full 15 seconds.
>>
>>
>> Is there any reason why your co-processor is unable to release the TX RPMSG
>> buffers for 15 seconds? If not, you should first determine the reason why it is
>> stalled.
> 
> Arnaud's concern is valid.  If the remote processor can't consume a buffer
> within 15 seconds, something is probably wrong.
> 
> That said, I believe your assesment of the situation is correct.  *If* the TX
> callback is disabled and there is no buffer available, there is a window of
> opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
> interrupt to arrive in function rpmsg_send_offchannel_raw().

the remote processor certainly releases the tx buffer and according to 
my tracing the `vring_interrupt` fires immediately before `rpmsg_send` 
enters the `rpmsg_upref_sleepers`.

after applying this patch we haven't been able to reproduce the 15s 
timeout anymore, whereas before we could easily reproduce it with 
certain workloads.

> 3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
> soak.  No error are locks are reported due to this patch during that time.

mentioning locks: i was a bit uncertain about a good way to implement 
the retry, since both `rpmsg_upref_sleepers` and `get_a_tx_buf` both 
acquire the same mutex. i briefly considered to add `get_a_tx_buf` into 
`rpmsg_upref_sleepers` to avoid locking the same mutex multiple times, 
though it adds a bit of complexity to the implementation and harms 
readability a bit.
are there any recommendations on this topic or are (likely 
non-contended) locks not expensive enough to justify the added complexity?

thanks,
tim


> 
>>
>> Regards,
>> Arnaud
>>
>>>
>>> in this case, so we re-try once before we really start to sleep
>>>
>>> Signed-off-by: Tim Blechmann <tim@klingt.org>
>>> ---
>>>   drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
>>>   1 file changed, 15 insertions(+), 9 deletions(-)
>>>
>>> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
>>> index 905ac7910c98..2a9d42225e60 100644
>>> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
>>> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
>>> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
>>>   
>>>   	/* no free buffer ? wait for one (but bail after 15 seconds) */
>>>   	while (!msg) {
>>>   		/* enable "tx-complete" interrupts, if not already enabled */
>>>   		rpmsg_upref_sleepers(vrp);
>>>   
>>> -		/*
>>> -		 * sleep until a free buffer is available or 15 secs elapse.
>>> -		 * the timeout period is not configurable because there's
>>> -		 * little point in asking drivers to specify that.
>>> -		 * if later this happens to be required, it'd be easy to add.
>>> -		 */
>>> -		err = wait_event_interruptible_timeout(vrp->sendq,
>>> -					(msg = get_a_tx_buf(vrp)),
>>> -					msecs_to_jiffies(15000));
>>> +		/* make sure to retry to grab tx buffer before we start waiting */
>>> +		msg = get_a_tx_buf(vrp);
>>> +		if (msg) {
>>> +			err = 0;
>>> +		} else {
>>> +			/*
>>> +			 * sleep until a free buffer is available or 15 secs elapse.
>>> +			 * the timeout period is not configurable because there's
>>> +			 * little point in asking drivers to specify that.
>>> +			 * if later this happens to be required, it'd be easy to add.
>>> +			 */
>>> +			err = wait_event_interruptible_timeout(vrp->sendq,
>>> +						(msg = get_a_tx_buf(vrp)),
>>> +						msecs_to_jiffies(15000));
>>> +		}
>>>   
>>>   		/* disable "tx-complete" interrupts if we're the last sleeper */
>>>   		rpmsg_downref_sleepers(vrp);
>>>   
>>>   		/* timeout ? */
>>>   		if (!err) {
> 

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Mathieu Poirier]

On Mon, 4 Sept 2023 at 19:33, Tim Blechmann <tim@klingt.org> wrote:
>
> >>> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
> >>> enables tx-complete interrupt.
> >>> however if the interrupt is executed after `get_a_tx_buf` and before
> >>> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
> >>> for the full 15 seconds.
> >>
> >>
> >> Is there any reason why your co-processor is unable to release the TX RPMSG
> >> buffers for 15 seconds? If not, you should first determine the reason why it is
> >> stalled.
> >
> > Arnaud's concern is valid.  If the remote processor can't consume a buffer
> > within 15 seconds, something is probably wrong.
> >
> > That said, I believe your assesment of the situation is correct.  *If* the TX
> > callback is disabled and there is no buffer available, there is a window of
> > opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
> > interrupt to arrive in function rpmsg_send_offchannel_raw().
>
> the remote processor certainly releases the tx buffer and according to
> my tracing the `vring_interrupt` fires immediately before `rpmsg_send`
> enters the `rpmsg_upref_sleepers`.
>
> after applying this patch we haven't been able to reproduce the 15s
> timeout anymore, whereas before we could easily reproduce it with
> certain workloads.
>
> > 3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
> > soak.  No error are locks are reported due to this patch during that time.
>
> mentioning locks: i was a bit uncertain about a good way to implement
> the retry, since both `rpmsg_upref_sleepers` and `get_a_tx_buf` both
> acquire the same mutex. i briefly considered to add `get_a_tx_buf` into
> `rpmsg_upref_sleepers` to avoid locking the same mutex multiple times,
> though it adds a bit of complexity to the implementation and harms
> readability a bit.

The current implementation looks good to me.

> are there any recommendations on this topic or are (likely
> non-contended) locks not expensive enough to justify the added complexity?
>

Since we are changing how buffers are delivered to applications in a
highly concurrent environment, it is possible for this patch to
introduce unintended side effects, something I want to avoid as much
as possible.

I am not worried about contentions for the vrp->tx_lock.

> thanks,
> tim
>
>
> >
> >>
> >> Regards,
> >> Arnaud
> >>
> >>>
> >>> in this case, so we re-try once before we really start to sleep
> >>>
> >>> Signed-off-by: Tim Blechmann <tim@klingt.org>
> >>> ---
> >>>   drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
> >>>   1 file changed, 15 insertions(+), 9 deletions(-)
> >>>
> >>> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
> >>> index 905ac7910c98..2a9d42225e60 100644
> >>> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
> >>> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
> >>> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
> >>>
> >>>     /* no free buffer ? wait for one (but bail after 15 seconds) */
> >>>     while (!msg) {
> >>>             /* enable "tx-complete" interrupts, if not already enabled */
> >>>             rpmsg_upref_sleepers(vrp);
> >>>
> >>> -           /*
> >>> -            * sleep until a free buffer is available or 15 secs elapse.
> >>> -            * the timeout period is not configurable because there's
> >>> -            * little point in asking drivers to specify that.
> >>> -            * if later this happens to be required, it'd be easy to add.
> >>> -            */
> >>> -           err = wait_event_interruptible_timeout(vrp->sendq,
> >>> -                                   (msg = get_a_tx_buf(vrp)),
> >>> -                                   msecs_to_jiffies(15000));
> >>> +           /* make sure to retry to grab tx buffer before we start waiting */
> >>> +           msg = get_a_tx_buf(vrp);
> >>> +           if (msg) {
> >>> +                   err = 0;
> >>> +           } else {
> >>> +                   /*
> >>> +                    * sleep until a free buffer is available or 15 secs elapse.
> >>> +                    * the timeout period is not configurable because there's
> >>> +                    * little point in asking drivers to specify that.
> >>> +                    * if later this happens to be required, it'd be easy to add.
> >>> +                    */
> >>> +                   err = wait_event_interruptible_timeout(vrp->sendq,
> >>> +                                           (msg = get_a_tx_buf(vrp)),
> >>> +                                           msecs_to_jiffies(15000));
> >>> +           }
> >>>
> >>>             /* disable "tx-complete" interrupts if we're the last sleeper */
> >>>             rpmsg_downref_sleepers(vrp);
> >>>
> >>>             /* timeout ? */
> >>>             if (!err) {
> >
>

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Arnaud POULIQUEN]

On 9/5/23 03:33, Tim Blechmann wrote:
>>>> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
>>>> enables tx-complete interrupt.
>>>> however if the interrupt is executed after `get_a_tx_buf` and before
>>>> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
>>>> for the full 15 seconds.
>>>
>>>
>>> Is there any reason why your co-processor is unable to release the TX RPMSG
>>> buffers for 15 seconds? If not, you should first determine the reason why it is
>>> stalled.
>>
>> Arnaud's concern is valid.  If the remote processor can't consume a buffer
>> within 15 seconds, something is probably wrong.
>>
>> That said, I believe your assesment of the situation is correct.  *If* the TX
>> callback is disabled and there is no buffer available, there is a window of
>> opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
>> interrupt to arrive in function rpmsg_send_offchannel_raw().
> 
> the remote processor certainly releases the tx buffer and according to my
> tracing the `vring_interrupt` fires immediately before `rpmsg_send` enters the
> `rpmsg_upref_sleepers`.


If I well understood your point, the issue occur in following race condition

- all the Tx buffers are used
- in rpmsg_send_offchannel_raw() function, we try to get a buffer using
get_a_tx_buf(vrp) that returns NULL
- rpmsg_xmit_done is called as a Tx buffer is released by the remote processor
  and now free
- in rpmsg_send_offchannel_raw() rpmsg_upref_sleepers is called

At this point you are nothing happen until 15 second because rpmsg_xmit_done is
never called  again that would wake up the waitqueue to call get_a_tx_buf()

I'm right?

If yes what is not clear to me is that wait_event_interruptible_timeout() seems
to test the condition (so call get_a_tx_buf()) before entering in sleep[1]. A
free TX buffer should be found at this step.

[1]https://elixir.bootlin.com/linux/latest/source/include/linux/wait.h#L534

Regards,
Arnaud

> 
> after applying this patch we haven't been able to reproduce the 15s timeout
> anymore, whereas before we could easily reproduce it with certain workloads.
> 
>> 3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
>> soak.  No error are locks are reported due to this patch during that time.
> 
> mentioning locks: i was a bit uncertain about a good way to implement the retry,
> since both `rpmsg_upref_sleepers` and `get_a_tx_buf` both acquire the same
> mutex. i briefly considered to add `get_a_tx_buf` into `rpmsg_upref_sleepers` to
> avoid locking the same mutex multiple times, though it adds a bit of complexity
> to the implementation and harms readability a bit.
> are there any recommendations on this topic or are (likely non-contended) locks
> not expensive enough to justify the added complexity?
> 
> thanks,
> tim
> 
> 
>>
>>>
>>> Regards,
>>> Arnaud
>>>
>>>>
>>>> in this case, so we re-try once before we really start to sleep
>>>>
>>>> Signed-off-by: Tim Blechmann <tim@klingt.org>
>>>> ---
>>>>   drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
>>>>   1 file changed, 15 insertions(+), 9 deletions(-)
>>>>
>>>> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c
>>>> b/drivers/rpmsg/virtio_rpmsg_bus.c
>>>> index 905ac7910c98..2a9d42225e60 100644
>>>> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
>>>> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
>>>> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct
>>>> rpmsg_device *rpdev,
>>>>         /* no free buffer ? wait for one (but bail after 15 seconds) */
>>>>       while (!msg) {
>>>>           /* enable "tx-complete" interrupts, if not already enabled */
>>>>           rpmsg_upref_sleepers(vrp);
>>>>   -        /*
>>>> -         * sleep until a free buffer is available or 15 secs elapse.
>>>> -         * the timeout period is not configurable because there's
>>>> -         * little point in asking drivers to specify that.
>>>> -         * if later this happens to be required, it'd be easy to add.
>>>> -         */
>>>> -        err = wait_event_interruptible_timeout(vrp->sendq,
>>>> -                    (msg = get_a_tx_buf(vrp)),
>>>> -                    msecs_to_jiffies(15000));
>>>> +        /* make sure to retry to grab tx buffer before we start waiting */
>>>> +        msg = get_a_tx_buf(vrp);
>>>> +        if (msg) {
>>>> +            err = 0;
>>>> +        } else {
>>>> +            /*
>>>> +             * sleep until a free buffer is available or 15 secs elapse.
>>>> +             * the timeout period is not configurable because there's
>>>> +             * little point in asking drivers to specify that.
>>>> +             * if later this happens to be required, it'd be easy to add.
>>>> +             */
>>>> +            err = wait_event_interruptible_timeout(vrp->sendq,
>>>> +                        (msg = get_a_tx_buf(vrp)),
>>>> +                        msecs_to_jiffies(15000));
>>>> +        }
>>>>             /* disable "tx-complete" interrupts if we're the last sleeper */
>>>>           rpmsg_downref_sleepers(vrp);
>>>>             /* timeout ? */
>>>>           if (!err) {
>>
> 

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

[-- Attachment #1.1: Type: text/plain, Size: 6199 bytes --]

>>>>> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
>>>>> enables tx-complete interrupt.
>>>>> however if the interrupt is executed after `get_a_tx_buf` and before
>>>>> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
>>>>> for the full 15 seconds.
>>>>
>>>>
>>>> Is there any reason why your co-processor is unable to release the TX RPMSG
>>>> buffers for 15 seconds? If not, you should first determine the reason why it is
>>>> stalled.
>>>
>>> Arnaud's concern is valid.  If the remote processor can't consume a buffer
>>> within 15 seconds, something is probably wrong.
>>>
>>> That said, I believe your assesment of the situation is correct.  *If* the TX
>>> callback is disabled and there is no buffer available, there is a window of
>>> opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
>>> interrupt to arrive in function rpmsg_send_offchannel_raw().
>>
>> the remote processor certainly releases the tx buffer and according to my
>> tracing the `vring_interrupt` fires immediately before `rpmsg_send` enters the
>> `rpmsg_upref_sleepers`.
> 
> 
> If I well understood your point, the issue occur in following race condition
> 
> - all the Tx buffers are used
> - in rpmsg_send_offchannel_raw() function, we try to get a buffer using
> get_a_tx_buf(vrp) that returns NULL
> - rpmsg_xmit_done is called as a Tx buffer is released by the remote processor
>    and now free
> - in rpmsg_send_offchannel_raw() rpmsg_upref_sleepers is called
> 
> At this point you are nothing happen until 15 second because rpmsg_xmit_done is
> never called  again that would wake up the waitqueue to call get_a_tx_buf()

yes, this is the behaviour that i've been seeing:

virtio emits a few times:
[  404.XXXXXX] No more buffers in queue
and then
[  404.588722] remoteproc remoteproc0: vq index 1 is interrupted
[  404.597249] virtqueue interrupt with no work for 6d53f13a

> If yes what is not clear to me is that wait_event_interruptible_timeout() seems
> to test the condition (so call get_a_tx_buf()) before entering in sleep[1]. A
> free TX buffer should be found at this step.
> 
> [1]https://elixir.bootlin.com/linux/latest/source/include/linux/wait.h#L534

hmm, interesting. but that would imply a timing issue where calling 
get_a_tx_buf twice somehow makes a difference as opposed to calling it 
only once.

would the "interrupt with no work" point to a different cause for the 
issue that we are seeing?

> 
> Regards,
> Arnaud
> 
>>
>> after applying this patch we haven't been able to reproduce the 15s timeout
>> anymore, whereas before we could easily reproduce it with certain workloads.
>>
>>> 3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
>>> soak.  No error are locks are reported due to this patch during that time.
>>
>> mentioning locks: i was a bit uncertain about a good way to implement the retry,
>> since both `rpmsg_upref_sleepers` and `get_a_tx_buf` both acquire the same
>> mutex. i briefly considered to add `get_a_tx_buf` into `rpmsg_upref_sleepers` to
>> avoid locking the same mutex multiple times, though it adds a bit of complexity
>> to the implementation and harms readability a bit.
>> are there any recommendations on this topic or are (likely non-contended) locks
>> not expensive enough to justify the added complexity?
>>
>> thanks,
>> tim
>>
>>
>>>
>>>>
>>>> Regards,
>>>> Arnaud
>>>>
>>>>>
>>>>> in this case, so we re-try once before we really start to sleep
>>>>>
>>>>> Signed-off-by: Tim Blechmann <tim@klingt.org>
>>>>> ---
>>>>>    drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
>>>>>    1 file changed, 15 insertions(+), 9 deletions(-)
>>>>>
>>>>> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>> b/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>> index 905ac7910c98..2a9d42225e60 100644
>>>>> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct
>>>>> rpmsg_device *rpdev,
>>>>>          /* no free buffer ? wait for one (but bail after 15 seconds) */
>>>>>        while (!msg) {
>>>>>            /* enable "tx-complete" interrupts, if not already enabled */
>>>>>            rpmsg_upref_sleepers(vrp);
>>>>>    -        /*
>>>>> -         * sleep until a free buffer is available or 15 secs elapse.
>>>>> -         * the timeout period is not configurable because there's
>>>>> -         * little point in asking drivers to specify that.
>>>>> -         * if later this happens to be required, it'd be easy to add.
>>>>> -         */
>>>>> -        err = wait_event_interruptible_timeout(vrp->sendq,
>>>>> -                    (msg = get_a_tx_buf(vrp)),
>>>>> -                    msecs_to_jiffies(15000));
>>>>> +        /* make sure to retry to grab tx buffer before we start waiting */
>>>>> +        msg = get_a_tx_buf(vrp);
>>>>> +        if (msg) {
>>>>> +            err = 0;
>>>>> +        } else {
>>>>> +            /*
>>>>> +             * sleep until a free buffer is available or 15 secs elapse.
>>>>> +             * the timeout period is not configurable because there's
>>>>> +             * little point in asking drivers to specify that.
>>>>> +             * if later this happens to be required, it'd be easy to add.
>>>>> +             */
>>>>> +            err = wait_event_interruptible_timeout(vrp->sendq,
>>>>> +                        (msg = get_a_tx_buf(vrp)),
>>>>> +                        msecs_to_jiffies(15000));
>>>>> +        }
>>>>>              /* disable "tx-complete" interrupts if we're the last sleeper */
>>>>>            rpmsg_downref_sleepers(vrp);
>>>>>              /* timeout ? */
>>>>>            if (!err) {
>>>
>>
> 

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 236 bytes --]

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Arnaud POULIQUEN]

On 9/9/23 08:28, Tim Blechmann wrote:
>>>>>> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
>>>>>> enables tx-complete interrupt.
>>>>>> however if the interrupt is executed after `get_a_tx_buf` and before
>>>>>> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
>>>>>> for the full 15 seconds.
>>>>>
>>>>>
>>>>> Is there any reason why your co-processor is unable to release the TX RPMSG
>>>>> buffers for 15 seconds? If not, you should first determine the reason why
>>>>> it is
>>>>> stalled.
>>>>
>>>> Arnaud's concern is valid.  If the remote processor can't consume a buffer
>>>> within 15 seconds, something is probably wrong.
>>>>
>>>> That said, I believe your assesment of the situation is correct.  *If* the TX
>>>> callback is disabled and there is no buffer available, there is a window of
>>>> opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
>>>> interrupt to arrive in function rpmsg_send_offchannel_raw().
>>>
>>> the remote processor certainly releases the tx buffer and according to my
>>> tracing the `vring_interrupt` fires immediately before `rpmsg_send` enters the
>>> `rpmsg_upref_sleepers`.
>>
>>
>> If I well understood your point, the issue occur in following race condition
>>
>> - all the Tx buffers are used
>> - in rpmsg_send_offchannel_raw() function, we try to get a buffer using
>> get_a_tx_buf(vrp) that returns NULL
>> - rpmsg_xmit_done is called as a Tx buffer is released by the remote processor
>>    and now free
>> - in rpmsg_send_offchannel_raw() rpmsg_upref_sleepers is called
>>
>> At this point you are nothing happen until 15 second because rpmsg_xmit_done is
>> never called  again that would wake up the waitqueue to call get_a_tx_buf()
> 
> yes, this is the behaviour that i've been seeing:
> 
> virtio emits a few times:
> [  404.XXXXXX] No more buffers in queue
> and then
> [  404.588722] remoteproc remoteproc0: vq index 1 is interrupted
> [  404.597249] virtqueue interrupt with no work for 6d53f13a

Difficult to understand the scheduling with your trace. Could you enable ftrace to
observe it (mailbox interrupts,rpmsg and virtio functions)
> 
>> If yes what is not clear to me is that wait_event_interruptible_timeout() seems
>> to test the condition (so call get_a_tx_buf()) before entering in sleep[1]. A
>> free TX buffer should be found at this step.
>>
>> [1]https://elixir.bootlin.com/linux/latest/source/include/linux/wait.h#L534
> 
> hmm, interesting. but that would imply a timing issue where calling get_a_tx_buf
> twice somehow makes a difference as opposed to calling it only once.
> 
> would the "interrupt with no work" point to a different cause for the issue that
> we are seeing?

Look like you have not released the buffer on remote side so no buffer in vring
used list.

Do you use the zero copy (rpmsg_hold_rx_buffer) on remote processor?
If yes, please check that you have following fix:
https://github.com/OpenAMP/open-amp/commit/2b6a38a9c6890869960ed41d6a1dc9930c079e0d

> 
>>
>> Regards,
>> Arnaud
>>
>>>
>>> after applying this patch we haven't been able to reproduce the 15s timeout
>>> anymore, whereas before we could easily reproduce it with certain workloads.
>>>
>>>> 3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
>>>> soak.  No error are locks are reported due to this patch during that time.
>>>
>>> mentioning locks: i was a bit uncertain about a good way to implement the retry,
>>> since both `rpmsg_upref_sleepers` and `get_a_tx_buf` both acquire the same
>>> mutex. i briefly considered to add `get_a_tx_buf` into `rpmsg_upref_sleepers` to
>>> avoid locking the same mutex multiple times, though it adds a bit of complexity
>>> to the implementation and harms readability a bit.
>>> are there any recommendations on this topic or are (likely non-contended) locks
>>> not expensive enough to justify the added complexity?
>>>
>>> thanks,
>>> tim
>>>
>>>
>>>>
>>>>>
>>>>> Regards,
>>>>> Arnaud
>>>>>
>>>>>>
>>>>>> in this case, so we re-try once before we really start to sleep
>>>>>>
>>>>>> Signed-off-by: Tim Blechmann <tim@klingt.org>
>>>>>> ---
>>>>>>    drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
>>>>>>    1 file changed, 15 insertions(+), 9 deletions(-)
>>>>>>
>>>>>> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>>> b/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>>> index 905ac7910c98..2a9d42225e60 100644
>>>>>> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>>> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
>>>>>> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct
>>>>>> rpmsg_device *rpdev,
>>>>>>          /* no free buffer ? wait for one (but bail after 15 seconds) */
>>>>>>        while (!msg) {
>>>>>>            /* enable "tx-complete" interrupts, if not already enabled */
>>>>>>            rpmsg_upref_sleepers(vrp);
>>>>>>    -        /*
>>>>>> -         * sleep until a free buffer is available or 15 secs elapse.
>>>>>> -         * the timeout period is not configurable because there's
>>>>>> -         * little point in asking drivers to specify that.
>>>>>> -         * if later this happens to be required, it'd be easy to add.
>>>>>> -         */
>>>>>> -        err = wait_event_interruptible_timeout(vrp->sendq,
>>>>>> -                    (msg = get_a_tx_buf(vrp)),
>>>>>> -                    msecs_to_jiffies(15000));
>>>>>> +        /* make sure to retry to grab tx buffer before we start waiting */
>>>>>> +        msg = get_a_tx_buf(vrp);
>>>>>> +        if (msg) {
>>>>>> +            err = 0;
>>>>>> +        } else {
>>>>>> +            /*
>>>>>> +             * sleep until a free buffer is available or 15 secs elapse.
>>>>>> +             * the timeout period is not configurable because there's
>>>>>> +             * little point in asking drivers to specify that.
>>>>>> +             * if later this happens to be required, it'd be easy to add.
>>>>>> +             */
>>>>>> +            err = wait_event_interruptible_timeout(vrp->sendq,
>>>>>> +                        (msg = get_a_tx_buf(vrp)),
>>>>>> +                        msecs_to_jiffies(15000));
>>>>>> +        }
>>>>>>              /* disable "tx-complete" interrupts if we're the last sleeper */
>>>>>>            rpmsg_downref_sleepers(vrp);
>>>>>>              /* timeout ? */
>>>>>>            if (!err) {
>>>>
>>>
>>

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

[-- Attachment #1.1: Type: text/plain, Size: 3510 bytes --]

>> virtio emits a few times:
>> [  404.XXXXXX] No more buffers in queue
>> and then
>> [  404.588722] remoteproc remoteproc0: vq index 1 is interrupted
>> [  404.597249] virtqueue interrupt with no work for 6d53f13a
> 
> Difficult to understand the scheduling with your trace. Could you enable ftrace to
> observe it (mailbox interrupts,rpmsg and virtio functions)

does this help (it's a trace that a coworker did a few days ago)?

```
root:.../kernel/tracing# cat trace | head -50
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
  0) + 10.250 us   |        rpmsg_sg_init();
  0) + 42.375 us   |      } /* rpmsg_send_offchannel_raw */
  0) + 51.125 us   |    } /* virtio_rpmsg_send */
  0) + 59.625 us   |  } /* rpmsg_send */
  ------------------------------------------
  0)  stm32mp-414   =>  kworker-365
  ------------------------------------------

  0)               |  rpmsg_recv_done() {
  0)               |    rpmsg_recv_single() {
  0)   5.542 us    |      rpmsg_sg_init();
  0) + 36.542 us   |    }
  0) + 48.250 us   |  }
  ------------------------------------------
  0)  kworker-365   =>  stm32mp-414
  ------------------------------------------

  0)   7.000 us    |  rpmsg_get_buffer_size();
  0)               |  rpmsg_send() {
  0)               |    virtio_rpmsg_send() {
  0)               |      rpmsg_send_offchannel_raw() {
  0)   5.625 us    |        rpmsg_sg_init();
  0) + 37.333 us   |      }
  0) + 45.916 us   |    }
  0) + 54.250 us   |  }
  ------------------------------------------
  0)  stm32mp-414   =>  kworker-365
  ------------------------------------------

  0)               |  rpmsg_recv_done() {
  0)               |    rpmsg_recv_single() {
  0)   6.041 us    |      rpmsg_sg_init();
  0) + 37.292 us   |    }
  0) + 49.542 us   |  }
  ------------------------------------------
  0)  kworker-365   =>  stm32mp-414
  ------------------------------------------

  0)   6.500 us    |  rpmsg_get_buffer_size();
  0)               |  rpmsg_send() {
  0)               |    virtio_rpmsg_send() {
  0)               |      rpmsg_send_offchannel_raw() {
  0)   5.417 us    |        rpmsg_sg_init();
  0) + 36.583 us   |      }
  0) + 45.167 us   |    }
  0) + 53.583 us   |  }
```

apparently this is where it gets stuck (not sure if it's enough context, 
though).

>>
>>> If yes what is not clear to me is that wait_event_interruptible_timeout() seems
>>> to test the condition (so call get_a_tx_buf()) before entering in sleep[1]. A
>>> free TX buffer should be found at this step.
>>>
>>> [1]https://elixir.bootlin.com/linux/latest/source/include/linux/wait.h#L534
>>
>> hmm, interesting. but that would imply a timing issue where calling get_a_tx_buf
>> twice somehow makes a difference as opposed to calling it only once.
>>
>> would the "interrupt with no work" point to a different cause for the issue that
>> we are seeing?
> 
> Look like you have not released the buffer on remote side so no buffer in vring
> used list.
> 
> Do you use the zero copy (rpmsg_hold_rx_buffer) on remote processor?
> If yes, please check that you have following fix:
> https://github.com/OpenAMP/open-amp/commit/2b6a38a9c6890869960ed41d6a1dc9930c079e0d

yes, we use rpmsg_hold_rx_buffer, however the fix from 
2b6a38a9c6890869960ed41d6a1dc9930c079e0d apparently did not change the 
behaviour.

many thanks,
tim

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 236 bytes --]

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

[-- Attachment #1.1: Type: text/plain, Size: 637 bytes --]

On 9/13/23 09:07, Tim Blechmann wrote:
>>> virtio emits a few times:
>>> [  404.XXXXXX] No more buffers in queue
>>> and then
>>> [  404.588722] remoteproc remoteproc0: vq index 1 is interrupted
>>> [  404.597249] virtqueue interrupt with no work for 6d53f13a
>>
>> Difficult to understand the scheduling with your trace. Could you 
>> enable ftrace to
>> observe it (mailbox interrupts,rpmsg and virtio functions)

full trace, that my worker did (quite large, so i zipped it):
https://fileservice.klingt.org/downloads/15526951694567393180-tracefull.zip

the interesting part starts at 907.2244250

many thanks,
tim

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 236 bytes --]

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Arnaud POULIQUEN]

hello Tim

On 9/13/23 03:11, Tim Blechmann wrote:
> On 9/13/23 09:07, Tim Blechmann wrote:
>>>> virtio emits a few times:
>>>> [  404.XXXXXX] No more buffers in queue
>>>> and then
>>>> [  404.588722] remoteproc remoteproc0: vq index 1 is interrupted
>>>> [  404.597249] virtqueue interrupt with no work for 6d53f13a
>>>
>>> Difficult to understand the scheduling with your trace. Could you enable
>>> ftrace to
>>> observe it (mailbox interrupts,rpmsg and virtio functions)
> 
> full trace, that my worker did (quite large, so i zipped it):
> https://fileservice.klingt.org/downloads/15526951694567393180-tracefull.zip

please find below an extract of your trace with my analysis:


 stm32mp1_bulk_p-390     [001] .....   907.241226: rpmsg_send
<-rpmsg_intercore_send_buffer.constprop.0
 stm32mp1_bulk_p-390     [001] .....   907.241228: virtio_rpmsg_send <-rpmsg_send
 stm32mp1_bulk_p-390     [001] .....   907.241237: virtqueue_enable_cb
<-rpmsg_send_offchannel_raw
 stm32mp1_bulk_p-390     [001] .....   907.241239: virtqueue_enable_cb_prepare

At this point seems that no more TX-buffer

<-rpmsg_recv_single
     kworker/0:4-67      [000] .....   907.242533: vring_interrupt
<-rproc_vq_interrupt
     kworker/0:4-67      [000] .....   907.242536: rpmsg_xmit_done

Here you receive  an interrupt indicating that TX buffer has been released by
the remote. that's the expected behavior.


<-rpmsg_send_offchannel_raw
 stm32mp1_bulk_p-390     [000] .....   984.054941: rpmsg_send
<-rpmsg_intercore_send_buffer.constprop.0
 stm32mp1_bulk_p-390     [000] .....   984.054943: virtio_rpmsg_send <-rpmsg_send
 stm32mp1_bulk_p-390     [000] .....   984.054956: virtqueue_enable_cb
<-rpmsg_send_offchannel_raw
 stm32mp1_bulk_p-390     [000] .....   984.054958: virtqueue_enable_cb_prepare
<-virtqueue_enable_cb
 stm32mp1_bulk_p-390     [000] .....   999.398667: virtqueue_disable_cb
<-rpmsg_send_offchannel_raw
 stm32mp1_bulk_p-390     [000] .....   999.414840: rpmsg_send
<-rpmsg_intercore_send_buffer.constprop.0
 stm32mp1_bulk_p-390     [000] .....   999.414843: virtio_rpmsg_send <-rpmsg_send
 stm32mp1_bulk_p-390     [000] .....   999.414855: virtqueue_enable_cb
<-rpmsg_send_offchannel_raw
 stm32mp1_bulk_p-390     [000] .....   999.414857: virtqueue_enable_cb_prepare

Here you have again no more TX buffer. From this point there is no more activity
neither in TX nor in RX until the timeout of 15 seconds.
If you have a look to rproc_vq_interrupt the last one occurs at 907.242533


As you have no more virtqueue interrupts call for both directions, the issue is
probably either in the Cortex-M firmware, which seems to be stalled, or due to a
disable of the IRQs in Linux.

<-virtqueue_enable_cb
 stm32mp1_bulk_p-390     [000] .....  1014.758678: virtqueue_disable_cb
<-rpmsg_send_offchannel_raw
 stm32mp1_bulk_p-390     [000] .....  1014.774802: rpmsg_send
<-rpmsg_intercore_send_buffer.constprop.0
 stm32mp1_bulk_p-390     [000] .....  1014.774804: virtio_rpmsg_send <-rpmsg_send
 stm32mp1_bulk_p-390     [000] .....  1014.774815: virtqueue_enable_cb

Regards,
Arnaud

> 
> the interesting part starts at 907.2244250
> 
> many thanks,
> tim

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

[-- Attachment #1.1: Type: text/plain, Size: 2997 bytes --]

many thanks for your analysis, very interesting.

> please find below an extract of your trace with my analysis:
> 
> 
>   stm32mp1_bulk_p-390     [001] .....   907.241226: rpmsg_send
> <-rpmsg_intercore_send_buffer.constprop.0
>   stm32mp1_bulk_p-390     [001] .....   907.241228: virtio_rpmsg_send <-rpmsg_send
>   stm32mp1_bulk_p-390     [001] .....   907.241237: virtqueue_enable_cb
> <-rpmsg_send_offchannel_raw
>   stm32mp1_bulk_p-390     [001] .....   907.241239: virtqueue_enable_cb_prepare
> 
> At this point seems that no more TX-buffer
> 
> <-rpmsg_recv_single
>       kworker/0:4-67      [000] .....   907.242533: vring_interrupt
> <-rproc_vq_interrupt
>       kworker/0:4-67      [000] .....   907.242536: rpmsg_xmit_done
> 
> Here you receive  an interrupt indicating that TX buffer has been released by
> the remote. that's the expected behavior.
> 
> 
> <-rpmsg_send_offchannel_raw
>   stm32mp1_bulk_p-390     [000] .....   984.054941: rpmsg_send
> <-rpmsg_intercore_send_buffer.constprop.0
>   stm32mp1_bulk_p-390     [000] .....   984.054943: virtio_rpmsg_send <-rpmsg_send
>   stm32mp1_bulk_p-390     [000] .....   984.054956: virtqueue_enable_cb
> <-rpmsg_send_offchannel_raw
>   stm32mp1_bulk_p-390     [000] .....   984.054958: virtqueue_enable_cb_prepare
> <-virtqueue_enable_cb
>   stm32mp1_bulk_p-390     [000] .....   999.398667: virtqueue_disable_cb
> <-rpmsg_send_offchannel_raw
>   stm32mp1_bulk_p-390     [000] .....   999.414840: rpmsg_send
> <-rpmsg_intercore_send_buffer.constprop.0
>   stm32mp1_bulk_p-390     [000] .....   999.414843: virtio_rpmsg_send <-rpmsg_send
>   stm32mp1_bulk_p-390     [000] .....   999.414855: virtqueue_enable_cb
> <-rpmsg_send_offchannel_raw
>   stm32mp1_bulk_p-390     [000] .....   999.414857: virtqueue_enable_cb_prepare
> 
> Here you have again no more TX buffer. From this point there is no more activity
> neither in TX nor in RX until the timeout of 15 seconds.
> If you have a look to rproc_vq_interrupt the last one occurs at 907.242533
> 
> 
> As you have no more virtqueue interrupts call for both directions, the issue is
> probably either in the Cortex-M firmware, which seems to be stalled, or due to a
> disable of the IRQs in Linux.

afaict we can rule out a complete stall of the cortex-m firmware: if we 
change the rpmsg_send to a rpmsg_trysend/msleep loop, the trysend will 
succeed to get a buffer after a few iterations.

> or due to a disable of the IRQs in Linux.

do you have some recommendations how we could trace this?

many thanks,
tim

> <-virtqueue_enable_cb
>   stm32mp1_bulk_p-390     [000] .....  1014.758678: virtqueue_disable_cb
> <-rpmsg_send_offchannel_raw
>   stm32mp1_bulk_p-390     [000] .....  1014.774802: rpmsg_send
> <-rpmsg_intercore_send_buffer.constprop.0
>   stm32mp1_bulk_p-390     [000] .....  1014.774804: virtio_rpmsg_send <-rpmsg_send
>   stm32mp1_bulk_p-390     [000] .....  1014.774815: virtqueue_enable_cb



[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 236 bytes --]

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Arnaud POULIQUEN]

On 9/13/23 10:47, Tim Blechmann wrote:
> many thanks for your analysis, very interesting.
> 
>> please find below an extract of your trace with my analysis:
>>
>>
>>   stm32mp1_bulk_p-390     [001] .....   907.241226: rpmsg_send
>> <-rpmsg_intercore_send_buffer.constprop.0
>>   stm32mp1_bulk_p-390     [001] .....   907.241228: virtio_rpmsg_send
>> <-rpmsg_send
>>   stm32mp1_bulk_p-390     [001] .....   907.241237: virtqueue_enable_cb
>> <-rpmsg_send_offchannel_raw
>>   stm32mp1_bulk_p-390     [001] .....   907.241239: virtqueue_enable_cb_prepare
>>
>> At this point seems that no more TX-buffer
>>
>> <-rpmsg_recv_single
>>       kworker/0:4-67      [000] .....   907.242533: vring_interrupt
>> <-rproc_vq_interrupt
>>       kworker/0:4-67      [000] .....   907.242536: rpmsg_xmit_done
>>
>> Here you receive  an interrupt indicating that TX buffer has been released by
>> the remote. that's the expected behavior.
>>
>>
>> <-rpmsg_send_offchannel_raw
>>   stm32mp1_bulk_p-390     [000] .....   984.054941: rpmsg_send
>> <-rpmsg_intercore_send_buffer.constprop.0
>>   stm32mp1_bulk_p-390     [000] .....   984.054943: virtio_rpmsg_send
>> <-rpmsg_send
>>   stm32mp1_bulk_p-390     [000] .....   984.054956: virtqueue_enable_cb
>> <-rpmsg_send_offchannel_raw
>>   stm32mp1_bulk_p-390     [000] .....   984.054958: virtqueue_enable_cb_prepare
>> <-virtqueue_enable_cb
>>   stm32mp1_bulk_p-390     [000] .....   999.398667: virtqueue_disable_cb
>> <-rpmsg_send_offchannel_raw
>>   stm32mp1_bulk_p-390     [000] .....   999.414840: rpmsg_send
>> <-rpmsg_intercore_send_buffer.constprop.0
>>   stm32mp1_bulk_p-390     [000] .....   999.414843: virtio_rpmsg_send
>> <-rpmsg_send
>>   stm32mp1_bulk_p-390     [000] .....   999.414855: virtqueue_enable_cb
>> <-rpmsg_send_offchannel_raw
>>   stm32mp1_bulk_p-390     [000] .....   999.414857: virtqueue_enable_cb_prepare
>>
>> Here you have again no more TX buffer. From this point there is no more activity
>> neither in TX nor in RX until the timeout of 15 seconds.
>> If you have a look to rproc_vq_interrupt the last one occurs at 907.242533
>>
>>
>> As you have no more virtqueue interrupts call for both directions, the issue is
>> probably either in the Cortex-M firmware, which seems to be stalled, or due to a
>> disable of the IRQs in Linux.
> 
> afaict we can rule out a complete stall of the cortex-m firmware: if we change
> the rpmsg_send to a rpmsg_trysend/msleep loop, the trysend will succeed to get a
> buffer after a few iterations.
> 
>> or due to a disable of the IRQs in Linux.
> 
> do you have some recommendations how we could trace this?

First, check if the Cortex-M sends the IPCC mailbox notification during the
15-second period. Then, you can verify the IPCC registers to check if some flags
are pending. On the Linux side, there is probably literature available to
explain how to trace it.

> 
> many thanks,
> tim
> 
>> <-virtqueue_enable_cb
>>   stm32mp1_bulk_p-390     [000] .....  1014.758678: virtqueue_disable_cb
>> <-rpmsg_send_offchannel_raw
>>   stm32mp1_bulk_p-390     [000] .....  1014.774802: rpmsg_send
>> <-rpmsg_intercore_send_buffer.constprop.0
>>   stm32mp1_bulk_p-390     [000] .....  1014.774804: virtio_rpmsg_send
>> <-rpmsg_send
>>   stm32mp1_bulk_p-390     [000] .....  1014.774815: virtqueue_enable_cb
> 
> 

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Arnaud POULIQUEN]

On 9/13/23 12:57, Agostiño Carballeira wrote:
> Hello!
> 
> I am the main developer of the CM4 firmware for this project.
> First of all thanks for taking the time to analyse the trace.
> Further analysis on my side has shown that the CM4 is not completely stalled in
> this situation, but it is stuck on a busywait loop within the MAILBOX_Notify
> function, awaiting a window to send a "buffer used" notification to the CA7. So
> it seems that the mailbox is locked both ways and neither side is giving way to
> unclog the traffic jam.

The Cortex-M4 is probably blocked, waiting for Linux mailbox to acknowledge a
mailbox notification[1].
Are you 100% sure that you have never exited this loop during the issue?
Could you provide the value of the 'id' variable and the call stack?

That would mean that the mailbox has not been acknowledged by Linux [2] or [3].
I don't understand how it could be possible...

[1]
https://github.com/STMicroelectronics/STM32CubeMP1/blob/master/Middlewares/Third_Party/OpenAMP/mw_if/platform_if/mbox_ipcc_template.c#L182

[2] https://elixir.bootlin.com/linux/latest/source/drivers/mailbox/stm32-ipcc.c#L105
[3] https://elixir.bootlin.com/linux/latest/source/drivers/mailbox/stm32-ipcc.c#L134

> Interestingly, when we replace rpmsg_send by rpmsg_trysend + busywait loop, this
> mutual stall doesn't happen at all.

What do you mean by busywait? Do you add a delay between 2 rpmsg_trysend()
calls? If yes, you probably add delay that avoid the issue.

That said rpmsg_trysend is recommended for baremetal to avoid to block the system.

> Does that give you any clues?
> 
> Thanks
> Agos
> 
> On Wed, Sep 13, 2023 at 10:47 AM Tim Blechmann <tim@klingt.org
> <mailto:tim@klingt.org>> wrote:
> 
>     many thanks for your analysis, very interesting.
> 
>     > please find below an extract of your trace with my analysis:
>     >
>     >
>     >   stm32mp1_bulk_p-390     [001] .....   907.241226: rpmsg_send
>     > <-rpmsg_intercore_send_buffer.constprop.0
>     >   stm32mp1_bulk_p-390     [001] .....   907.241228: virtio_rpmsg_send
>     <-rpmsg_send
>     >   stm32mp1_bulk_p-390     [001] .....   907.241237: virtqueue_enable_cb
>     > <-rpmsg_send_offchannel_raw
>     >   stm32mp1_bulk_p-390     [001] .....   907.241239:
>     virtqueue_enable_cb_prepare
>     >
>     > At this point seems that no more TX-buffer
>     >
>     > <-rpmsg_recv_single
>     >       kworker/0:4-67      [000] .....   907.242533: vring_interrupt
>     > <-rproc_vq_interrupt
>     >       kworker/0:4-67      [000] .....   907.242536: rpmsg_xmit_done
>     >
>     > Here you receive  an interrupt indicating that TX buffer has been released by
>     > the remote. that's the expected behavior.
>     >
>     >
>     > <-rpmsg_send_offchannel_raw
>     >   stm32mp1_bulk_p-390     [000] .....   984.054941: rpmsg_send
>     > <-rpmsg_intercore_send_buffer.constprop.0
>     >   stm32mp1_bulk_p-390     [000] .....   984.054943: virtio_rpmsg_send
>     <-rpmsg_send
>     >   stm32mp1_bulk_p-390     [000] .....   984.054956: virtqueue_enable_cb
>     > <-rpmsg_send_offchannel_raw
>     >   stm32mp1_bulk_p-390     [000] .....   984.054958:
>     virtqueue_enable_cb_prepare
>     > <-virtqueue_enable_cb
>     >   stm32mp1_bulk_p-390     [000] .....   999.398667: virtqueue_disable_cb
>     > <-rpmsg_send_offchannel_raw
>     >   stm32mp1_bulk_p-390     [000] .....   999.414840: rpmsg_send
>     > <-rpmsg_intercore_send_buffer.constprop.0
>     >   stm32mp1_bulk_p-390     [000] .....   999.414843: virtio_rpmsg_send
>     <-rpmsg_send
>     >   stm32mp1_bulk_p-390     [000] .....   999.414855: virtqueue_enable_cb
>     > <-rpmsg_send_offchannel_raw
>     >   stm32mp1_bulk_p-390     [000] .....   999.414857:
>     virtqueue_enable_cb_prepare
>     >
>     > Here you have again no more TX buffer. From this point there is no more
>     activity
>     > neither in TX nor in RX until the timeout of 15 seconds.
>     > If you have a look to rproc_vq_interrupt the last one occurs at 907.242533
>     >
>     >
>     > As you have no more virtqueue interrupts call for both directions, the
>     issue is
>     > probably either in the Cortex-M firmware, which seems to be stalled, or
>     due to a
>     > disable of the IRQs in Linux.
> 
>     afaict we can rule out a complete stall of the cortex-m firmware: if we
>     change the rpmsg_send to a rpmsg_trysend/msleep loop, the trysend will
>     succeed to get a buffer after a few iterations.
> 
>     > or due to a disable of the IRQs in Linux.
> 
>     do you have some recommendations how we could trace this?
> 
>     many thanks,
>     tim
> 
>     > <-virtqueue_enable_cb
>     >   stm32mp1_bulk_p-390     [000] .....  1014.758678: virtqueue_disable_cb
>     > <-rpmsg_send_offchannel_raw
>     >   stm32mp1_bulk_p-390     [000] .....  1014.774802: rpmsg_send
>     > <-rpmsg_intercore_send_buffer.constprop.0
>     >   stm32mp1_bulk_p-390     [000] .....  1014.774804: virtio_rpmsg_send
>     <-rpmsg_send
>     >   stm32mp1_bulk_p-390     [000] .....  1014.774815: virtqueue_enable_cb
> 
> 
> 
> 
> -- 
> 
> Agostiño Carballeira
> 
> Senior Embedded Software Engineer
> 
> agostino.carballeira@native-instruments.com
> <mailto:agostino.carballeira@native-instruments.com>
> 
> 
> Native Instruments <https://www.native-instruments.com>– now including iZotope,
> Plugin Alliance, and Brainworx

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

>> Interestingly, when we replace rpmsg_send by rpmsg_trysend + busywait loop, this
>> mutual stall doesn't happen at all.
> 
> What do you mean by busywait? Do you add a delay between 2 rpmsg_trysend()
> calls? If yes, you probably add delay that avoid the issue.
> 
> That said rpmsg_trysend is recommended for baremetal to avoid to block the system.

to avoid misunderstanding here: replacing `rpmsg_send` by a 
`rpmsg_trysend` / `usleep` loop on the *linux* side works around the 
issue (i.e. in our own small module and in rpmsg_char).

thanks,
tim

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Arnaud POULIQUEN]

On 9/4/23 22:43, Mathieu Poirier wrote:
> On Mon, Sep 04, 2023 at 03:52:56PM +0200, Arnaud POULIQUEN wrote:
>> Hello Tim,
>>
>> On 9/4/23 10:36, Tim Blechmann wrote:
>>> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
>>> enables tx-complete interrupt.
>>> however if the interrupt is executed after `get_a_tx_buf` and before
>>> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
>>> for the full 15 seconds.
>>
>>
>> Is there any reason why your co-processor is unable to release the TX RPMSG
>> buffers for 15 seconds? If not, you should first determine the reason why it is
>> stalled.
> 
> Arnaud's concern is valid.  If the remote processor can't consume a buffer
> within 15 seconds, something is probably wrong.
> 
> That said, I believe your assesment of the situation is correct.  *If* the TX
> callback is disabled and there is no buffer available, there is a window of
> opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
> interrupt to arrive in function rpmsg_send_offchannel_raw().  
> 
> From here three things need to happen:
> 
> 1) You send another version of this patch with a changelong that uses proper
> english, i.e capital letters when they are needed and no spelling mistake.
> 
> 2) Arnaud confirms our suspicions.

Seems to me that this patch is useless
- wait_event_interruptible_timeout() function already seems
to test the condition (so call get_a_tx_buf()) before entering in sleep[1].
- ftraces show that vq interrupt is not called during the 15-second period.
  So it is a normal behavior that the vrp->sendq is never waked-up.

Tim needs to analyze the reason why no mailbox interrupt occurs.

[1]https://elixir.bootlin.com/linux/latest/source/include/linux/wait.h#L534


> 
> 3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
> soak.  No error are locks are reported due to this patch during that time. 
> 
>>
>> Regards,
>> Arnaud
>>
>>>
>>> in this case, so we re-try once before we really start to sleep
>>>
>>> Signed-off-by: Tim Blechmann <tim@klingt.org>
>>> ---
>>>  drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
>>>  1 file changed, 15 insertions(+), 9 deletions(-)
>>>
>>> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
>>> index 905ac7910c98..2a9d42225e60 100644
>>> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
>>> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
>>> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
>>>  
>>>  	/* no free buffer ? wait for one (but bail after 15 seconds) */
>>>  	while (!msg) {
>>>  		/* enable "tx-complete" interrupts, if not already enabled */
>>>  		rpmsg_upref_sleepers(vrp);
>>>  
>>> -		/*
>>> -		 * sleep until a free buffer is available or 15 secs elapse.
>>> -		 * the timeout period is not configurable because there's
>>> -		 * little point in asking drivers to specify that.
>>> -		 * if later this happens to be required, it'd be easy to add.
>>> -		 */
>>> -		err = wait_event_interruptible_timeout(vrp->sendq,
>>> -					(msg = get_a_tx_buf(vrp)),
>>> -					msecs_to_jiffies(15000));
>>> +		/* make sure to retry to grab tx buffer before we start waiting */
>>> +		msg = get_a_tx_buf(vrp);
>>> +		if (msg) {
>>> +			err = 0;
>>> +		} else {
>>> +			/*
>>> +			 * sleep until a free buffer is available or 15 secs elapse.
>>> +			 * the timeout period is not configurable because there's
>>> +			 * little point in asking drivers to specify that.
>>> +			 * if later this happens to be required, it'd be easy to add.
>>> +			 */
>>> +			err = wait_event_interruptible_timeout(vrp->sendq,
>>> +						(msg = get_a_tx_buf(vrp)),
>>> +						msecs_to_jiffies(15000));
>>> +		}
>>>  
>>>  		/* disable "tx-complete" interrupts if we're the last sleeper */
>>>  		rpmsg_downref_sleepers(vrp);
>>>  
>>>  		/* timeout ? */
>>>  		if (!err) {

Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Mathieu Poirier]

On Wed, Sep 13, 2023 at 12:10:39PM +0200, Arnaud POULIQUEN wrote:
> 
> 
> On 9/4/23 22:43, Mathieu Poirier wrote:
> > On Mon, Sep 04, 2023 at 03:52:56PM +0200, Arnaud POULIQUEN wrote:
> >> Hello Tim,
> >>
> >> On 9/4/23 10:36, Tim Blechmann wrote:
> >>> when we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
> >>> enables tx-complete interrupt.
> >>> however if the interrupt is executed after `get_a_tx_buf` and before
> >>> `rpmsg_upref_sleepers` we may mis the tx-complete interrupt and sleep
> >>> for the full 15 seconds.
> >>
> >>
> >> Is there any reason why your co-processor is unable to release the TX RPMSG
> >> buffers for 15 seconds? If not, you should first determine the reason why it is
> >> stalled.
> > 
> > Arnaud's concern is valid.  If the remote processor can't consume a buffer
> > within 15 seconds, something is probably wrong.
> > 
> > That said, I believe your assesment of the situation is correct.  *If* the TX
> > callback is disabled and there is no buffer available, there is a window of
> > opportunity between calls to get_a_tx_buf() and rpmsg_upref_sleepers() for an
> > interrupt to arrive in function rpmsg_send_offchannel_raw().  
> > 
> > From here three things need to happen:
> > 
> > 1) You send another version of this patch with a changelong that uses proper
> > english, i.e capital letters when they are needed and no spelling mistake.
> > 
> > 2) Arnaud confirms our suspicions.
> 
> Seems to me that this patch is useless
> - wait_event_interruptible_timeout() function already seems
> to test the condition (so call get_a_tx_buf()) before entering in sleep[1].
> - ftraces show that vq interrupt is not called during the 15-second period.
>   So it is a normal behavior that the vrp->sendq is never waked-up.
> 

Thanks for looking further into this issue.  I will wait for you guys to get to
the root of the problems.

> Tim needs to analyze the reason why no mailbox interrupt occurs.
> 
> [1]https://elixir.bootlin.com/linux/latest/source/include/linux/wait.h#L534
> 
> 
> > 
> > 3) This patch gets applied when rc1 comes out so that it has 6 or 7 weeks to
> > soak.  No error are locks are reported due to this patch during that time. 
> > 
> >>
> >> Regards,
> >> Arnaud
> >>
> >>>
> >>> in this case, so we re-try once before we really start to sleep
> >>>
> >>> Signed-off-by: Tim Blechmann <tim@klingt.org>
> >>> ---
> >>>  drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
> >>>  1 file changed, 15 insertions(+), 9 deletions(-)
> >>>
> >>> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
> >>> index 905ac7910c98..2a9d42225e60 100644
> >>> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
> >>> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
> >>> @@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
> >>>  
> >>>  	/* no free buffer ? wait for one (but bail after 15 seconds) */
> >>>  	while (!msg) {
> >>>  		/* enable "tx-complete" interrupts, if not already enabled */
> >>>  		rpmsg_upref_sleepers(vrp);
> >>>  
> >>> -		/*
> >>> -		 * sleep until a free buffer is available or 15 secs elapse.
> >>> -		 * the timeout period is not configurable because there's
> >>> -		 * little point in asking drivers to specify that.
> >>> -		 * if later this happens to be required, it'd be easy to add.
> >>> -		 */
> >>> -		err = wait_event_interruptible_timeout(vrp->sendq,
> >>> -					(msg = get_a_tx_buf(vrp)),
> >>> -					msecs_to_jiffies(15000));
> >>> +		/* make sure to retry to grab tx buffer before we start waiting */
> >>> +		msg = get_a_tx_buf(vrp);
> >>> +		if (msg) {
> >>> +			err = 0;
> >>> +		} else {
> >>> +			/*
> >>> +			 * sleep until a free buffer is available or 15 secs elapse.
> >>> +			 * the timeout period is not configurable because there's
> >>> +			 * little point in asking drivers to specify that.
> >>> +			 * if later this happens to be required, it'd be easy to add.
> >>> +			 */
> >>> +			err = wait_event_interruptible_timeout(vrp->sendq,
> >>> +						(msg = get_a_tx_buf(vrp)),
> >>> +						msecs_to_jiffies(15000));
> >>> +		}
> >>>  
> >>>  		/* disable "tx-complete" interrupts if we're the last sleeper */
> >>>  		rpmsg_downref_sleepers(vrp);
> >>>  
> >>>  		/* timeout ? */
> >>>  		if (!err) {

[PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition

[Tim Blechmann]

When we cannot get a tx buffer (`get_a_tx_buf`) `rpmsg_upref_sleepers`
enables tx-complete interrupt.
However if the interrupt is executed after `get_a_tx_buf` and before
`rpmsg_upref_sleepers` we may miss the tx-complete interrupt and sleep
for the full 15 seconds. To avoid this race condition, we re-try once
before we really start to sleep.

Signed-off-by: Tim Blechmann <tim@klingt.org>
---
 drivers/rpmsg/virtio_rpmsg_bus.c | 24 +++++++++++++++---------
 1 file changed, 15 insertions(+), 9 deletions(-)

diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
index 905ac7910c98..2a9d42225e60 100644
--- a/drivers/rpmsg/virtio_rpmsg_bus.c
+++ b/drivers/rpmsg/virtio_rpmsg_bus.c
@@ -587,21 +587,27 @@ static int rpmsg_send_offchannel_raw(struct rpmsg_device *rpdev,
 
 	/* no free buffer ? wait for one (but bail after 15 seconds) */
 	while (!msg) {
 		/* enable "tx-complete" interrupts, if not already enabled */
 		rpmsg_upref_sleepers(vrp);
 
-		/*
-		 * sleep until a free buffer is available or 15 secs elapse.
-		 * the timeout period is not configurable because there's
-		 * little point in asking drivers to specify that.
-		 * if later this happens to be required, it'd be easy to add.
-		 */
-		err = wait_event_interruptible_timeout(vrp->sendq,
-					(msg = get_a_tx_buf(vrp)),
-					msecs_to_jiffies(15000));
+		/* make sure to retry to grab tx buffer before we start waiting */
+		msg = get_a_tx_buf(vrp);
+		if (msg) {
+			err = 0;
+		} else {
+			/*
+			 * sleep until a free buffer is available or 15 secs elapse.
+			 * the timeout period is not configurable because there's
+			 * little point in asking drivers to specify that.
+			 * if later this happens to be required, it'd be easy to add.
+			 */
+			err = wait_event_interruptible_timeout(vrp->sendq,
+						(msg = get_a_tx_buf(vrp)),
+						msecs_to_jiffies(15000));
+		}
 
 		/* disable "tx-complete" interrupts if we're the last sleeper */
 		rpmsg_downref_sleepers(vrp);
 
 		/* timeout ? */
 		if (!err) {
-- 
2.34.1