rpmsg_multi_services demo runs only once after reboot

[olneumann]

After solving #52 now I run into the issue that the provided demo does not run for a second time.

Zephyr hangs on:

[19:10:46:516] D: platform_ipm_callback: msg received from mb 0
[19:10:46:519] 
[19:10:46:519] D: mailbox_notify: msg received
[19:10:46:522] 
[19:10:46:522] D: mailbox_notify: msg received
[19:10:46:525] 
[19:10:46:525] OpenAMP Linux sample client responder ended
[19:17:16:307] *** Booting Zephyr OS build v3.7.0-3935-g9403b08512eb ***
[19:17:16:312] Starting application threads!
[19:17:16:315] 
[19:17:16:319] OpenAMP[remote]  linux responder demo started

Loaded modules:

Module                  Size  Used by
rpmsg_client_sample    12288  0
rpmsg_ctrl             12288  0
rpmsg_char             16384  1 rpmsg_ctrl
virtio_rpmsg_bus       16384  0
rpmsg_ns               12288  1 virtio_rpmsg_bus
rpmsg_core             12288  5 virtio_rpmsg_bus,rpmsg_char,rpmsg_ctrl,rpmsg_client_sample,rpmsg_ns
cfg80211              757760  0
xlnx_r5_remoteproc     16384  0
uio_pdrv_genirq        12288  0
dmaproxy               12288  0
usb5744                12288  0
usb2244                12288  0

Steps to reproduce

# First run successful 

echo firmware.elf > /sys/class/remoteproc/remoteproc0/firmware
echo start > /sys/class/remoteproc/remoteproc0/state

# Second run with removing modules

echo stop > /sys/class/remoteproc/remoteproc0/state

modprobe -r xlnx_r5_remoteproc
modprobe -r virtio_rpmsg_bus
modprobe -r rpmsg_client_sample rpmsg_tty rpmsg_ctrl rpmsg_char rpmsg_core

modprobe xlnx_r5_remoteproc 
modprobe rpmsg_client_sample
modprobe rpmsg_char
modprobe rpmsg_tty
modprobe rpmsg_ctrl
modprobe virtio_rpmsg_bus

echo firmware.elf > /sys/class/remoteproc/remoteproc0/firmware
echo start > /sys/class/remoteproc/remoteproc0/state

# Third run without removing modules

echo stop > /sys/class/remoteproc/remoteproc0/state
echo firmware.elf > /sys/class/remoteproc/remoteproc0/firmware
echo start > /sys/class/remoteproc/remoteproc0/state

Logs

dmesg output

