AM620-Q1: During the RPMSG communication process, the SOC side occasionally fails to receive data sent from the M4.

xiao-an lei

Part Number: AM620-Q1

Tool/software:

During the RPMSG communication process, the SOC side occasionally fails to receive data sent from the M4. This issue becomes more frequent after waking up from MCU ONLY mode sleep.

The observed phenomenon is that:

1. the SOC side can send data normally and the M4 can receive it,

2. the data sent from the M4 is not received by the SOC side.

We are using the select function to monitor the RPMSG file descriptor (fd) every 3 seconds, which consistently returns a value of 0 which means reach the timeout 3s.

The communication can be restored by executing the following commands:

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

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

Please help analyze the root cause of this issue.

2 months ago

0 Nick Saulnier 2 months ago

TI__Guru** 101250 points

Hello,

Apologies for the delayed responses here.

1) Did you resolve the issue, or are you still debugging?

2) Is this related to the other e2e threads with the low power mode cycling tests, where sometimes after coming back up out of low power mode, the M4F stops responding to the low power mode transition message from Linux? Or is this related to a different test?

3) "This issue becomes more frequent after waking up from MCU ONLY mode sleep." ---> Please tell me more about this. Does the issue ONLY occur after going into MCU ONLY low power mode, and then come back up out of low power mode? Or does the issue sometimes occur during regular Linux runtime, without going into a low power mode?

4) What have you done to debug what the M4F core is doing right before it enters a bad state?

Regards,

Nick

0 xiao-an lei 2 months ago in reply to Nick Saulnier

Intellectual 420 points

Hi Nick:

1). we still debugging

2). the debug test is still a low power mode cycling tests, but we use MCU only, When this happend, we can see the last wakeup is not doing work, but we use USB0 to wakeup it.

3). We not sure ths bug occur ONLY in MCU ONLY LPM, but in this test mode , the happend rate will rise and easy to repeat.

4). we use MCU UART to see the MCU running state, it output the right information

0 xiao-an lei 2 months ago

Intellectual 420 points

Hi experter:

we have found more debug information here:

1. we use a SOC APP to comunicate with M4F by rpmsg.(you can use rpmsg_char_simple instead)

2. Enter MCU ONLY mode

3. MCU wakeup the SOC by IPC way in 10 seconds later.(must suspend for a while, if only 1 seconds, this happend hardly)

4. repeat 2 & 3 steps until it cant wake up the SOC, i use a suspend script to do this as show bellow.

5. at this time, i guess the IPC channel happend something wrong, as a result, it cannot wakeup SOC by IPC way.

6. as IPC wakeup way does not work, we use USB0 wake up instead.

7. after the SOC was wakeup to run, we can our APP with RPMSG recevied a return value from 'select' means timeout. BUT we can still send msg to MCU, as the 'send' function did not return error and MCU did recieved the message.

the suspend script here:

echo 100 > /sys/devices/system/cpu/cpu0/power/pm_qos_resume_latency_us
while true; do
 cnt=$((cnt+1))
 echo $cnt > /cache/sleeptimes
 echo "===========[$(date)] the $cnt times to sleep ======================"
 usleep 10000
 echo mem > /sys/power/state
 usleep 100000
 echo "========== wake up now ==========="
done

the dmesg output from SOC are here:

in my oppinion:

the first error happend at [ 537.023842] where output:

> k3-m4-rproc 5000000.m4fss: k3_m4_suspend: timedout waiting for rproc completion event

at this time , the IPC has been wrong. so we cannot wakeup by IPC in this suspend/resume cycle, then I use USB disconnect/connect to wakeup,

> ti-sci 44043000.system-controller: wakeup source: 0x70, pin: 255, mode: 1, time: 0

and we can see in SOC running status:

> [ 537.527250] [17:56:15.226] mng: no keep-alive msg received from MCU, last keep-alive time : 530585ms, current time: 537303ms

this means out APP have not received from MCU. As i did not stop the suspend script, then it repeat suspend and resume untill i stop at [ 549.332041]

then we recevied "rx: no data" in 3 seconds later, we first try to reopen the rpmsg by usespace rpmsg lib to restore it but failed,

another 3s elapsed, we stop and restart MCU by /sys/class/remoteproc/remoteproc0/state.

as you see in [ 558.276285], it report timedout to stop means we still can received from MCU.

> k3-m4-rproc 5000000.m4fss: k3_m4_rproc_stop: timedout waiting for rproc completion event

when the MCU start again, and our APP reopen the rpmsg after the MCU running, it restore comunications at [ 564.940432]

> [17:56:56.796] MCU: RPmsg: Inquire TBOX version retry 1, next retry in 6 s

