search

OpenAMP / openamp-system-reference

End-to-end system reference material showcasing all the different aspects of OpenAMP, on multiple vendor platforms.
Other
16 stars 15 forks source link

rpmsg_multi_services demo runs only once after reboot #56

Open olneumann opened 1 week ago

olneumann commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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. https://github.com/OpenAMP/openamp-system-reference/blob/5386c24ae376f35a760fd07550d959bb5ca51c5c/examples/zephyr/rpmsg_multi_services/src/main_remote.c#L43

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

3) Also cat /proc/interrupts output ?

tnmysh commented 1 week ago
  • Could you post /proc/interrupts on linux side?

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

olneumann commented 1 week ago
interrupts before demo ``` bash 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 commented 1 week ago

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 commented 1 week ago

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

tnmysh commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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 commented 1 week ago

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

olneumann commented 1 week ago

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%
tnmysh commented 1 week ago

0x3ed0_0000 address isn't used for zephyr firmware. It's only used for XLNX baremetal firmware as of now. Only 128K should be used per core for split mode. I don't know what will be the effect if r5 core0 uses r5 core1's TCM in split mode.

I tested zephyr firmware (zephyr 3.6) on zcu102 qemu board and repeat start stop is working there. However, It's too soon to concluded anything as it's not real hardware.

tnmysh commented 1 week ago

I tested with R5 cluster configured in lockstep mode on qemu. Still need to see behavior in split mode.

Meanwhile for experiment change cluster mode to lockstep mode in linux and see if it changes anything. I don't have any solution for this issue as of now, I have to go for trial and error method here, until I have setup.

olneumann commented 5 days ago

If I uncomment the two following threads in the demo and only run the thread_raw_data:

int main(void)
{
    printk("Starting application threads!\n");
    k_thread_create(&thread_mng_data, thread_mng_stack, APP_TASK_STACK_SIZE,
            (k_thread_entry_t)rpmsg_mng_task,
            NULL, NULL, NULL, K_PRIO_COOP(8), 0, K_NO_WAIT);
    // k_thread_create(&thread_rp__client_data, thread_rp__client_stack, APP_TASK_STACK_SIZE,
    //      (k_thread_entry_t)app_rpmsg_client_sample,
    //      NULL, NULL, NULL, K_PRIO_COOP(7), 0, K_NO_WAIT);
    // k_thread_create(&thread_tty_data, thread_tty_stack, APP_TTY_TASK_STACK_SIZE,
    //      (k_thread_entry_t)app_rpmsg_tty,
    //      NULL, NULL, NULL, K_PRIO_COOP(7), 0, K_NO_WAIT);
    k_thread_create(&thread_raw_data, thread_raw_stack, APP_TASK_STACK_SIZE * 2,
            (k_thread_entry_t)app_rpmsg_raw,
            NULL, NULL, NULL, K_PRIO_COOP(7), 0, K_NO_WAIT);

    return 0;
}

I get after pinging the dev/rpmsg0 device the error:

[15:06:46:332] *** Booting Zephyr OS build v3.7.0-3935-g9403b08512eb ***
[15:06:46:339] Starting application threads!
[15:06:46:340] OpenAMP[remote]  linux responder demo started
[15:06:46:356] D: platform_ipm_callback: msg received from mb 0
[15:06:46:365] OpenAMP[remote] Linux raw data responder started
[15:06:46:365] D: mailbox_notify: msg received
[15:06:46:365] OpenAMP[remote] create a endpoint 0x0400
[15:06:46:381] OpenAMP[remote] create a endpoint 0x0001
[15:07:03:157] D: platform_ipm_callback: msg received from mb 0
[15:07:03:162] 
[15:07:03:162] *** Booting Zephyr OS build v3.7.0-3935-g9403b08512eb ***
[15:07:03:168] Starting application threads!
[15:07:03:170] OpenAMP[remote]  linux responder demo started
[15:07:03:174] E: ***** DATA ABORT *****
[15:07:03:179] E: Permission Fault @ 0x00000000
[15:07:03:179] E: r0/a1:  0x00008000  r1/a2:  0x00000000  r2/a3:  0x00000000
[15:07:03:186] E: r3/a4:  0x00000000 r12/ip:  0x0000c318 r14/lr:  0x00005245
[15:07:03:190] E:  xpsr:  0x200001bf
[15:07:03:192] E: s[ 0]:  0x009040c0  s[ 1]:  0x0009027a  s[ 2]:  0x2210c523  s[ 3]:  0x3408a0a0
[15:07:03:199] E: s[ 4]:  0x08400514  s[ 5]:  0x080810c8  s[ 6]:  0x88282240  s[ 7]:  0x270008a0
[15:07:03:206] E: s[ 8]:  0x18280490  s[ 9]:  0x0a909680  s[10]:  0xa4000104  s[11]:  0x24022600
[15:07:03:216] E: s[12]:  0x9300840a  s[13]:  0x14418004  s[14]:  0xc8804200  s[15]:  0x160a981c
[15:07:03:221] E: fpscr:  0x00000000
[15:07:03:223] E: Faulting instruction address (r15/pc): 0x00005232
[15:07:03:228] E: >>> ZEPHYR FATAL ERROR 48: Unknown error on CPU 0
[15:07:03:233] E: Current thread: 0x80c0 (unknown)
[15:07:03:237] E: Halting system

I do this directly after booting and I do not start the firmware twice (seems to be loaded twice from the UART log).