[   84.583855] remoteproc remoteproc0: powering up zynqmp-rpu:r5f-0
[   84.629797] remoteproc remoteproc0: Booting fw image firmware.elf, size 695112
[   84.633002] platform zynqmp-rpu:r5f-0: TCM carveout split mode atcm0 addr=ffe00000, da=0x0, size=0x10000
[   84.636196] platform zynqmp-rpu:r5f-0: TCM carveout split mode btcm0 addr=ffe20000, da=0x20000, size=0x10000
[   84.636213] remoteproc remoteproc0: reserved mem carveout memory addr=3ed00000, size=0x40000
[   84.636224] remoteproc remoteproc0: reserved mem carveout vdev0buffer addr=3ed48000, size=0x100000
[   84.636232] remoteproc remoteproc0: reserved mem carveout vdev0vring0 addr=3ed40000, size=0x4000
[   84.636241] remoteproc remoteproc0: reserved mem carveout vdev0vring1 addr=3ed44000, size=0x4000
[   84.636739] platform zynqmp-rpu:r5f-0: RPU boot addr 0x1034 from TCM.
[   84.636850] rproc-virtio rproc-virtio.3.auto: assigned reserved memory node vdev0buffer@3ed48000
[   84.636915] rproc-virtio rproc-virtio.3.auto: registered virtio0 (type 7)
[   84.636923] remoteproc remoteproc0: remote processor zynqmp-rpu:r5f-0 is now up
[   84.655123] virtio_rpmsg_bus virtio0: rpmsg host is online
[   84.667710] virtio_rpmsg_bus virtio0: creating channel rpmsg-client-sample addr 0x400
[   84.667857] remoteproc remoteproc0: data not found for vqid=1
[   84.672254] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: new channel: 0x400 -> 0x400!
[   84.679466] virtio_rpmsg_bus virtio0: creating channel rpmsg-tty addr 0x401
[   84.679603] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 1 (src: 0x400)
[   84.686992] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 2 (src: 0x400)
[   84.697163] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 3 (src: 0x400)
[   84.702031] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 4 (src: 0x400)
[   84.709544] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 5 (src: 0x400)
[   84.717068] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 6 (src: 0x400)
[   84.724593] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 7 (src: 0x400)
[   84.732119] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 8 (src: 0x400)
[   84.739645] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 9 (src: 0x400)
[   84.747171] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 10 (src: 0x400)
[   84.754696] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 11 (src: 0x400)
[   84.762221] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 12 (src: 0x400)
[   84.769747] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 13 (src: 0x400)
[   84.777273] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 14 (src: 0x400)
[   84.784797] remoteproc remoteproc0: data not found for vqid=0
[   84.787824] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 15 (src: 0x400)
[   84.800030] virtio_rpmsg_bus virtio0: creating channel rpmsg-raw addr 0x402
[   84.809992] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 16 (src: 0x400)
[   84.817500] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 17 (src: 0x400)
[   84.825021] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 18 (src: 0x400)
[   84.832546] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 19 (src: 0x400)
[   84.840072] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 20 (src: 0x400)
[   84.847598] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 21 (src: 0x400)
[   84.855124] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 22 (src: 0x400)
[   84.862648] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 23 (src: 0x400)
[   84.870174] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 24 (src: 0x400)
[   84.877699] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 25 (src: 0x400)
[   84.885225] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 26 (src: 0x400)
[   84.892750] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 27 (src: 0x400)
[   84.900276] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 28 (src: 0x400)
[   84.907802] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 29 (src: 0x400)
[   84.915327] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 30 (src: 0x400)
[   84.922853] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 31 (src: 0x400)
[   84.930379] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 32 (src: 0x400)
[   84.937905] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 33 (src: 0x400)
[   84.945430] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 34 (src: 0x400)
[   84.952955] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 35 (src: 0x400)
[   84.960481] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 36 (src: 0x400)
[   84.968006] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 37 (src: 0x400)
[   84.975532] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 38 (src: 0x400)
[   84.983058] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 39 (src: 0x400)
[   84.990583] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 40 (src: 0x400)
[   84.998109] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 41 (src: 0x400)
[   85.005634] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 42 (src: 0x400)
[   85.013164] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 43 (src: 0x400)
[   85.020686] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 44 (src: 0x400)
[   85.028211] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 45 (src: 0x400)
[   85.035736] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 46 (src: 0x400)
[   85.043262] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 47 (src: 0x400)
[   85.050788] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 48 (src: 0x400)
[   85.058314] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 49 (src: 0x400)
[   85.065839] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 50 (src: 0x400)
[   85.073364] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 51 (src: 0x400)
[   85.080890] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 52 (src: 0x400)
[   85.088415] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 53 (src: 0x400)
[   85.095941] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 54 (src: 0x400)
[   85.103468] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 55 (src: 0x400)
[   85.110993] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 56 (src: 0x400)
[   85.118520] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 57 (src: 0x400)
[   85.126044] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 58 (src: 0x400)
[   85.133569] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 59 (src: 0x400)
[   85.141095] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 60 (src: 0x400)
[   85.148620] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 61 (src: 0x400)
[   85.156146] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 62 (src: 0x400)
[   85.163671] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 63 (src: 0x400)
[   85.171197] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 64 (src: 0x400)
[   85.178723] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 65 (src: 0x400)
[   85.186248] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 66 (src: 0x400)
[   85.193774] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 67 (src: 0x400)
[   85.201299] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 68 (src: 0x400)
[   85.208825] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 69 (src: 0x400)
[   85.216350] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 70 (src: 0x400)
[   85.223876] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 71 (src: 0x400)
[   85.231402] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 72 (src: 0x400)
[   85.238927] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 73 (src: 0x400)
[   85.246453] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 74 (src: 0x400)
[   85.253978] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 75 (src: 0x400)
[   85.261504] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 76 (src: 0x400)
[   85.269029] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 77 (src: 0x400)
[   85.276555] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 78 (src: 0x400)
[   85.284080] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 79 (src: 0x400)
[   85.291606] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 80 (src: 0x400)
[   85.299133] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 81 (src: 0x400)
[   85.306657] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 82 (src: 0x400)
[   85.314183] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 83 (src: 0x400)
[   85.321709] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 84 (src: 0x400)
[   85.329234] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 85 (src: 0x400)
[   85.336760] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 86 (src: 0x400)
[   85.344285] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 87 (src: 0x400)
[   85.351811] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 88 (src: 0x400)
[   85.359338] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 89 (src: 0x400)
[   85.366862] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 90 (src: 0x400)
[   85.374388] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 91 (src: 0x400)
[   85.381914] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 92 (src: 0x400)
[   85.389439] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 93 (src: 0x400)
[   85.396964] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 94 (src: 0x400)
[   85.404490] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 95 (src: 0x400)
[   85.412015] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 96 (src: 0x400)
[   85.419541] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 97 (src: 0x400)
[   85.427067] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 98 (src: 0x400)
[   85.434592] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 99 (src: 0x400)
[   85.442118] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: incoming msg 100 (src: 0x400)
[   85.442126] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: goodbye!
[   85.442140] virtio_rpmsg_bus virtio0: destroying channel rpmsg-client-sample addr 0x400
[   85.442223] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: rpmsg sample client driver is removed
[   85.445177] remoteproc remoteproc0: data not found for vqid=0
[   94.007480] remoteproc remoteproc0: stopped remote processor zynqmp-rpu:r5f-0
[   94.045587] remoteproc remoteproc0: releasing zynqmp-rpu:r5f-0
[   94.085399] remoteproc remoteproc1: releasing zynqmp-rpu:r5f-1
[   98.448445] remoteproc remoteproc0: zynqmp-rpu:r5f-0 is available
[   98.449674] remoteproc remoteproc1: zynqmp-rpu:r5f-1 is available
[  115.434922] remoteproc remoteproc0: powering up zynqmp-rpu:r5f-0
[  115.436877] remoteproc remoteproc0: Booting fw image firmware.elf, size 695112
[  115.440135] platform zynqmp-rpu:r5f-0: TCM carveout split mode atcm0 addr=ffe00000, da=0x0, size=0x10000
[  115.443328] platform zynqmp-rpu:r5f-0: TCM carveout split mode btcm0 addr=ffe20000, da=0x20000, size=0x10000
[  115.443343] remoteproc remoteproc0: reserved mem carveout memory addr=3ed00000, size=0x40000
[  115.443353] remoteproc remoteproc0: reserved mem carveout vdev0buffer addr=3ed48000, size=0x100000
[  115.443362] remoteproc remoteproc0: reserved mem carveout vdev0vring0 addr=3ed40000, size=0x4000
[  115.443370] remoteproc remoteproc0: reserved mem carveout vdev0vring1 addr=3ed44000, size=0x4000
[  115.443887] platform zynqmp-rpu:r5f-0: RPU boot addr 0x1034 from TCM.
[  115.443942] rproc-virtio rproc-virtio.3.auto: assigned reserved memory node vdev0buffer@3ed48000
[  115.444033] virtio_rpmsg_bus virtio0: buffers: va 000000002e1495ee, dma 0x000000003ed48000
[  115.444387] virtio_rpmsg_bus virtio0: rpmsg host is online
[  115.444410] rproc-virtio rproc-virtio.3.auto: registered virtio0 (type 7)
[  115.444417] remoteproc remoteproc0: remote processor zynqmp-rpu:r5f-0 is now up
[  122.319862] remoteproc remoteproc0: stopped remote processor zynqmp-rpu:r5f-0
[  133.116422] remoteproc remoteproc0: powering up zynqmp-rpu:r5f-0
[  133.118277] remoteproc remoteproc0: Booting fw image firmware.elf, size 695112
[  133.121498] platform zynqmp-rpu:r5f-0: TCM carveout split mode atcm0 addr=ffe00000, da=0x0, size=0x10000
[  133.124676] platform zynqmp-rpu:r5f-0: TCM carveout split mode btcm0 addr=ffe20000, da=0x20000, size=0x10000
[  133.124690] remoteproc remoteproc0: reserved mem carveout memory addr=3ed00000, size=0x40000
[  133.124700] remoteproc remoteproc0: reserved mem carveout vdev0buffer addr=3ed48000, size=0x100000
[  133.124708] remoteproc remoteproc0: reserved mem carveout vdev0vring0 addr=3ed40000, size=0x4000
[  133.124716] remoteproc remoteproc0: reserved mem carveout vdev0vring1 addr=3ed44000, size=0x4000
[  133.125228] platform zynqmp-rpu:r5f-0: RPU boot addr 0x1034 from TCM.
[  133.125285] rproc-virtio rproc-virtio.3.auto: assigned reserved memory node vdev0buffer@3ed48000
[  133.125431] virtio_rpmsg_bus virtio0: buffers: va 000000002e1495ee, dma 0x000000003ed48000
[  133.125747] virtio_rpmsg_bus virtio0: rpmsg host is online
[  133.125770] rproc-virtio rproc-virtio.3.auto: registered virtio0 (type 7)
[  133.125777] remoteproc remoteproc0: remote processor zynqmp-rpu:r5f-0 is now up
[  133.145651] virtio_rpmsg_bus virtio0: From: 0x400, To: 0x35, Len: 40, Flags: 0, Reserved: 0
[  133.145674] virtio_rpmsg_bus virtio0: RX vring: avail: 8 used: 1
[  133.145686] rpmsg_virtio RX: 00 04 00 00 35 00 00 00 00 00 00 00 28 00 00 00  ....5.......(...
[  133.145695] rpmsg_virtio RX: 72 70 6d 73 67 2d 63 6c 69 65 6e 74 2d 73 61 6d  rpmsg-client-sam
[  133.145702] rpmsg_virtio RX: 70 6c 65 00 64 87 00 00 00 00 00 00 a7 25 00 00  ple.d........%..
[  133.145708] rpmsg_virtio RX: 00 04 00 00 00 00 00 00                          ........
[  133.145719] virtio_rpmsg_bus virtio0: creating channel rpmsg-client-sample addr 0x400
[  133.145879] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: new channel: 0x400 -> 0x400!
[  133.145890] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: TX From 0x400, To 0x400, Len 12, Flags 0, Reserved 0
[  133.145900] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: TX vring: avail: 0 used: 0
[  133.145910] rpmsg_virtio TX: 00 04 00 00 00 04 00 00 00 00 00 00 0c 00 00 00  ................
[  133.145917] rpmsg_virtio TX: 68 65 6c 6c 6f 20 77 6f 72 6c 64 21              hello world!
[  133.145972] virtio_rpmsg_bus virtio0: Received 1 messages
[  133.145981] remoteproc remoteproc0: data not found for vqid=1
[  133.152909] virtio_rpmsg_bus virtio0: From: 0x401, To: 0x35, Len: 40, Flags: 0, Reserved: 0
[  133.152925] virtio_rpmsg_bus virtio0: RX vring: avail: 9 used: 2
[  133.152936] rpmsg_virtio RX: 01 04 00 00 35 00 00 00 00 00 00 00 28 00 00 00  ....5.......(...
[  133.152944] rpmsg_virtio RX: 72 70 6d 73 67 2d 74 74 79 00 00 00 00 00 00 00  rpmsg-tty.......
[  133.152952] rpmsg_virtio RX: 5c 86 00 00 64 87 00 00 00 00 00 00 a7 25 00 00  \...d........%..
[  133.152959] rpmsg_virtio RX: 01 04 00 00 00 00 00 00                          ........
[  133.152969] virtio_rpmsg_bus virtio0: creating channel rpmsg-tty addr 0x401
[  133.153300] virtio_rpmsg_bus virtio0: Received 1 messages
[  133.153312] remoteproc remoteproc0: data not found for vqid=1
[  133.160616] virtio_rpmsg_bus virtio0: From: 0x402, To: 0x35, Len: 40, Flags: 0, Reserved: 0
[  133.160636] virtio_rpmsg_bus virtio0: RX vring: avail: 10 used: 3
[  133.160648] rpmsg_virtio RX: 02 04 00 00 35 00 00 00 00 00 00 00 28 00 00 00  ....5.......(...
[  133.160657] rpmsg_virtio RX: 72 70 6d 73 67 2d 72 61 77 00 00 00 00 00 00 00  rpmsg-raw.......
[  133.160665] rpmsg_virtio RX: b4 85 00 00 64 87 00 00 00 00 00 00 a7 25 00 00  ....d........%..
[  133.160671] rpmsg_virtio RX: 02 04 00 00 00 00 00 00                          ........
[  133.160682] virtio_rpmsg_bus virtio0: creating channel rpmsg-raw addr 0x402
[  133.160996] virtio_rpmsg_bus virtio0: Received 1 messages
[  133.161009] remoteproc remoteproc0: data not found for vqid=1

UART log

[19:38:37:585] *** Booting Zephyr OS build v3.7.0-3935-g9403b08512eb ***
[19:38:37:590] Starting application threads!
[19:38:37:592] 
[19:38:37:593] OpenAMP[remote]  linux responder demo started
[19:38:37:603] D: platform_ipm_callback: msg received from mb 0
[19:38:37:607] 
[19:38:37:607] 
[19:38:37:608] OpenAMP[remote] Linux sample client responder started
[19:38:37:612] D: mailbox_notify: msg received
[19:38:37:615] 
[19:38:37:616] 
[19:38:37:616] OpenAMP[remote] Linux tty responder started
[19:38:37:620] D: maD: platform_ipm_callback: msg received from mb 0
[19:38:37:624] 
[19:38:37:625] ilbox_notify: msg received
[19:38:37:627] 
[19:38:37:627] D: D: platform_ipm_callback: msg received from mb 0
[19:38:37:632] 
[19:38:37:632] mailbox_notify: msg received
[19:38:37:635] 
[19:38:37:635] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:639] 
[19:38:37:639] : mailbox_notify: msg received
[19:38:37:642] 
[19:38:37:642] D: mailbox_notify: msg receivedD: platform_ipm_callback: msg received from mb 0
[19:38:37:649] 
[19:38:37:649] 
[19:38:37:650] 
[19:38:37:650] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:654] 
[19:38:37:654] : mailbox_notify: msg received
[19:38:37:657] 
[19:38:37:657] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:662] 
[19:38:37:662] : mailbox_notify: msg received
[19:38:37:665] 
[19:38:37:665] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:669] 
[19:38:37:669] : mailbox_notify: msg received
[19:38:37:672] 
[19:38:37:672] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:677] 
[19:38:37:677] : mailbox_notify: msg received
[19:38:37:680] 
[19:38:37:680] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:684] 
[19:38:37:684] : mailbox_notify: msg received
[19:38:37:687] 
[19:38:37:687] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:692] 
[19:38:37:692] : mailbox_notify: msg received
[19:38:37:695] 
[19:38:37:695] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:699] 
[19:38:37:699] : mailbox_notify: msg received
[19:38:37:702] 
[19:38:37:702] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:707] 
[19:38:37:707] : mailbox_notify: msg received
[19:38:37:710] 
[19:38:37:710] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:714] 
[19:38:37:715] : mailbox_notify: msg received
[19:38:37:717] 
[19:38:37:717] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:722] 
[19:38:37:722] : mailbox_notify: msg received
[19:38:37:725] 
[19:38:37:725] DD: platform_ipm_callback: msg received from mb 0
[19:38:37:729] 
[19:38:37:730] : mailbox_notify: msg received
[19:38:37:732] 
[19:38:37:733] D: mailbox_notify: msg received
[19:38:37:735] 
[19:38:37:736] D: platform_ipm_callback: msg received from mb 0
[19:38:37:740] 
[19:38:37:740] 
[19:38:37:740] OpenAMP[remote] Linux raw data responder started
[19:38:37:745] D: mailbox_notify: msg received
[19:38:37:749] 
[19:38:37:749] 
[19:38:37:749] OpenAMP[remote] create a endpoint with address and dest_address set to 0x1
[19:38:37:755] D: mailbox_notify: msg received
[19:38:37:759] 
[19:38:37:759] D: platform_ipm_callback: msg received from mb 0
[19:38:37:762] 
[19:38:37:762] D: mailbox_notify: msg received
[19:38:37:765] 
[19:38:37:765] D: platform_ipm_callback: msg received from mb 0
[19:38:37:770] 
[19:38:37:770] D: mailbox_notify: msg received
[19:38:37:773] 
[19:38:37:773] D: platform_ipm_callback: msg received from mb 0
[19:38:37:777] 
[19:38:37:777] D: mailbox_notify: msg received
[19:38:37:780] 
[19:38:37:780] D: platform_ipm_callback: msg received from mb 0
[19:38:37:785] 
[19:38:37:785] D: mailbox_notify: msg received
[19:38:37:788] 
[19:38:37:788] D: platform_ipm_callback: msg received from mb 0
[19:38:37:792] 
[19:38:37:792] D: mailbox_notify: msg received
[19:38:37:795] 
[19:38:37:795] D: platform_ipm_callback: msg received from mb 0
[19:38:37:800] 
[19:38:37:800] D: mailbox_notify: msg received
[19:38:37:803] 
[19:38:37:803] D: platform_ipm_callback: msg received from mb 0
[19:38:37:807] 
[19:38:37:807] D: mailbox_notify: msg received
[19:38:37:810] 
[19:38:37:810] D: platform_ipm_callback: msg received from mb 0
[19:38:37:815] 
[19:38:37:815] D: mailbox_notify: msg received
[19:38:37:818] 
[19:38:37:818] D: platform_ipm_callback: msg received from mb 0
[19:38:37:822] 
[19:38:37:822] D: mailbox_notify: msg received
[19:38:37:825] 
[19:38:37:825] D: platform_ipm_callback: msg received from mb 0
[19:38:37:830] 
[19:38:37:830] D: mailbox_notify: msg received
[19:38:37:833] 
[19:38:37:833] D: platform_ipm_callback: msg received from mb 0
[19:38:37:837] 
[19:38:37:837] D: mailbox_notify: msg received
[19:38:37:840] 
[19:38:37:840] D: platform_ipm_callback: msg received from mb 0
[19:38:37:845] 
[19:38:37:845] D: mailbox_notify: msg received
[19:38:37:848] 
[19:38:37:848] D: platform_ipm_callback: msg received from mb 0
[19:38:37:852] 
[19:38:37:852] D: mailbox_notify: msg received
[19:38:37:855] 
[19:38:37:856] D: platform_ipm_callback: msg received from mb 0
[19:38:37:860] 
[19:38:37:860] D: mailbox_notify: msg received
[19:38:37:863] 
[19:38:37:863] D: platform_ipm_callback: msg received from mb 0
[19:38:37:867] 
[19:38:37:868] D: mailbox_notify: msg received
[19:38:37:870] 
[19:38:37:871] D: platform_ipm_callback: msg received from mb 0
[19:38:37:875] 
[19:38:37:875] D: mailbox_notify: msg received
[19:38:37:878] 
[19:38:37:878] D: platform_ipm_callback: msg received from mb 0
[19:38:37:882] 
[19:38:37:883] D: mailbox_notify: msg received
[19:38:37:886] 
[19:38:37:886] D: platform_ipm_callback: msg received from mb 0
[19:38:37:890] 
[19:38:37:890] D: mailbox_notify: msg received
[19:38:37:893] 
[19:38:37:893] D: platform_ipm_callback: msg received from mb 0
[19:38:37:898] 
[19:38:37:898] D: mailbox_notify: msg received
[19:38:37:901] 
[19:38:37:901] D: platform_ipm_callback: msg received from mb 0
[19:38:37:905] 
[19:38:37:905] D: mailbox_notify: msg received
[19:38:37:908] 
[19:38:37:908] D: platform_ipm_callback: msg received from mb 0
[19:38:37:913] 
[19:38:37:913] D: mailbox_notify: msg received
[19:38:37:916] 
[19:38:37:916] D: platform_ipm_callback: msg received from mb 0
[19:38:37:920] 
[19:38:37:920] D: mailbox_notify: msg received
[19:38:37:923] 
[19:38:37:923] D: platform_ipm_callback: msg received from mb 0
[19:38:37:928] 
[19:38:37:928] D: mailbox_notify: msg received
[19:38:37:931] 
[19:38:37:931] D: platform_ipm_callback: msg received from mb 0
[19:38:37:935] 
[19:38:37:935] D: mailbox_notify: msg received
[19:38:37:938] 
[19:38:37:938] D: platform_ipm_callback: msg received from mb 0
[19:38:37:943] 
[19:38:37:943] D: mailbox_notify: msg received
[19:38:37:946] 
[19:38:37:946] D: platform_ipm_callback: msg received from mb 0
[19:38:37:950] 
[19:38:37:950] D: mailbox_notify: msg received
[19:38:37:953] 
[19:38:37:953] D: platform_ipm_callback: msg received from mb 0
[19:38:37:958] 
[19:38:37:958] D: mailbox_notify: msg received
[19:38:37:961] 
[19:38:37:961] D: platform_ipm_callback: msg received from mb 0
[19:38:37:965] 
[19:38:37:965] D: mailbox_notify: msg received
[19:38:37:968] 
[19:38:37:968] D: platform_ipm_callback: msg received from mb 0
[19:38:37:973] 
[19:38:37:973] D: mailbox_notify: msg received
[19:38:37:976] 
[19:38:37:976] D: platform_ipm_callback: msg received from mb 0
[19:38:37:980] 
[19:38:37:980] D: mailbox_notify: msg received
[19:38:37:983] 
[19:38:37:983] D: platform_ipm_callback: msg received from mb 0
[19:38:37:988] 
[19:38:37:988] D: mailbox_notify: msg received
[19:38:37:991] 
[19:38:37:991] D: platform_ipm_callback: msg received from mb 0
[19:38:37:995] 
[19:38:37:995] D: mailbox_notify: msg received
[19:38:37:998] 
[19:38:37:999] D: platform_ipm_callback: msg received from mb 0
[19:38:38:003] 
[19:38:38:003] D: mailbox_notify: msg received
[19:38:38:006] 
[19:38:38:006] D: platform_ipm_callback: msg received from mb 0
[19:38:38:010] 
[19:38:38:011] D: mailbox_notify: msg received
[19:38:38:013] 
[19:38:38:014] D: platform_ipm_callback: msg received from mb 0
[19:38:38:018] 
[19:38:38:018] D: mailbox_notify: msg received
[19:38:38:021] 
[19:38:38:021] D: platform_ipm_callback: msg received from mb 0
[19:38:38:025] 
[19:38:38:026] D: mailbox_notify: msg received
[19:38:38:029] 
[19:38:38:029] D: platform_ipm_callback: msg received from mb 0
[19:38:38:033] 
[19:38:38:033] D: mailbox_notify: msg received
[19:38:38:036] 
[19:38:38:036] D: platform_ipm_callback: msg received from mb 0
[19:38:38:041] 
[19:38:38:041] D: mailbox_notify: msg received
[19:38:38:044] 
[19:38:38:044] D: platform_ipm_callback: msg received from mb 0
[19:38:38:048] 
[19:38:38:048] D: mailbox_notify: msg received
[19:38:38:051] 
[19:38:38:051] D: platform_ipm_callback: msg received from mb 0
[19:38:38:056] 
[19:38:38:056] D: mailbox_notify: msg received
[19:38:38:061] 
[19:38:38:061] D: platform_ipm_callback: msg received from mb 0
[19:38:38:063] 
[19:38:38:063] D: mailbox_notify: msg received
[19:38:38:066] 
[19:38:38:066] D: platform_ipm_callback: msg received from mb 0
[19:38:38:071] 
[19:38:38:071] D: mailbox_notify: msg received
[19:38:38:076] 
[19:38:38:076] D: platform_ipm_callback: msg received from mb 0
[19:38:38:078] 
[19:38:38:078] D: mailbox_notify: msg received
[19:38:38:081] 
[19:38:38:081] D: platform_ipm_callback: msg received from mb 0
[19:38:38:086] 
[19:38:38:086] D: mailbox_notify: msg received
[19:38:38:089] 
[19:38:38:089] D: platform_ipm_callback: msg received from mb 0
[19:38:38:093] 
[19:38:38:093] D: mailbox_notify: msg received
[19:38:38:096] 
[19:38:38:096] D: platform_ipm_callback: msg received from mb 0
[19:38:38:101] 
[19:38:38:101] D: mailbox_notify: msg received
[19:38:38:104] 
[19:38:38:104] D: platform_ipm_callback: msg received from mb 0
[19:38:38:108] 
[19:38:38:108] D: mailbox_notify: msg received
[19:38:38:111] 
[19:38:38:111] D: platform_ipm_callback: msg received from mb 0
[19:38:38:116] 
[19:38:38:116] D: mailbox_notify: msg received
[19:38:38:119] 
[19:38:38:119] D: platform_ipm_callback: msg received from mb 0
[19:38:38:123] 
[19:38:38:123] D: mailbox_notify: msg received
[19:38:38:126] 
[19:38:38:126] D: platform_ipm_callback: msg received from mb 0
[19:38:38:131] 
[19:38:38:131] D: mailbox_notify: msg received
[19:38:38:134] 
[19:38:38:134] D: platform_ipm_callback: msg received from mb 0
[19:38:38:138] 
[19:38:38:138] D: mailbox_notify: msg received
[19:38:38:141] 
[19:38:38:141] D: platform_ipm_callback: msg received from mb 0
[19:38:38:146] 
[19:38:38:146] D: mailbox_notify: msg received
[19:38:38:149] 
[19:38:38:149] D: platform_ipm_callback: msg received from mb 0
[19:38:38:153] 
[19:38:38:154] D: mailbox_notify: msg received
[19:38:38:156] 
[19:38:38:157] D: platform_ipm_callback: msg received from mb 0
[19:38:38:161] 
[19:38:38:161] D: mailbox_notify: msg received
[19:38:38:164] 
[19:38:38:164] D: platform_ipm_callback: msg received from mb 0
[19:38:38:168] 
[19:38:38:169] D: mailbox_notify: msg received
[19:38:38:172] 
[19:38:38:172] D: platform_ipm_callback: msg received from mb 0
[19:38:38:176] 
[19:38:38:176] D: mailbox_notify: msg received
[19:38:38:179] 
[19:38:38:179] D: platform_ipm_callback: msg received from mb 0
[19:38:38:184] 
[19:38:38:184] D: mailbox_notify: msg received
[19:38:38:189] 
[19:38:38:189] D: platform_ipm_callback: msg received from mb 0
[19:38:38:191] 
[19:38:38:191] D: mailbox_notify: msg received
[19:38:38:194] 
[19:38:38:194] D: platform_ipm_callback: msg received from mb 0
[19:38:38:199] 
[19:38:38:199] D: mailbox_notify: msg received
[19:38:38:204] 
[19:38:38:204] D: platform_ipm_callback: msg received from mb 0
[19:38:38:206] 
[19:38:38:206] D: mailbox_notify: msg received
[19:38:38:209] 
[19:38:38:209] D: platform_ipm_callback: msg received from mb 0
[19:38:38:214] 
[19:38:38:214] D: mailbox_notify: msg received
[19:38:38:219] 
[19:38:38:219] D: platform_ipm_callback: msg received from mb 0
[19:38:38:221] 
[19:38:38:221] D: mailbox_notify: msg received
[19:38:38:224] 
[19:38:38:224] D: platform_ipm_callback: msg received from mb 0
[19:38:38:229] 
[19:38:38:229] D: mailbox_notify: msg received
[19:38:38:232] 
[19:38:38:232] D: platform_ipm_callback: msg received from mb 0
[19:38:38:236] 
[19:38:38:236] D: mailbox_notify: msg received
[19:38:38:239] 
[19:38:38:239] D: platform_ipm_callback: msg received from mb 0
[19:38:38:244] 
[19:38:38:244] D: mailbox_notify: msg received
[19:38:38:247] 
[19:38:38:247] D: platform_ipm_callback: msg received from mb 0
[19:38:38:251] 
[19:38:38:251] D: mailbox_notify: msg received
[19:38:38:254] 
[19:38:38:254] D: platform_ipm_callback: msg received from mb 0
[19:38:38:259] 
[19:38:38:259] D: mailbox_notify: msg received
[19:38:38:262] 
[19:38:38:262] D: platform_ipm_callback: msg received from mb 0
[19:38:38:266] 
[19:38:38:266] D: mailbox_notify: msg received
[19:38:38:269] 
[19:38:38:269] D: platform_ipm_callback: msg received from mb 0
[19:38:38:274] 
[19:38:38:274] D: mailbox_notify: msg received
[19:38:38:277] 
[19:38:38:277] D: platform_ipm_callback: msg received from mb 0
[19:38:38:281] 
[19:38:38:281] D: mailbox_notify: msg received
[19:38:38:284] 
[19:38:38:284] D: platform_ipm_callback: msg received from mb 0
[19:38:38:289] 
[19:38:38:289] D: mailbox_notify: msg received
[19:38:38:292] 
[19:38:38:292] D: platform_ipm_callback: msg received from mb 0
[19:38:38:296] 
[19:38:38:297] D: mailbox_notify: msg received
[19:38:38:299] 
[19:38:38:300] D: platform_ipm_callback: msg received from mb 0
[19:38:38:304] 
[19:38:38:304] D: mailbox_notify: msg received
[19:38:38:307] 
[19:38:38:307] D: platform_ipm_callback: msg received from mb 0
[19:38:38:311] 
[19:38:38:312] D: mailbox_notify: msg received
[19:38:38:315] 
[19:38:38:315] D: platform_ipm_callback: msg received from mb 0
[19:38:38:319] 
[19:38:38:319] D: mailbox_notify: msg received
[19:38:38:322] 
[19:38:38:322] D: platform_ipm_callback: msg received from mb 0
[19:38:38:327] 
[19:38:38:327] D: mailbox_notify: msg received
[19:38:38:332] 
[19:38:38:332] D: platform_ipm_callback: msg received from mb 0
[19:38:38:334] 
[19:38:38:334] D: mailbox_notify: msg received
[19:38:38:337] 
[19:38:38:337] D: platform_ipm_callback: msg received from mb 0
[19:38:38:342] 
[19:38:38:342] D: mailbox_notify: msg received
[19:38:38:347] 
[19:38:38:347] D: platform_ipm_callback: msg received from mb 0
[19:38:38:349] 
[19:38:38:349] D: mailbox_notify: msg received
[19:38:38:352] 
[19:38:38:352] D: platform_ipm_callback: msg received from mb 0
[19:38:38:357] 
[19:38:38:357] D: mailbox_notify: msg received
[19:38:38:362] 
[19:38:38:362] D: platform_ipm_callback: msg received from mb 0
[19:38:38:364] 
[19:38:38:364] D: mailbox_notify: msg received
[19:38:38:367] 
[19:38:38:367] D: platform_ipm_callback: msg received from mb 0
[19:38:38:372] 
[19:38:38:372] D: mailbox_notify: msg received
[19:38:38:375] 
[19:38:38:375] D: platform_ipm_callback: msg received from mb 0
[19:38:38:379] 
[19:38:38:379] D: mailbox_notify: msg received
[19:38:38:382] 
[19:38:38:382] D: platform_ipm_callback: msg received from mb 0
[19:38:38:387] 
[19:38:38:387] D: mailbox_notify: msg received
[19:38:38:390] 
[19:38:38:390] D: mailbox_notify: msg received
[19:38:38:393] 
[19:38:38:393] OpenAMP Linux sample client responder ended
[19:39:08:391] *** Booting Zephyr OS build v3.7.0-3935-g9403b08512eb ***
[19:39:08:396] Starting application threads!
[19:39:08:403] 
[19:39:08:403] OpenAMP[remote]  linux responder demo started
[19:39:26:073] *** Booting Zephyr OS build v3.7.0-3935-g9403b08512eb ***
[19:39:26:078] Starting application threads!
[19:39:26:084] 
[19:39:26:084] OpenAMP[remote]  linux responder demo started
[19:39:26:099] 
[19:39:26:099] OpenAMP[remote] Linux sample client responder started
[19:39:26:099] D: mailbox_notify: msg received
[19:39:26:099] 
[19:39:26:099] 
[19:39:26:099] OpenAMP[remote] Linux tty responder started
[19:39:26:099] D: mailbox_notify: msg received
[19:39:26:118] 
[19:39:26:118] 
[19:39:26:118] OpenAMP[remote] Linux raw data responder started
[19:39:26:118] D: mailbox_notify: msg received
[19:39:26:118] 
[19:39:26:118] 
[19:39:26:118] OpenAMP[remote] create a endpoint with address and dest_address set to 0x1