[  524.860303] PM: suspend entry (deep)
[  525.002916] Filesystems sync: 0.138 seconds
[  525.013849] Freezing user space processes
[  525.020118] Freezing user space processes completed (elapsed 0.002 seconds)
[  525.027185] OOM killer disabled.
[  525.030435] Freezing remaining freezable tasks
[  525.036155] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  525.043724] printk: Suspending console(s) (use no_console_suspend to debug)
[  525.061994] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  525.064424] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  525.068439] omap8250 2800000.serial: PM domain pd:146 will not be powered off
[  525.069237] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  525.069380] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  525.085514] Disabling non-boot CPUs ...
[  525.087764] psci: CPU1 killed (polled 0 ms)
[  525.089023] Enabling non-boot CPUs ...
[  525.089464] Detected VIPT I-cache on CPU1
[  525.089521] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  525.089592] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  525.090798] CPU1 is up
[  525.091295] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  525.091308] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  525.105617] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  525.112088] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  525.575828] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  525.584185] OOM killer enabled.
[  525.587329] Restarting tasks ... done.
[  525.609647] random: crng reseeded on system resumption
[  525.629300] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  525.648785] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  525.657417] PM: suspend exit
[  525.791680] PM: suspend entry (deep)
[  525.906881] Filesystems sync: 0.111 seconds
[  525.914122] Freezing user space processes
[  525.920091] Freezing user space processes completed (elapsed 0.001 seconds)
[  525.927104] OOM killer disabled.
[  525.930334] Freezing remaining freezable tasks
[  525.936043] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  525.943480] printk: Suspending console(s) (use no_console_suspend to debug)
[  525.958301] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  525.961534] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  525.966111] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  525.966252] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  525.979277] Disabling non-boot CPUs ...
[  525.981553] psci: CPU1 killed (polled 0 ms)
[  525.982411] Enabling non-boot CPUs ...
[  525.982849] Detected VIPT I-cache on CPU1
[  525.982908] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  525.982978] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  525.984165] CPU1 is up
[  525.984961] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  525.984981] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  525.999208] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  526.005888] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  526.462625] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  526.462647] OOM killer enabled.
[  526.462650] Restarting tasks ... done.
[  526.480896] random: crng reseeded on system resumption
[  526.486950] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  526.493169] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  526.500083] PM: suspend exit
[  526.646248] PM: suspend entry (deep)
[  526.743939] Filesystems sync: 0.093 seconds
[  526.749103] Freezing user space processes
[  526.755302] Freezing user space processes completed (elapsed 0.001 seconds)
[  526.762315] OOM killer disabled.
[  526.765561] Freezing remaining freezable tasks
[  526.771278] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  526.778689] printk: Suspending console(s) (use no_console_suspend to debug)
[  526.794703] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  526.797940] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  526.802517] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  526.802661] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  526.812603] Disabling non-boot CPUs ...
[  526.814847] psci: CPU1 killed (polled 0 ms)
[  526.815775] Enabling non-boot CPUs ...
[  526.816222] Detected VIPT I-cache on CPU1
[  526.816281] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  526.816350] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  526.817553] CPU1 is up
[  526.818057] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  526.818071] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  526.832882] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  526.839539] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  527.296225] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  527.304589] OOM killer enabled.
[  527.304593] Restarting tasks ... done.
[  527.307756] random: crng reseeded on system resumption
[  527.327803] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  527.347841] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  527.357374] PM: suspend exit
[  527.514735] PM: suspend entry (deep)
[  527.598101] Filesystems sync: 0.079 seconds
[  527.603443] Freezing user space processes
[  527.609122] Freezing user space processes completed (elapsed 0.001 seconds)
[  527.616143] OOM killer disabled.
[  527.619361] Freezing remaining freezable tasks
[  527.625104] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  527.632512] printk: Suspending console(s) (use no_console_suspend to debug)
[  527.646501] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  527.649753] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  527.654351] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  527.654491] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  527.666044] Disabling non-boot CPUs ...
[  527.668316] psci: CPU1 killed (polled 4 ms)
[  527.669321] Enabling non-boot CPUs ...
[  527.669755] Detected VIPT I-cache on CPU1
[  527.669814] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  527.669885] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  527.671102] CPU1 is up
[  527.671601] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  527.671616] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  527.686189] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  527.710734] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  528.147613] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  528.155984] OOM killer enabled.
[  528.159129] Restarting tasks ... done.
[  528.165027] random: crng reseeded on system resumption
[  528.175134] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  528.184517] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  528.191830] PM: suspend exit
[  528.321665] PM: suspend entry (deep)
[  528.413465] Filesystems sync: 0.088 seconds
[  528.418933] Freezing user space processes
[  528.427263] Freezing user space processes completed (elapsed 0.008 seconds)
[  528.434263] OOM killer disabled.
[  528.437585] Freezing remaining freezable tasks
[  528.443316] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  528.450726] printk: Suspending console(s) (use no_console_suspend to debug)
[  528.465077] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  528.468164] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  528.476683] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  528.476827] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  528.489652] Disabling non-boot CPUs ...
[  528.491905] psci: CPU1 killed (polled 0 ms)
[  528.492963] Enabling non-boot CPUs ...
[  528.493402] Detected VIPT I-cache on CPU1
[  528.493459] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  528.493528] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  528.494712] CPU1 is up
[  528.495214] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  528.495227] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  528.509370] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  528.533732] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  528.970607] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  528.978955] OOM killer enabled.
[  528.978959] Restarting tasks ... done.
[  528.986128] random: crng reseeded on system resumption
[  528.997291] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  529.008328] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  529.015926] PM: suspend exit
[  529.150432] PM: suspend entry (deep)
[  529.260905] Filesystems sync: 0.106 seconds
[  529.266007] Freezing user space processes
[  529.268199] Freezing user space processes completed (elapsed 0.002 seconds)
[  529.277439] OOM killer disabled.
[  529.280678] Freezing remaining freezable tasks
[  529.286429] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  529.293842] printk: Suspending console(s) (use no_console_suspend to debug)
[  529.308300] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  529.311546] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  529.316168] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  529.316307] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  529.333398] Disabling non-boot CPUs ...
[  529.335666] psci: CPU1 killed (polled 0 ms)
[  529.336790] Enabling non-boot CPUs ...
[  529.337232] Detected VIPT I-cache on CPU1
[  529.337288] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  529.337359] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  529.338550] CPU1 is up
[  529.339048] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  529.339062] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  529.353466] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  529.377692] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  529.814551] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  529.822908] OOM killer enabled.
[  529.822912] Restarting tasks ... done.
[  529.830717] random: crng reseeded on system resumption
[  529.844088] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  529.849872] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  529.857256] PM: suspend exit
[  529.987723] PM: suspend entry (deep)
[  530.126549] Filesystems sync: 0.134 seconds
[  530.133159] Freezing user space processes
[  530.139196] Freezing user space processes completed (elapsed 0.001 seconds)
[  530.146220] OOM killer disabled.
[  530.149465] Freezing remaining freezable tasks
[  530.155223] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  530.162652] printk: Suspending console(s) (use no_console_suspend to debug)
[  530.181213] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  530.184052] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  530.188674] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  530.188817] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  530.197137] Disabling non-boot CPUs ...
[  530.199397] psci: CPU1 killed (polled 0 ms)
[  530.200728] Enabling non-boot CPUs ...
[  530.201161] Detected VIPT I-cache on CPU1
[  530.201217] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  530.201286] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  530.202475] CPU1 is up
[  530.202974] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  530.202987] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  530.218268] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  530.242846] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  530.679726] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  530.688073] OOM killer enabled.
[  530.688078] Restarting tasks ... done.
[  530.696486] random: crng reseeded on system resumption
[  530.713948] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  530.726089] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  530.733915] PM: suspend exit
[  530.865569] PM: suspend entry (deep)
[  530.952564] Filesystems sync: 0.083 seconds
[  530.957897] Freezing user space processes
[  530.960074] Freezing user space processes completed (elapsed 0.002 seconds)
[  530.969454] OOM killer disabled.
[  530.972686] Freezing remaining freezable tasks
[  530.978449] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  530.985899] printk: Suspending console(s) (use no_console_suspend to debug)
[  531.000897] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  531.003972] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  531.008531] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  531.008675] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  531.020921] Disabling non-boot CPUs ...
[  531.023195] psci: CPU1 killed (polled 0 ms)
[  531.024301] Enabling non-boot CPUs ...
[  531.024737] Detected VIPT I-cache on CPU1
[  531.024791] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  531.024862] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  531.026051] CPU1 is up
[  531.026549] ti-sci 44043000.system-controller: wakeup source: 0x90, pin: 255, mode: 1, time: 0
[  531.026563] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x90
[  531.041032] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  531.057411] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  531.057448] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  531.513143] OOM killer enabled.
[  531.516287] Restarting tasks ... done.
[  531.521825] random: crng reseeded on system resumption
[  531.535442] k3-m4-rproc 5000000.m4fss: Core is on in resume
[  531.545029] k3-m4-rproc 5000000.m4fss: received echo reply from 5000000.m4fss
[  531.552294] PM: suspend exit
[  531.693244] PM: suspend entry (deep)
[  531.779409] Filesystems sync: 0.082 seconds
[  531.784928] Freezing user space processes
[  531.790642] Freezing user space processes completed (elapsed 0.001 seconds)
[  531.797706] OOM killer disabled.
[  531.800958] Freezing remaining freezable tasks
[  531.806822] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  531.814257] printk: Suspending console(s) (use no_console_suspend to debug)
[  531.829789] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  531.833017] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  531.840475] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  531.840622] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  537.023842] k3-m4-rproc 5000000.m4fss: k3_m4_suspend: timedout waiting for rproc completion event
[  537.027249] Disabling non-boot CPUs ...
[  537.029563] psci: CPU1 killed (polled 0 ms)
[  537.030532] Enabling non-boot CPUs ...
[  537.030969] Detected VIPT I-cache on CPU1
[  537.031024] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  537.031096] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  537.032322] CPU1 is up
[  537.032823] ti-sci 44043000.system-controller: wakeup source: 0x70, pin: 255, mode: 1, time: 0
[  537.032837] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x70
[  537.046775] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  537.083419] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  537.517066] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  537.525410] OOM killer enabled.
[  537.525413] Restarting tasks ... 
[  537.527250] [17:56:15.226] mng: no keep-alive msg received from MCU, last keep-alive time : 530585ms, current time: 537303ms
[  537.544864] done.
[  537.546838] random: crng reseeded on system resumption
[  537.556622] PM: suspend exit
[  537.701472] PM: suspend entry (deep)
[  537.793705] Filesystems sync: 0.088 seconds
[  537.798994] Freezing user space processes
[  537.804728] Freezing user space processes completed (elapsed 0.001 seconds)
[  537.811747] OOM killer disabled.
[  537.814967] Freezing remaining freezable tasks
[  537.820714] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  537.828135] printk: Suspending console(s) (use no_console_suspend to debug)
[  537.844786] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  537.847002] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  537.851528] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  537.851669] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  542.911788] k3-m4-rproc 5000000.m4fss: k3_m4_suspend: timedout waiting for rproc completion event
[  542.915143] Disabling non-boot CPUs ...
[  542.917411] psci: CPU1 killed (polled 0 ms)
[  542.918413] Enabling non-boot CPUs ...
[  542.918850] Detected VIPT I-cache on CPU1
[  542.918909] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  542.918979] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  542.920228] CPU1 is up
[  542.920728] ti-sci 44043000.system-controller: wakeup source: 0x70, pin: 255, mode: 1, time: 0
[  542.920741] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x70
[  542.934806] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  542.971425] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  543.405145] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  543.405161] OOM killer enabled.
[  543.416639] Restarting tasks ... done.
[  543.426082] random: crng reseeded on system resumption
[  543.435122] PM: suspend exit
[  543.569187] PM: suspend entry (deep)
[  543.653126] Filesystems sync: 0.080 seconds
[  543.658956] Freezing user space processes
[  543.664895] Freezing user space processes completed (elapsed 0.005 seconds)
[  543.672045] OOM killer disabled.
[  543.675323] Freezing remaining freezable tasks
[  543.681147] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
[  543.688563] printk: Suspending console(s) (use no_console_suspend to debug)
[  543.714344] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 179: state: 1: ret 0
[  543.715781] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 178: state: 1: ret 0
[  543.720346] ti-sci 44043000.system-controller: ti_sci_cmd_set_device_constraint: device: 117: state: 1: ret 0
[  543.720493] ti-sci 44043000.system-controller: ti_sci_cmd_set_latency_constraint: latency: 100: state: 1: ret 0
[  548.799709] k3-m4-rproc 5000000.m4fss: k3_m4_suspend: timedout waiting for rproc completion event
[  548.803101] Disabling non-boot CPUs ...
[  548.805369] psci: CPU1 killed (polled 0 ms)
[  548.806386] Enabling non-boot CPUs ...
[  548.806820] Detected VIPT I-cache on CPU1
[  548.806877] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[  548.806946] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[  548.808184] CPU1 is up
[  548.808684] ti-sci 44043000.system-controller: wakeup source: 0x70, pin: 255, mode: 1, time: 0
[  548.808697] ti-sci 44043000.system-controller: ti_sci_resume: wakeup source: 0x70
[  548.822815] am65-cpsw-nuss 8000000.ethernet: set new flow-id-base 19
[  548.829408] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  549.294679] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  549.294700] OOM killer enabled.
[  549.306212] Restarting tasks ... done.
[  549.321860] random: crng reseeded on system resumption
[  549.332041] PM: suspend exit
[  551.578360] [17:56:43.435] mng: rpmsg: rx: no data
[  551.583504] [17:56:43.440] mng: rpmsg: no data, try to reinit rpmsg
[  555.097013] [17:56:46.953] mng: rpmsg: rx: no data
[  555.102213] [17:56:46.958] mng: rpmsg: no data, try to stop MCU, and then start MCU to restore rpmsg
[  555.189715] [17:56:47.046] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.381153] [17:56:47.237] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.397261] [17:56:47.253] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.411569] [17:56:47.268] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.425830] [17:56:47.282] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.439863] [17:56:47.296] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.453725] [17:56:47.310] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.467563] [17:56:47.324] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.481386] [17:56:47.338] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.495244] [17:56:47.352] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.509046] [17:56:47.365] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.522840] [17:56:47.379] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.536675] [17:56:47.393] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.550487] [17:56:47.407] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.564333] [17:56:47.421] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.578147] [17:56:47.434] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.591946] [17:56:47.448] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.605762] [17:56:47.462] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.619569] [17:56:47.476] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.633370] [17:56:47.490] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.647226] [17:56:47.504] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.661048] [17:56:47.517] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.674874] [17:56:47.531] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.688661] [17:56:47.545] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.702473] [17:56:47.559] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.716303] [17:56:47.573] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.730113] [17:56:47.586] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.743982] [17:56:47.600] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.757805] [17:56:47.614] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.771607] [17:56:47.628] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.785418] [17:56:47.642] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.799244] [17:56:47.656] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.813116] [17:56:47.669] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.827045] [17:56:47.683] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.840977] [17:56:47.697] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.854809] [17:56:47.711] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.868630] [17:56:47.725] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.882457] [17:56:47.739] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.896302] [17:56:47.753] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.910120] [17:56:47.766] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.923968] [17:56:47.780] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.937828] [17:56:47.794] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.951704] [17:56:47.808] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.965560] [17:56:47.822] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.979406] [17:56:47.836] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  555.993221] [17:56:47.850] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.007211] [17:56:47.863] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.021137] [17:56:47.877] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.035011] [17:56:47.891] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.048980] [17:56:47.905] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.062884] [17:56:47.919] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.076751] [17:56:47.933] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.090578] [17:56:47.947] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.104422] [17:56:47.961] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.118278] [17:56:47.975] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.132144] [17:56:47.988] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.146043] [17:56:48.002] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.159943] [17:56:48.016] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.173779] [17:56:48.030] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.187645] [17:56:48.044] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.201621] [17:56:48.058] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.215537] [17:56:48.072] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.229402] [17:56:48.086] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.243233] [17:56:48.100] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.257237] [17:56:48.113] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.271064] [17:56:48.127] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.284891] [17:56:48.141] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.298715] [17:56:48.155] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.312522] [17:56:48.169] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.326352] [17:56:48.183] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.340250] [17:56:48.197] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.354085] [17:56:48.210] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.367906] [17:56:48.224] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.381692] [17:56:48.238] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.395492] [17:56:48.252] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.409318] [17:56:48.266] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.423205] [17:56:48.279] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.437077] [17:56:48.293] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.450919] [17:56:48.307] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.464790] [17:56:48.321] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.478639] [17:56:48.335] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.492517] [17:56:48.349] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.506346] [17:56:48.363] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.520232] [17:56:48.376] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.534084] [17:56:48.390] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.547960] [17:56:48.404] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.561827] [17:56:48.418] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.575687] [17:56:48.432] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.589505] [17:56:48.446] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.603355] [17:56:48.460] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.617204] [17:56:48.473] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.631095] [17:56:48.487] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.644928] [17:56:48.501] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.658798] [17:56:48.515] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.672665] [17:56:48.529] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.686511] [17:56:48.543] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.700337] [17:56:48.557] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.714173] [17:56:48.570] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.728031] [17:56:48.584] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.741866] [17:56:48.598] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.755772] [17:56:48.612] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.769605] [17:56:48.626] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.783465] [17:56:48.640] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.797281] [17:56:48.654] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.811113] [17:56:48.667] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.824942] [17:56:48.681] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.838784] [17:56:48.695] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.852638] [17:56:48.709] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.866517] [17:56:48.723] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.880361] [17:56:48.737] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.894151] [17:56:48.750] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.907970] [17:56:48.764] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.921828] [17:56:48.778] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.935694] [17:56:48.792] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.949521] [17:56:48.806] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.963372] [17:56:48.820] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.977223] [17:56:48.833] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  556.991059] [17:56:48.847] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.004901] [17:56:48.861] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.018731] [17:56:48.875] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.032640] [17:56:48.889] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.046446] [17:56:48.903] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.060325] [17:56:48.917] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.074191] [17:56:48.930] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.088062] [17:56:48.944] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.101913] [17:56:48.958] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.115805] [17:56:48.972] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.129678] [17:56:48.986] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.143566] [17:56:49.000] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.157478] [17:56:49.014] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.171379] [17:56:49.028] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.185261] [17:56:49.042] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.199212] [17:56:49.055] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.213092] [17:56:49.069] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.226938] [17:56:49.083] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.240759] [17:56:49.097] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.254599] [17:56:49.111] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.268478] [17:56:49.125] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.282362] [17:56:49.139] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.296221] [17:56:49.152] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.310130] [17:56:49.166] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.323994] [17:56:49.180] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.337846] [17:56:49.194] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.351757] [17:56:49.208] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.365608] [17:56:49.222] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.379472] [17:56:49.236] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.393320] [17:56:49.250] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.407184] [17:56:49.263] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.421080] [17:56:49.277] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.434924] [17:56:49.291] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.448840] [17:56:49.305] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.462749] [17:56:49.319] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.476626] [17:56:49.333] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.490471] [17:56:49.347] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.504370] [17:56:49.361] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.518187] [17:56:49.374] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.532019] [17:56:49.388] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.545881] [17:56:49.402] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.559827] [17:56:49.416] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.573705] [17:56:49.430] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.587550] [17:56:49.444] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.601388] [17:56:49.458] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.615231] [17:56:49.471] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.629084] [17:56:49.485] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.642929] [17:56:49.499] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.656840] [17:56:49.513] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.670676] [17:56:49.527] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.684521] [17:56:49.541] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.698368] [17:56:49.555] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.712247] [17:56:49.569] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.726120] [17:56:49.582] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.740004] [17:56:49.596] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.753864] [17:56:49.610] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.767796] [17:56:49.624] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.781678] [17:56:49.638] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.795508] [17:56:49.652] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.809373] [17:56:49.666] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.823236] [17:56:49.679] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.837121] [17:56:49.693] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.850976] [17:56:49.707] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.864855] [17:56:49.721] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.878727] [17:56:49.735] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.892621] [17:56:49.749] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.906477] [17:56:49.763] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.920358] [17:56:49.777] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.934228] [17:56:49.790] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.948085] [17:56:49.804] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.961970] [17:56:49.818] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.975937] [17:56:49.832] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  557.989882] [17:56:49.846] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.003786] [17:56:49.860] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.017664] [17:56:49.874] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.031507] [17:56:49.888] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.045370] [17:56:49.902] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.059369] [17:56:49.916] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.073311] [17:56:49.930] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.087192] [17:56:49.943] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.101066] [17:56:49.957] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.114874] [17:56:49.971] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.128716] [17:56:49.985] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.142628] [17:56:49.999] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.156529] [17:56:50.013] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.170490] [17:56:50.027] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.184402] [17:56:50.041] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.198330] [17:56:50.055] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.212258] [17:56:50.068] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.226150] [17:56:50.082] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.240033] [17:56:50.096] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.253905] [17:56:50.110] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.267877] [17:56:50.124] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.276285] k3-m4-rproc 5000000.m4fss: k3_m4_rproc_stop: timedout waiting for rproc completion event
[  558.282002] [17:56:50.138] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.285969] remoteproc remoteproc0: stopped remote processor 5000000.m4fss
[  558.299488] [17:56:50.156] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.307962] remoteproc remoteproc0: powering up 5000000.m4fss
[  558.316638] remoteproc remoteproc0: Booting fw image am62-mcu-m4f0_0-fw, size 1010784
[  558.325218] [17:56:50.181] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.336153] rproc-virtio rproc-virtio.5.auto: assigned reserved memory node m4f-dma-memory@9cb00000
[  558.340096] [17:56:50.196] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.351360] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  558.355946] virtio_rpmsg_bus virtio0: rpmsg host is online
[  558.362044] virtio_rpmsg_bus virtio0: creating channel ti.ipc4.ping-pong addr 0xd
[  558.370009] rproc-virtio rproc-virtio.5.auto: registered virtio0 (type 7)
[  558.375139] virtio_rpmsg_bus virtio0: creating channel rpmsg_chrdev addr 0xe
[  558.382313] [17:56:50.238] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.393912] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  558.399541] remoteproc remoteproc0: remote processor 5000000.m4fss is now up
[  558.416038] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  558.426118] [17:56:50.282] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.434614] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports
[  558.448689] [17:56:50.305] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.462828] [17:56:50.319] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.476873] [17:56:50.333] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.490833] [17:56:50.347] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.504805] [17:56:50.361] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.518723] [17:56:50.375] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.532643] [17:56:50.389] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.546528] [17:56:50.403] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.560410] [17:56:50.417] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.574272] [17:56:50.431] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.588138] [17:56:50.444] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.602027] [17:56:50.458] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.615941] [17:56:50.472] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.629819] [17:56:50.486] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.643701] [17:56:50.500] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.657570] [17:56:50.514] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.671449] [17:56:50.528] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.685338] [17:56:50.542] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.699271] [17:56:50.555] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.713184] [17:56:50.569] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.727031] [17:56:50.583] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.740988] [17:56:50.597] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.754862] [17:56:50.611] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.768751] [17:56:50.625] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.782652] [17:56:50.639] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.796592] [17:56:50.653] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.810473] [17:56:50.667] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.824346] [17:56:50.681] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.838237] [17:56:50.694] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.852139] [17:56:50.708] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.866025] [17:56:50.722] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.879936] [17:56:50.736] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.893844] [17:56:50.750] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.907747] [17:56:50.764] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.921584] [17:56:50.778] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.935459] [17:56:50.792] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.949358] [17:56:50.806] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.963238] [17:56:50.819] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.977154] [17:56:50.833] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  558.991028] [17:56:50.847] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.004951] [17:56:50.861] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.018851] [17:56:50.875] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.032769] [17:56:50.889] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.046770] [17:56:50.903] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.060665] [17:56:50.917] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.074558] [17:56:50.931] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.088441] [17:56:50.945] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.102380] [17:56:50.959] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.116278] [17:56:50.973] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.130191] [17:56:50.986] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.144157] [17:56:51.000] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.158059] [17:56:51.014] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.171997] [17:56:51.028] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.185905] [17:56:51.042] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.199985] [17:56:51.056] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.213926] [17:56:51.070] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.227841] [17:56:51.084] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.241702] [17:56:51.098] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.255663] [17:56:51.112] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.269530] [17:56:51.126] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.283405] [17:56:51.140] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.297316] [17:56:51.154] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.311214] [17:56:51.167] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.325148] [17:56:51.181] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.339083] [17:56:51.195] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.352993] [17:56:51.209] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.366785] virtio_rpmsg_bus virtio0: msg received with no recipient
[  559.366891] [17:56:51.223] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.387166] [17:56:51.243] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.401188] [17:56:51.257] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.415127] [17:56:51.271] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.429029] [17:56:51.285] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.442912] [17:56:51.299] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.456807] [17:56:51.313] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.470690] [17:56:51.327] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.484549] [17:56:51.341] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.498456] [17:56:51.355] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.512390] [17:56:51.369] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.526346] [17:56:51.383] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.540271] [17:56:51.396] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.554239] [17:56:51.410] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.568188] [17:56:51.424] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.582099] [17:56:51.438] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.596056] [17:56:51.452] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.609977] [17:56:51.466] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.623910] [17:56:51.480] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.637821] [17:56:51.494] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.651757] [17:56:51.508] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.665643] [17:56:51.522] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.679575] [17:56:51.536] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.693493] [17:56:51.550] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.707444] [17:56:51.564] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.721406] [17:56:51.578] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.735331] [17:56:51.592] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.749211] [17:56:51.605] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.763107] [17:56:51.619] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.777020] [17:56:51.633] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.790905] [17:56:51.647] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.804865] [17:56:51.661] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.818788] [17:56:51.675] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.832780] [17:56:51.689] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.846691] [17:56:51.703] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.860612] [17:56:51.717] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.874495] [17:56:51.731] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.888408] [17:56:51.745] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.902351] [17:56:51.759] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.916303] [17:56:51.773] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.930205] [17:56:51.786] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.944114] [17:56:51.800] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.957985] [17:56:51.814] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.971916] [17:56:51.828] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.985793] [17:56:51.842] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  559.999758] [17:56:51.856] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.013700] [17:56:51.870] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.027672] [17:56:51.884] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.041624] [17:56:51.898] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.055539] [17:56:51.912] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.069508] [17:56:51.926] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.083489] [17:56:51.940] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.097472] [17:56:51.954] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.111522] [17:56:51.968] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.125538] [17:56:51.982] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.139465] [17:56:51.996] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.153459] [17:56:52.010] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.167426] [17:56:52.024] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.181368] [17:56:52.038] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.195390] [17:56:52.052] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.209407] [17:56:52.066] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.223335] [17:56:52.080] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.237273] [17:56:52.093] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.251210] [17:56:52.107] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.265162] [17:56:52.121] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.279077] [17:56:52.135] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.293040] [17:56:52.149] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.306980] [17:56:52.163] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.320908] [17:56:52.177] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.334863] [17:56:52.191] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.348790] [17:56:52.205] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.362715] [17:56:52.219] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.376650] [17:56:52.233] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.376787] virtio_rpmsg_bus virtio0: msg received with no recipient
[  560.390518] [17:56:52.247] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.405416] [17:56:52.262] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.419385] [17:56:52.276] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.433382] [17:56:52.290] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.447327] [17:56:52.304] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.461237] [17:56:52.317] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.475140] [17:56:52.331] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.489050] [17:56:52.345] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.503025] [17:56:52.359] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.516989] [17:56:52.373] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.530917] [17:56:52.387] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.544830] [17:56:52.401] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.558732] [17:56:52.415] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.572635] [17:56:52.429] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.586788] [17:56:52.443] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.600795] [17:56:52.457] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.614782] [17:56:52.471] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.628722] [17:56:52.485] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.642676] [17:56:52.499] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.656593] [17:56:52.513] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.670521] [17:56:52.527] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.684501] [17:56:52.541] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.698457] [17:56:52.555] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.712391] [17:56:52.569] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.726326] [17:56:52.583] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.740261] [17:56:52.596] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.754195] [17:56:52.610] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.768202] [17:56:52.624] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.782133] [17:56:52.638] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.796036] [17:56:52.652] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.809989] [17:56:52.666] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.823941] [17:56:52.680] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.837920] [17:56:52.694] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.851901] [17:56:52.708] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.865817] [17:56:52.722] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.879785] [17:56:52.736] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.893726] [17:56:52.750] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.907778] [17:56:52.764] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.921680] [17:56:52.778] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.935597] [17:56:52.792] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.949533] [17:56:52.806] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.963487] [17:56:52.820] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.977431] [17:56:52.834] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  560.991425] [17:56:52.848] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.005426] [17:56:52.862] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.019416] [17:56:52.876] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.033351] [17:56:52.890] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.047272] [17:56:52.903] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.061237] [17:56:52.917] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.075255] [17:56:52.931] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.089183] [17:56:52.945] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.103156] [17:56:52.959] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.117124] [17:56:52.973] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.131075] [17:56:52.987] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.145024] [17:56:53.001] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.159021] [17:56:53.015] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.173012] [17:56:53.029] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.186934] [17:56:53.043] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.200997] [17:56:53.057] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.214981] [17:56:53.071] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.228959] [17:56:53.085] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.242922] [17:56:53.099] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.256835] [17:56:53.113] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.270779] [17:56:53.127] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.284729] [17:56:53.141] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.298650] [17:56:53.155] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.312639] [17:56:53.169] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.326606] [17:56:53.183] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.341018] [17:56:53.197] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.355222] [17:56:53.211] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.369462] [17:56:53.226] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.383396] [17:56:53.240] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.391861] virtio_rpmsg_bus virtio0: msg received with no recipient
[  561.401391] [17:56:53.257] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.415400] [17:56:53.272] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.424152] [17:56:53.280] mng: rpmsg: rx: can't read data from rpmsg for 3s, try to reinit rpmsg
[  561.429436] [17:56:53.286] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.447135] [17:56:53.303] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.461574] [17:56:53.318] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.476545] [17:56:53.333] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.491804] [17:56:53.348] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.506013] [17:56:53.362] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.520135] [17:56:53.376] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.534149] [17:56:53.390] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.548339] [17:56:53.404] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.562374] [17:56:53.419] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.576371] [17:56:53.433] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.590328] [17:56:53.447] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.604332] [17:56:53.460] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.618348] [17:56:53.474] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.632328] [17:56:53.489] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.646299] [17:56:53.502] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.660239] [17:56:53.516] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.674153] [17:56:53.530] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.688108] [17:56:53.544] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.702110] [17:56:53.558] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.716099] [17:56:53.572] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.730027] [17:56:53.586] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.744003] [17:56:53.600] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.757931] [17:56:53.614] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.771928] [17:56:53.628] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.785926] [17:56:53.642] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.799903] [17:56:53.656] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.813902] [17:56:53.670] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.827918] [17:56:53.684] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.841899] [17:56:53.698] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.855916] [17:56:53.712] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.869913] [17:56:53.726] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.883872] [17:56:53.740] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.897816] [17:56:53.754] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.911852] [17:56:53.768] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  561.925784] [17:56:53.782] mng: rpmsg: tx: write rpmsg dev failed through rpmsg char dev fd
[  564.940432] [17:56:56.796] MCU: RPmsg: Inquire TBOX version retry 1, next retry in 6 s
[  568.754449] [17:57:00.610] Signal: Continued by SIGCONT, WDT started!
[  568.768549] [17:57:00.624] Signal: Quit by Signal: 15
[  568.775750] [17:57:00.632] tbox_manager: Log Safely Quit: reason: User!
[  570.306836] virtio_rpmsg_bus virtio0: msg received with no recipient
[  570.476794] virtio_rpmsg_bus virtio0: msg received with no recipient
[  570.506793] virtio_rpmsg_bus virtio0: msg received with no recipient
[  570.606796] virtio_rpmsg_bus virtio0: msg received with no recipient
[  570.706778] virtio_rpmsg_bus virtio0: msg received with no recipient
[  571.006775] virtio_rpmsg_bus virtio0: msg received with no recipient
[  571.106775] virtio_rpmsg_bus virtio0: msg received with no recipient
[  571.486767] virtio_rpmsg_bus virtio0: msg received with no recipient
[  571.906782] virtio_rpmsg_bus virtio0: msg received with no recipient
[  572.106775] virtio_rpmsg_bus virtio0: msg received with no recipient
[  575.506782] rpmsg_recv_single: 9 callbacks suppressed

