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

From: Arnaud POULIQUEN <arnaud.pouliquen@foss.st.com>
To: Tim Blechmann <tim@klingt.org>,
	Mathieu Poirier <mathieu.poirier@linaro.org>
Cc: Tim Blechmann <tim.blechmann@gmail.com>,
	<linux-remoteproc@vger.kernel.org>,
	<agostino.carballeira@native-instruments.de>
Subject: Re: [PATCH 1/1] rpmsg: virtio_rpmsg_bus - prevent possible race condition
Date: Wed, 13 Sep 2023 12:02:16 +0200	[thread overview]
Message-ID: <aec60fe8-ec1d-25d1-f07d-eb0b664d8dba@foss.st.com> (raw)
In-Reply-To: <117fbe3c-3db4-4f82-1d96-11501259e209@klingt.org>

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
> 
> 