Any help?

[tnmysh]

Few questions from above logs:

1. rpmsg_ns wasn't being removed and reinstalled. I think is it removed automatically when removed virtio_rpmsg_bus?

2. Zephyr hangs after second run (i.e. after reinstalling drivers) or third run (i.e. without removing) ?

3. Why remove all the drivers in the first place ? If you run demo without removing drivers at all the demo works multiple times ?

[olneumann]

Few questions from above logs:

1. rpmsg_ns wasn't being removed and reinstalled. I think is it removed automatically when removed virtio_rpmsg_bus?

2. Zephyr hangs after second run (i.e. after reinstalling drivers) or third run (i.e. without removing) ?

3. Why remove all the drivers in the first place ? If you run demo without removing drivers at all the demo works multiple times ?

Thank you for looking into that.

1. Yes, it was removed completely.
2. Zephyr hangs on both runs (second and third), but for the third it runs until the creation of the rpmsg endpoint.
3. See question two. I thought that it is maybe due to some driver getting stuck in responding. It should produce the same output from the first run on the UART console.

[tnmysh]

Not sure what could be the issue here. I will have to setup and run demo.
I will be running for zcu102 board. I will update here once I do that (might take couple of weeks).

Meanwhile few things to try:

1. increase stack size in the demo see if it resolves the issue.
   

   openamp-system-reference/examples/zephyr/rpmsg_multi_services/src/main_remote.c

   Line 43 in 5386c24

   K_THREAD_STACK_DEFINE(thread_rp__client_stack, APP_TASK_STACK_SIZE);