WHY THE IPC cant work somethimes?

In normal work mode ( dont do suspend/resume test, just running for a long while), it will also happended but less and rarely.

with this TEST step it happen every 100~200 cycle times

0 Gibbs Shih 2 months ago in reply to xiao-an lei

TI__Expert 5285 points

Hi, xiao-an

Summarize your question & background,

(1) Your board only works between NORMAL operation mode (A53+M4) and MCU only mode (M4).

(2) Your board have "multiple WAKUP source" which trigger wakeup event from MCU LPM, "two" source as below,

a). MCU code sent "SOC_triggerMcuLpmWakeup()" : Which is used to generate MCU IPC interrupt to DM R5 to wake up main domain from MCU LPM.

b). USB I/O : Related code write in Linux DTS

About item a). we have an stress test, because we want to make sure MCU can wake up A53 by sending RPMsg wakeup event SOC_triggerMcuLpmWakeup() in MCU LPM "for each time", more discussion follow this thread,

RE: AM620-Q1: MCU Only 3 minute reset after TIFS timeout

Your Story :

Once you found A53 can not wakeup by RPMSG wakeup event (SOC_triggerMcuLpmWakeup) in MCU LPM, you try to use USB I/O wakeup A53 (Linux).

After success wakeup up by USB, you found RPMSG only TX success to MCU, but MCU(M4) sent to A53 failed? Pls confirm

