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