2. Could you post /proc/interrupts on linux side?

3. Also cat /proc/interrupts output ?

[tnmysh]

• Could you post /proc/interrupts on linux side?

Sorry I mean /sys/bus/rpmsg/devices/ output ?

[olneumann]

interrupts before demo

xilinx:/lib/firmware# cat /proc/interrupts 
           CPU0       CPU1       CPU2       CPU3       
 11:      46862      13611       9083      10219     GICv2  30 Level     arch_timer
 14:          0          0          0          0     GICv2  67 Level     zynqmp-ipi
 15:          0          0          0          0     GICv2  58 Level     ffa60000.rtc
 16:          0          0          0          0     GICv2  59 Level     ffa60000.rtc
 17:          0          0          0          0     GICv2  88 Level     ams-irq
 18:          0          0          0          0     GICv2 155 Level     axi-pmon, axi-pmon
 19:          0          0          0          0     GICv2 175 Level     arm-pmu
 20:          0          0          0          0     GICv2 176 Level     arm-pmu
 21:          0          0          0          0     GICv2 177 Level     arm-pmu
 22:          0          0          0          0     GICv2 178 Level     arm-pmu
 23:        305          0          0          0     GICv2  54 Level     xuartps
 25:          0          0          0          0     GICv2 156 Level     zynqmp-dma
 26:          0          0          0          0     GICv2 157 Level     zynqmp-dma
 27:          0          0          0          0     GICv2 158 Level     zynqmp-dma
 28:          0          0          0          0     GICv2 159 Level     zynqmp-dma
 29:          0          0          0          0     GICv2 160 Level     zynqmp-dma
 30:          0          0          0          0     GICv2 161 Level     zynqmp-dma
 31:          0          0          0          0     GICv2 162 Level     zynqmp-dma
 32:          0          0          0          0     GICv2 163 Level     zynqmp-dma
 33:          0          0          0          0     GICv2 109 Level     zynqmp-dma
 34:          0          0          0          0     GICv2 110 Level     zynqmp-dma
 35:          0          0          0          0     GICv2 111 Level     zynqmp-dma
 36:          0          0          0          0     GICv2 112 Level     zynqmp-dma
 37:          0          0          0          0     GICv2 113 Level     zynqmp-dma
 38:          0          0          0          0     GICv2 114 Level     zynqmp-dma
 39:          0          0          0          0     GICv2 115 Level     zynqmp-dma
 40:          0          0          0          0     GICv2 116 Level     zynqmp-dma
 41:          0          0          0          0     GICv2 154 Level     fd4c0000.dma-controller
 42:          0          0          0          0     GICv2 151 Level     fd4a0000.display
 43:       1426          0          0          0     GICv2  52 Level     ff050000.spi
 44:      31138          0          0          0     GICv2  47 Level     ff0f0000.spi
 45:       1991          0          0          0     GICv2  89 Level     eth1, eth1
 46:          0          0          0          0     GICv2  91 Level     eth0, eth0
 47:          0          0          0          0     GICv2  57 Level     axi-pmon, axi-pmon
 48:       2845          0          0          0     GICv2  50 Level     cdns-i2c
 50:          0          0          0          0     GICv2  84 Edge      ff150000.watchdog
 51:      13677          0          0          0     GICv2  97 Level     xhci-hcd:usb1
 52:         93          0          0          0     GICv2 102 Level     xhci-hcd:usb3
 53:          0          0          0          0  zynq-gpio  12 Edge      fwuen