Thanks

Gibbs

0 xiao-an lei 2 months ago in reply to Gibbs Shih

Intellectual 420 points

Hi Gibbs:

> (1) Your board only works between NORMAL operation mode (A53+M4) and MCU only mode (M4).

Yes.

> (2) Your board have "multiple WAKUP source" which trigger wakeup event from MCU LPM, "two" source as below,

Yes.

> After success wakeup up by USB, you found RPMSG only TX success to MCU, but MCU(M4) sent to A53 failed? Pls confirm

Yes, after this days we study. we have found MCU does not send messages to A53 in our codes beacause we have no chance to change our send flag as we meet a blocking call.

here is the something news:

we found the reason of " k3-m4-rproc 5000000.m4fss: k3_m4_suspend: timedout waiting for rproc completion event" is the MCU running status is blocked at code bellow:

status = Sciclient_lpmGetNextHostState(SystemP_WAIT_FOREVER, &nextHostState);

when We send "RP_MBOX_SUSPEND_SYSTEM" msg to MCU from SOC, MCU have recived it actually, But when MCU wants to get the next host state by call the SCI API up, it cannot go on. So MCU has no chance to excute SOC_triggerMcuLpmWakeup yet. that is why IPC look like do not work.

So maybe we should focus on why the API "Sciclient_lpmGetNextHostState" really block forever !

0 Gibbs Shih 2 months ago in reply to xiao-an lei

TI__Expert 5285 points

Hi, Xiao-an

Lots of informattion to be clarificaed

Share some thing what I observered,

(1) Pls make sure you remove display node in DTS completely, because follow another thread discussion, I suspect wakeup crash (reboot) which "could be" have some relation ship with DSS or GPU,

Your error message as below,

[  537.083419] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@0/ports
[  537.517066] OF: graph: no port node found in /bus@f0000/dss@30200000/oldi-txes/oldi@1/ports

(2) This error message should be not follow "gracefule shutdown" in M4, even we still not know the root cause.

k3-m4-rproc 5000000.m4fss: k3_m4_suspend: timedout waiting for rproc completion event

(3) How do you make sure "RP_MBOX_SUSPEND_SYSTEM" message sent success? Does it mean "mail_box_send" return no error?

static int k3_m4_suspend(struct rproc *rproc)
{
	struct k3_m4_rproc *kproc = rproc->priv;
	unsigned long msg = RP_MBOX_SUSPEND_SYSTEM;
	unsigned long to = msecs_to_jiffies(5000);
	struct dev_pm_qos_request qos_req;
	struct device *dev = kproc->dev;
	int ret;

	kproc->suspend_status = 0;
	reinit_completion(&kproc->suspend_comp);

	ret = mbox_send_message(kproc->mbox, (void *)msg);
	if (ret < 0) {
		dev_err(dev, "PM mbox_send_message failed: %d\n", ret);
		return ret;
	}

	ret = wait_for_completion_timeout(&kproc->suspend_comp, to);
	if (ret == 0) {
		dev_err(dev, "%s: timedout waiting for rproc completion event\n", __func__);
		// Set constraint to keep the device on
		dev_pm_qos_add_request(kproc->dev, &qos_req, DEV_PM_QOS_RESUME_LATENCY, 0);
		return 0;
	};

(4) How about disable "SystemP_WAIT_FOREVER" in Sciclient_lpmGetNextHostState()?

Ref. https://software-dl.ti.com/mcu-plus-sdk/esd/AM62X/latest/exports/docs/api_guide_am62x/group__SCICLIENT__FMW__LPM__IF.html#ga57860e66a2f13065b44e7e255d066d36

Hi, Nick

Here is one question from my side,

(1) Do you think MCU only LPM also need "graceful shutdown" procedure? If the answer is yes, how to check it in code?

Thank You.

Gibbs

0 Nick Saulnier 2 months ago in reply to Gibbs Shih

TI__Guru** 101250 points

Hello Gibbs,

The Linux remoteproc driver should send an MCU Only low power mode message to the M4F, and then the M4F executes code based on that message. Let me show you what code is doing that.

https://github.com/TexasInstruments/mcupsdk-core-k3/blob/k3_main/examples/drivers/ipc/ipc_rpmsg_echo_linux/ipc_rpmsg_echo.c

This is where the M4F creates a task that waits for a suspend message from Linux, and then starts waiting for a UART input:

void lpm_mcu_suspend_task(void* args)
{
...
#if defined(ENABLE_MCU_ONLY_LPM)
    status = SemaphoreP_constructBinary(&gLpmResumeSem, 0);
    DebugP_assert(SystemP_SUCCESS == status);
#endif

    while (1)
    {
        uint8_t nextHostState;

        /* Wait for suspend from linux */
        SemaphoreP_pend(&gLpmSuspendSem, SystemP_WAIT_FOREVER);
        ...
         switch (nextHostState)
        {
        ...
#if defined(ENABLE_MCU_ONLY_LPM)
            case TISCI_MSG_VALUE_HOST_STATE_ON:
                gbSuspended = 1u;

                /* Print before sending ACK, otherwise IO isolation is enabled while printing */
                DebugP_log("[IPC RPMSG ECHO] Suspend request to MCU-only mode received \r\n");
                DebugP_log("[IPC RPMSG ECHO] Press a single key on this terminal to resume the kernel from MCU only mode \r\n");

// this is where we notify Linux that M4F has received the MCU only LPM message
                IpcNotify_sendMsg(gbSuspendRemotecoreID, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_SUSPEND_AUTO, 1u);
                lpm_mcu_wait_for_uart();

You can see the place where the M4F actually receives the mailbox message from Linux here:

void ipc_rp_mbox_callback(uint16_t remoteCoreId, uint16_t clientId, uint32_t msgValue, void *args)
{
    if (clientId == IPC_NOTIFY_CLIENT_ID_RP_MBOX)
    {
    ...
        else if (msgValue == IPC_NOTIFY_RP_MBOX_SUSPEND_SYSTEM) /* Suspend request received from linux during LPM suspend */
        {
            gbSuspendRemotecoreID = remoteCoreId;

// this semaphore is what tells the lpm_mcu_suspend_task that we got the mailbox
            SemaphoreP_post(&gLpmSuspendSem);
        }

Regards,

Nick

0 Walter Wang 2 months ago in reply to Gibbs Shih

Prodigy 200 points

Hi Gibbs,

We have clarified the issue of "k3-m4-rproc 5000000.m4fss: k3_m4_suspend: timedout waiting for rproc completion event".

The cause is that the M4 core is stuck at "status = Sciclient_lpmGetNextHostState(SystemP_WAIT_FOREVER, &nextHostState);".

We now plan to place the reply to ipc_notify in the callback function.

May we ask if there will be any other unknown issues with this approach?

And why isn't the R5 core replying to the requests from the M4 core?

Thanks

void ipc_rp_mbox_callback(uint16_t remoteCoreId, uint16_t clientId, uint32_t msgValue, void *args)
{
     if (clientId == IPC_NOTIFY_CLIENT_ID_RP_MBOX)
    {
        if (msgValue == (uint32_t)IPC_NOTIFY_RP_MBOX_SHUTDOWN) /* Shutdown request from the remotecore */
        {
            gbShutdownRemotecoreID = remoteCoreId;
            trigger_shutdown();
			IpcNotify_sendMsg(gbSuspendRemotecoreID, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_SUSPEND_ACK, 1u);
        }
        else if (msgValue == (uint32_t)IPC_NOTIFY_RP_MBOX_SUSPEND_SYSTEM) /* Suspend request from Linux. This is send when suspending to MCU only LPM */
        {
        	SUSPEND_cnt++;
        	gbSuspended = 1U;
            gbSuspendRemotecoreID = remoteCoreId;
            SemaphoreP_post(&gLpmSuspendSem);
			IpcNotify_sendMsg(gbSuspendRemotecoreID, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_SUSPEND_AUTO, 1u);
			DebugP_memLogWriterPause();
        }
        else if (msgValue == (uint32_t)IPC_NOTIFY_RP_MBOX_ECHO_REQUEST) /* This message is received after resuming from the MCU only LPM. */
        {
        	gbSuspended = 0u;
        	REQUEST_cnt++;
            IpcNotify_sendMsg(remoteCoreId, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_ECHO_REPLY, 1u);
            DebugP_shmLogWriterResume();
        }
    }
}


void lpm_mcu_suspend_proc(void)
{
    int32_t status;
	static uint8_t InitFlag = 0U;
	uint8_t nextHostState;

	if (InitFlag == 0U)
	{
		status = SemaphoreP_constructBinary(&gLpmSuspendSem, 0);
	    DebugP_assert(SystemP_SUCCESS == status);
	    status = SemaphoreP_constructBinary(&gLpmResumeSem, 0);
	    DebugP_assert(SystemP_SUCCESS == status);
		InitFlag = 1U;
	}

	/* Wait for suspend from linux */
	status = SemaphoreP_pend(&gLpmSuspendSem, SystemP_NO_WAIT);
	if (status == SystemP_SUCCESS)
	{
		status = Sciclient_lpmGetNextHostState(0x50, &nextHostState);
		if (status != SystemP_SUCCESS)
		{
			DebugStr("[IPC RPMSG ECHO] Failed to get next system state. Canceling suspend.\r\n");
			IpcNotify_sendMsg(gbSuspendRemotecoreID, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_SUSPEND_CANCEL, 1u);
		}
		switch (nextHostState)
		{
			case TISCI_MSG_VALUE_HOST_STATE_OFF:
				//IpcNotify_sendMsg(gbSuspendRemotecoreID, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_SUSPEND_ACK, 1u);
				break;

			case TISCI_MSG_VALUE_HOST_STATE_ON:
		#if 0
				gbSuspended = 1u;

				/* Print before sending ACK, otherwise IO isolation is enabled while printing */
				//DebugStr("[IPC RPMSG ECHO] Suspend request to MCU-only mode received \r\n");
				// DebugStr("[IPC RPMSG ECHO] Press a sinlge key on this terminal to resume the kernel from MCU only mode \r\n");

				IpcNotify_sendMsg(gbSuspendRemotecoreID, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_SUSPEND_AUTO, 1u);
				DebugP_memLogWriterPause();
		#endif
				break;

			case TISCI_MSG_VALUE_HOST_STATE_INVALID:
			default:
				IpcNotify_sendMsg(gbSuspendRemotecoreID, IPC_NOTIFY_CLIENT_ID_RP_MBOX, IPC_NOTIFY_RP_MBOX_SUSPEND_CANCEL, 1u);
				break;
		}

		if (gbShutdown == 1u)
		{
			SemaphoreP_destruct(&gLpmSuspendSem);
			SemaphoreP_destruct(&gLpmResumeSem);
		}
	}
}

0 Nick Saulnier 2 months ago in reply to Walter Wang

TI__Guru** 101250 points

Hello Walter,

I see that in your Sciclient_lpmGetNextHostState(), you replaced SystemP_WAIT_FOREVER with 0x50.

Just to confirm: in the "not working" case, were you using SystemP_WAIT_FOREVER? Or were you using 0x50?

Regards,

Nick

0 Walter Wang 2 months ago in reply to Nick Saulnier

Prodigy 200 points

Hi Nick,

Under abnormal circumstances, this parameter is SystemP_WAIT_FOREVER.

Thanks

0 Nick Saulnier 2 months ago in reply to Walter Wang

TI__Guru** 101250 points

Hello Walter,

Thank you for confirming.

Right now, I suspect something is going wrong in the DM R5F

That makes me suspect that the DM R5F core is getting into a bad state. Then the DM R5F core is not responding to Sciclient_lpmGetNextHostState(), so then the M4F does not respond to the Linux low power transition request.

Let's double check your M4F code just to make sure

Please send your full M4F test code to me through Gibbs. That way I can look it over and make sure there are not any obvious issues.

Debugging DM R5F

Anshu sent some guidance on getting the DM R5F logs in this other thread:

https://e2e.ti.com/support/processors-group/processors/f/processors-forum/1534178/am620-q1-mcu-only-3-minute-reset-after-tifs-timeout/5921504

We should probably also check the logs for this fail case.

Regards,

Nick

0 Nick Saulnier 2 months ago in reply to Nick Saulnier

TI__Guru** 101250 points

Checking the DM R5F current state

After the low power mode transition fails, do you start to see any messages in your terminal about mailbox communication failing? If so, that could be a sign that the DM R5F has entered a bad state. In that case, the mailbox messages would be failing because the DM R5F was not replying to them.

Did you still see low power mode fails after changing the M4F timeout value to 0x50?

If the DM R5F is going into a bad state, then the low power mode transition would still fail, even after you add a timeout value of 0x50. Please attach the terminal output if you are still seeing a low power mode transition fail after the M4F replies back.

Regards,

Nick

0 Walter Wang 2 months ago in reply to Nick Saulnier

Prodigy 200 points

Hi Nick,

1.Due to information security policies, we cannot distribute the entire code externally.

In previous replies, I have already posted the key code modifications.

2.After changing it to 0x50, AM62 no longer gets stuck at "Sciclient_lpmGetNextHostState()";

instead, it can proceed with sleep and wake-up cycles normally (including successful subsequent sleep-wake stress tests).

3.Previously, when RPMSG communication failed, we could restore it by restarting M4 using the command

"echo 'stop' > /sys/class/remoteproc/remoteproc0/state" (since M4 was stuck in wait_forever).

However, now when RPMSG communication fails, the command "echo 'stop' > /sys/class/remoteproc/remoteproc0/state" can no longer be sent to M4.

We have not connected the R5 serial port to check logs. Currently, we are testing the issue where

RPMSG communication fails intermittently under high-temperature conditions.

Thanks

0 Nick Saulnier 1 month ago in reply to Walter Wang

TI__Guru** 101250 points

Hello Walter,

Setting Support Expectations

I understand being unable to share the M4F code with us.

I have already found and fixed several issues in the previous code snippets that you shared. I am nervous that you might have other bugs in code snippets that you did not share. I cannot help you debug if the issue is caused by the code that you did not share.

Do you still see low power mode fails after changing the M4F timeout value to 0x50?

I am going to summarize what I think you are telling me with 2) and 3). Please correct me if any of this is wrong:

* After changing the M4F timeout to 0x50, the board can do sleep / wake cycles indefinitely. The board is ALWAYS able to go into a low power mode.

Please tell me more about 3): echo stop can no longer be sent to the M4F

Is this observed on the same test as the sleep / wake test? Or is this a different test?

Please share your terminal output when RPMsg communication fails, and when you send the "echo stop" command.

Regards,

Nick

0 Walter Wang 1 month ago in reply to Nick Saulnier

Prodigy 200 points

Hi Nick,

After changing it to 0x50, the issue of failure in sleep wake-up has only been significantly reduced.

However, the problem of automatic reset after 3 minutes still occurs after more than 10,000 sleep wake-up cycles

(the log is available in another issue). I have stopped further testing on sleep wake-up and am currently testing the problem

of occasional disconnection in rpmsg.

https://e2e.ti.com/support/processors-group/processors/f/processors-forum/1534178/am620-q1-mcu-only-3-minute-reset-after-tifs-timeout

Thanks

0 Nick Saulnier 1 month ago in reply to Walter Wang

TI__Guru** 101250 points

Hello Walter,

Understood. We can circle back to this discussion later after the other issues are resolved then.

Is there a different thread for the "occasional disconnection in RPMsg"? Or is that the "3 minute reset" thread?

Regards,

Nick

0 Walter Wang 1 month ago in reply to Nick Saulnier

Prodigy 200 points

Hi Nick,

This is the discussion thread about the probabilistic communication failure of RPMSG.

Previously, the communication failure occurred because the MCU got stuck in SystemP_WAIT_FOREVER during sleep wake-up.

Now, after changing it to 0x50, the issue of RPMSG communication failure during sleep wake-up has no longer occurred.

However, there is still a problem where RPMSG disconnects automatically during normal operation,

which is more likely to be reproduced under high-temperature conditions. We are currently testing to address this issue.

Thanks

Processors

Processors forum

AM620-Q1: During the RPMSG communication process, the SOC side occasionally fails to receive data sent from the M4.