IPI0:       236        335        357        222       Rescheduling interrupts
IPI1:      4062      10788      16574       5163       Function call interrupts
IPI2:         0          0          0          0       CPU stop interrupts
IPI3:         0          0          0          0       CPU stop (for crash dump) interrupts
IPI4:         0          0          0          0       Timer broadcast interrupts
IPI5:         0          0          0          0       IRQ work interrupts
IPI6:         0          0          0          0       CPU wake-up interrupts
Err:          0

after first run:

xilinx:/lib/firmware# cat /proc/interrupts 
           CPU0       CPU1       CPU2       CPU3       
 11:      58602      17355      14249      13498     GICv2  30 Level     arch_timer
 14:        104          0          0          0     GICv2  67 Level     zynqmp-ipi

after second run:

xilinx:/lib/firmware# cat /proc/interrupts 
           CPU0       CPU1       CPU2       CPU3       
 11:      65500      18714      17040      14987     GICv2  30 Level     arch_timer
 14:        104          0          0          0     GICv2  67 Level     zynqmp-ipi

after third run:

xilinx:/lib/firmware# cat /proc/interrupts 
           CPU0       CPU1       CPU2       CPU3       
 11:      86821      20055      19411      16651     GICv2  30 Level     arch_timer
 14:        107          0          0          0     GICv2  67 Level     zynqmp-ipi

and the rpmsg devices:

xilinx:/lib/firmware# ls /sys/bus/rpmsg/devices/
virtio0.rpmsg-client-sample.-1.1024  virtio0.rpmsg-tty.-1.1025	virtio0.rpmsg_ns.53.53
virtio0.rpmsg-raw.-1.1026	     virtio0.rpmsg_ctrl.0.0

For the stack sizes I use:

#define APP_TASK_STACK_SIZE (2048)

#define MAX_TTY_EPT  2
#define MAX_RAW_EPT  2

/* Add 512 extra bytes for the TTY task stack for the "tx_buff" buffer. */
#define APP_TTY_TASK_STACK_SIZE (2048)
#define APP_RAW_TASK_STACK_SIZE (2048)

and

CONFIG_MAIN_STACK_SIZE=2028
CONFIG_HEAP_MEM_POOL_SIZE=2048

[tnmysh]

I can see devices are created and interrupt count is also increasing from 104 to 107 for third run. For second run I don't see interrupt count is incremented. So, even name service announcement failed for second run, but it happened for third run. I will have to attempt to reproduce this issue on my end to debug further.

I am wondering if name service announcement can happen then why zephyr should hang after that? No obvious reason I can think of.

[tnmysh]

Are you trying rpmsg-tty demo ? after second start / third start ?

[tnmysh]

Are you trying rpmsg-tty demo ? after second start / third start ?

Sorry I mean after third start? Because second start devices aren't even created.

[olneumann]

The output for the third run with the tty-demo:

cat /dev/ttyRPMSG0 &
echo "Hello Zephyr" >/dev/ttyRPMSG0

rpmsg_export_dev /dev/rpmsg_ctrl0 rpmsg-tty 257 -1
cat /dev/ttyRPMSG0 &
cat /dev/ttyRPMSG1 &
echo hello dev0 >/dev/ttyRPMSG0
echo hello dev1 >/dev/ttyRPMSG1

gives the bash error:

sh: echo: write error: Invalid argument

even though:

ls /dev/ttyRP*
/dev/ttyRPMSG0	/dev/ttyRPMSG1

and dmesg:

[  161.213460] remoteproc remoteproc0: powering up zynqmp-rpu:r5f-0
[  161.215355] remoteproc remoteproc0: Booting fw image firmware.elf, size 695096
[  161.218594] platform zynqmp-rpu:r5f-0: TCM carveout split mode atcm0 addr=ffe00000, da=0x0, size=0x10000
[  161.221785] platform zynqmp-rpu:r5f-0: TCM carveout split mode btcm0 addr=ffe20000, da=0x20000, size=0x10000
[  161.221800] remoteproc remoteproc0: reserved mem carveout memory addr=3ed00000, size=0x40000
[  161.221809] remoteproc remoteproc0: reserved mem carveout vdev0buffer addr=3ed48000, size=0x100000
[  161.221817] remoteproc remoteproc0: reserved mem carveout vdev0vring0 addr=3ed40000, size=0x4000
[  161.221826] remoteproc remoteproc0: reserved mem carveout vdev0vring1 addr=3ed44000, size=0x4000
[  161.222306] platform zynqmp-rpu:r5f-0: RPU boot addr 0x1034 from TCM.
[  161.222360] rproc-virtio rproc-virtio.3.auto: assigned reserved memory node vdev0buffer@3ed48000
[  161.222447] virtio_rpmsg_bus virtio0: buffers: va 000000006c3fd804, dma 0x000000003ed48000
[  161.222747] virtio_rpmsg_bus virtio0: rpmsg host is online
[  161.222769] rproc-virtio rproc-virtio.3.auto: registered virtio0 (type 7)
[  161.222776] remoteproc remoteproc0: remote processor zynqmp-rpu:r5f-0 is now up
[  161.242723] virtio_rpmsg_bus virtio0: From: 0x400, To: 0x35, Len: 40, Flags: 0, Reserved: 0
[  161.242750] rpmsg_virtio RX: 00 04 00 00 35 00 00 00 00 00 00 00 28 00 00 00  ....5.......(...
[  161.242759] rpmsg_virtio RX: 72 70 6d 73 67 2d 63 6c 69 65 6e 74 2d 73 61 6d  rpmsg-client-sam
[  161.242767] rpmsg_virtio RX: 70 6c 65 00 64 87 00 00 00 00 00 00 a7 25 00 00  ple.d........%..
[  161.242773] rpmsg_virtio RX: 00 04 00 00 00 00 00 00                          ........
[  161.242784] virtio_rpmsg_bus virtio0: creating channel rpmsg-client-sample addr 0x400
[  161.242938] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: new channel: 0x400 -> 0x400!
[  161.242950] rpmsg_client_sample virtio0.rpmsg-client-sample.-1.1024: TX From 0x400, To 0x400, Len 12, Flags 0, Reserved 0
[  161.242963] rpmsg_virtio TX: 00 04 00 00 00 04 00 00 00 00 00 00 0c 00 00 00  ................
[  161.242970] rpmsg_virtio TX: 68 65 6c 6c 6f 20 77 6f 72 6c 64 21              hello world!
[  161.243020] virtio_rpmsg_bus virtio0: Received 1 messages
[  161.243028] remoteproc remoteproc0: data not found for vqid=1
[  161.249982] virtio_rpmsg_bus virtio0: From: 0x401, To: 0x35, Len: 40, Flags: 0, Reserved: 0
[  161.250003] rpmsg_virtio RX: 01 04 00 00 35 00 00 00 00 00 00 00 28 00 00 00  ....5.......(...
[  161.250012] rpmsg_virtio RX: 72 70 6d 73 67 2d 74 74 79 00 00 00 00 00 00 00  rpmsg-tty.......
[  161.250019] rpmsg_virtio RX: 5c 86 00 00 64 87 00 00 00 00 00 00 a7 25 00 00  \...d........%..
[  161.250025] rpmsg_virtio RX: 01 04 00 00 00 00 00 00                          ........
[  161.250037] virtio_rpmsg_bus virtio0: creating channel rpmsg-tty addr 0x401
[  161.250322] virtio_rpmsg_bus virtio0: Received 1 messages
[  161.250332] remoteproc remoteproc0: data not found for vqid=1
[  161.257871] virtio_rpmsg_bus virtio0: From: 0x402, To: 0x35, Len: 40, Flags: 0, Reserved: 0
[  161.257897] rpmsg_virtio RX: 02 04 00 00 35 00 00 00 00 00 00 00 28 00 00 00  ....5.......(...
[  161.257905] rpmsg_virtio RX: 72 70 6d 73 67 2d 72 61 77 00 00 00 00 00 00 00  rpmsg-raw.......
[  161.257914] rpmsg_virtio RX: b4 85 00 00 64 87 00 00 00 00 00 00 a7 25 00 00  ....d........%..
[  161.257920] rpmsg_virtio RX: 02 04 00 00 00 00 00 00                          ........
[  161.257932] virtio_rpmsg_bus virtio0: creating channel rpmsg-raw addr 0x402
[  161.261733] virtio_rpmsg_bus virtio0: Received 1 messages
[  161.261747] remoteproc remoteproc0: data not found for vqid=1
[  191.252469] rpmsg_tty virtio0.rpmsg-tty.-1.1025: TX From 0x401, To 0x401, Len 13, Flags 0, Reserved 0
[  191.252499] rpmsg_virtio TX: 01 04 00 00 01 04 00 00 00 00 00 00 0d 00 00 00  ................
[  191.252507] rpmsg_virtio TX: 48 65 6c 6c 6f 20 5a 65 70 68 79 72 0a           Hello Zephyr.
[  197.318115] rpmsg_tty virtio0.rpmsg-tty.257.-1: TX From 0x101, To 0x35, Len 40, Flags 0, Reserved 0
[  197.318142] rpmsg_virtio TX: 01 01 00 00 35 00 00 00 00 00 00 00 28 00 00 00  ....5.......(...
[  197.318152] rpmsg_virtio TX: 72 70 6d 73 67 2d 74 74 79 00 00 00 00 00 00 00  rpmsg-tty.......
[  197.318160] rpmsg_virtio TX: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
[  197.318166] rpmsg_virtio TX: 01 01 00 00 00 00 00 00                          ........
[  210.491064] rpmsg_tty virtio0.rpmsg-tty.-1.1025: TX From 0x401, To 0x401, Len 11, Flags 0, Reserved 0
[  210.491094] rpmsg_virtio TX: 01 04 00 00 01 04 00 00 00 00 00 00 0b 00 00 00  ................
[  210.491102] rpmsg_virtio TX: 68 65 6c 6c 6f 20 64 65 76 30 0a                 hello dev0.
[  213.526813] rpmsg_tty virtio0.rpmsg-tty.257.-1: invalid addr (src 0x101, dst 0xffffffff)

[tnmysh]

From #52 I looked at zephyr overlay.

  zephyr,sram = &tcm;

Could you remove above ? That wasn't introduced in original overlay for qemu_cortex_r5.
I think originally it was one of the ocm node not tcm.

I am not sure if it will resolve the issue or not, but worth the try.

In above logs, I see that zephyr stopped responding completely. May be zephyr crashed because TCM is assigned instead of OCM.
If it doesn't resolve the issue, I will get back once I have this exact setup.

[tnmysh]

From #52 I looked at zephyr overlay.

  zephyr,sram = &tcm;

Could you remove above ? That wasn't introduced in original overlay for qemu_cortex_r5. I think originally it was one of the ocm node not tcm.

I am not sure if it will resolve the issue or not, but worth the try.

In above logs, I see that zephyr stopped responding completely. May be zephyr crashed because TCM is assigned instead of OCM. If it doesn't resolve the issue, I will get back once I have this exact setup.

Ah! now I remember that later it was introduced as sram node: https://github.com/OpenAMP/openamp-system-reference/blob/main/examples/zephyr/rpmsg_multi_services/boards/zynqmp_r5_override.dtsi

However, this was tested on zephyr 3.5.0.

Looks like I will have to replicate this setup and test it with zephyr 3.6. I will get back once I do that.

[tnmysh]

I noticed something else too:

So Linux device-tree configures cluster in split mode:

xlnx,cluster-mode = <0>; // split mode

This will automatically configure TCM in split mode too. i.e. 128K TCM per core.

However, Zephyr is trying to use 256K TCM:

tcm: memory@0 {
			compatible = "mmio-sram";
			reg = <0 0x40000>;
		};

I think this is not correct. Zephyr should use only 128K TCM.
I believe try following in above TCM node:

reg = <0 0x20000>;

It's possible that zephyr code doesn't fit completely in TCM. You might have to change linker script and put some of the text section in rproc_0_fw_image address space from linux device-tree.

[tnmysh]

So far zephyr overlay is tested only for lockstep mode. Split mode work is still in progress.

[olneumann]

In the KV260 Board description from Zephyr they write:

Although Flash, DDR and OCM memory regions are defined in the DTS file, all the code plus data of the application will be loaded in the sram0 region, which points to the DDR memory. The ocm0 memory area is currently available for usage, although nothing is placed there by default.

But for me the assignment and effect of the zephyr,sram property is not clear at all. Since the sram0 node is by default:

sram0: memory@0 {
	compatible = "mmio-sram";
	reg = <0 DT_SIZE_M(64)>;
};

When I load the firmware via the xlnx_r5_remoteproc driver I understand that it is placed at the address 0x3ed0 0000. Does this address has to be taken into account by Zephyr? In the demo here they override the sram0 node accordingly. But that is maybe not needed anymore with the newer implementation of the xlnx_r5_remoteproc driver, because this one is placing the firmware by default at the TCM memory.

Regarding the firmware size I thing for this demo we do not have a size problem, since:

Memory region         Used Size  Region Size  %age Used
           FLASH:          0 GB         0 GB
             RAM:       51492 B       128 KB     39.29%
             OCM:          0 GB       256 KB      0.00%
        IDT_LIST:          0 GB        32 KB      0.00%