Linux/AM5728: TIOVX kernel boot issue

yu chen

Expert 1465 points

Part Number: AM5728
Other Parts Discussed in Thread: ADS7846

Tool/software: Linux

Hi,

I am using ti-processor-sdk-linux-am57xx-evm-04.03.00.05.

when i change the dsp firmware as openvx,the system is high probability let the system hang or crash.

the log is similar as Aither.

https://e2e.ti.com/support/arm/sitara_arm/f/791/p/700972/2609888#2609888

when the dsp firmware is opencl,everything is ok.

I found some release notes about this,

LCPD-9481 P4-Low Sometime the system hangs while loading the rpmsg rpc modules

LCPD-4699 P4-Low rpmsg-rpc: kernel crash during error recovery with dynamic debug traces enabled IPC

this will call the system hang or crash?which happen high probability.

Can you give me some advice?

Thanks.

over 7 years ago

0 Rex Chang over 7 years ago

TI__Guru 50170 points

Hi, CY,

Could you elaborate which example (or which exact binary of OpenVX) you are running? What were the steps you did to cause the system hang/crash? Were you trying to run the same example over and over again, or when run it after system comes up it fails sometimes? Can you post your failure logs ?

Rex

0 yu chen over 7 years ago in reply to Rex Chang

Expert 1465 points

Hi,Rex

Thanks for your reply.

Yes,i run the same example over and over again,it hang or crash many times.

Actually,I just change the firmware as dra7-dsp1-fw.xe66.openvx/dra7-dsp2-fw.xe66.openvx.

the system will hang or crash at three solution.

1.the system will crash at booting time,when i change the firmware and hardware reboot(i do not try software reboot many times),here is the log.

[ 11.023873] remoteproc remoteproc0: Booting fw image dra7-ipu1-fw.xem4, size 4747084
[ 11.031751] omap-iommu 58882000.mmu: 58882000.mmu: version 2.1
[ 11.046903] virtio_rpmsg_bus virtio1: rpmsg host is online
[ 11.052450] remoteproc remoteproc0: registered virtio1 (type 7)
[ 11.058394] remoteproc remoteproc0: remote processor 58820000.ipu is now up
[ 11.066484] virtio_rpmsg_bus virtio1: creating channel rpmsg-client-sample addr 0x32
[ 11.075174] virtio_rpmsg_bus virtio1: creating channel rpmsg-client-sample addr 0x33
[ 11.083057] virtio_rpmsg_bus virtio1: creating channel rpmsg-omx addr 0x3c
[ 11.090047] virtio_rpmsg_bus virtio1: creating channel rpmsg-rpc addr 0x65
[ OK ] Listening on dropbear.socket.
[ OK ] Listening on D-Bus System Message Bus Socket.
[ 11.164696] xhci-hcd xhci-hcd.2.auto: xHCI Host Controller
[ 11.170221] xhci-hcd xhci-hcd.2.auto: new USB bus registered, assigned bus number 3
[ 11.178861] remoteproc remoteproc3: powering up 41000000.dsp
[ 11.178869] remoteproc remoteproc3: Booting fw image dra7-dsp2-fw.xe66, size 8814504
[ 11.185931] omap-iommu 41501000.mmu: 41501000.mmu: version 3.0
** 2942 printk messages dropped ** [ 11.235786] [<c02829f8>] (irq_thread) from [<c024b004>] (kthread+0x100/0x118)
** 2517 printk messages dropped ** [ 11.246331] CPU: 0 PID: 27 Comm: irq/23-l3-app-i Tainted: G W O 4.9.65-rt23-06389-g750859d #30
** 3299 printk messages dropped ** [ 11.260220] r8:00000000 r7:00000000 r6:00000000 r5:c024af04 r4:ef23b2c0
** 2642 printk messages dropped ** [ 11.271323] [<c020b558>] (show_stack) from [<c04d3dbc>] (dump_stack+0x8c/0xa0)
** 3857 printk messages dropped ** [ 11.287694] Modules linked in: rtc_ds1307 rtc_omap rtc_palmas extcon_palmas omap_remoteproc virtio_rpmsg_bus rpmsg_core remoteproc sch_fq_codel uio_module_drv(O) uio ftdi_sio usbserial gdbserverproxy(O) cryptodev(O) cmemk(O)
** 8921 printk messages dropped ** [ 11.325729] r4:ef23b280
** 1328 printk messages dropped ** [ 11.331348] CPU: 0 PID: 27 Comm: irq/23-l3-app-i Tainted: G W O 4.9.65-rt23-06389-g750859d #30
** 4104 printk messages dropped ** [ 11.348885] r10:c0282790 r9:ef23b280 r8:ef067e00 r7:00000001 r6:00000000 r5:ef067e00
** 2661 printk messages dropped ** [ 11.360386] [<c0282790>] (irq_forced_thread_fn) from [<c0282b1c>] (irq_thread+0x124/0x1f8)
** 6562 printk messages dropped ** [ 11.388930] Modules linked in: ad5724r_spi snd_soc_tlv320aic3x rtc_ds1307 rtc_omap rtc_palmas extcon_palmas omap_remoteproc virtio_rpmsg_bus rpmsg_core remoteproc sch_fq_codel uio_module_drv(O) uio ftdi_sio usbserial gdbserverproxy(O) cryptodev(O) cmemk(O)
** 8508 printk messages dropped ** [ 11.426345] r10:00000000 r9:00000000 r8:c02829f8 r7:ef23b280 r6:ef27a000 r5:ef23b2c0
** 2738 printk messages dropped ** [ 11.438016] r10:c0282790 r9:ef23b280 r8:ef067e00 r7:00000001 r6:00000000 r5:ef067e00
** 2604 printk messages dropped ** [ 11.449291] r4:ef23b280
** 1306 printk messages dropped ** [ 11.454896] [<c04d3d30>] (dump_stack) from [<c022da90>] (__warn+0xec/0x104)
** 2383 printk messages dropped ** [ 11.465090] [<c022daac>] (warn_slowpath_fmt) from [<c0503d1c>] (l3_interrupt_handler+0x25c/0x36c)
** 2845 printk messages dropped ** [ 11.477181] CPU: 0 PID: 27 Comm: irq/23-l3-app-i Tainted: G W O 4.9.65-rt23-06389-g750859d #30
** 2965 printk messages dropped ** [ 11.489854] 44000000.ocp:L3 Custom Error: MASTER DSP2_DMA TARGET L4_PER3_P3 (Read): Data Access in User mode during Functional access
** 6676 printk messages dropped ** [ 11.518746] [<c020b558>] (show_stack) from [<c04d3dbc>] (dump_stack+0x8c/0xa0)
** 3136 printk messages dropped ** [ 11.533049] [<c04d3d30>] (dump_stack) from [<c022da90>] (__warn+0xec/0x104)
** 5 printk messages dropped ** [ 11.533068] r4:80080003
[ 11.533073] [<c0503ac0>] (l3_interrupt_handler) from [<c02827b8>] (irq_forced_thread_fn+0x28/0x7c)
[ 11.533077] r10:c0282790 r9:ef23b280 r8:ef067e00 r7:00000001 r6:00000000 r5:ef067e00
[ 11.533078] r4:ef23b280
[ 11.533082] [<c0282790>] (irq_forced_thread_fn) from [<c0282b1c>] (irq_thread+0x124/0x1f8)
[ 11.533085] r7:00000001 r6:00000000 r5:ef27a000 r4:ef23b2a4
[ 11.533090] [<c02829f8>] (irq_thread) from [<c024b004>] (kthread+0x100/0x118)
[ 11.533093] r10:00000000 r9:00000000 r8:c02829f8 r7:ef23b280 r6:ef27a000 r5:ef23b2c0
[ 11.533095] r4:00000000
[ 11.533099] [<c024af04>] (kthread) from [<c0207c90>] (ret_from_fork+0x14/0x24)
[ 11.533103] r8:00000000 r7:00000000 r6:00000000 r5:c024af04 r4:ef23b2c0
[ 11.533104] ---[ end trace 0000000000000a0c ]---
[ 11.533112] ------------[ cut here ]------------
[ 11.533118] WARNING: CPU: 0 PID: 27 at drivers/bus/omap_l3_noc.c:147 l3_interrupt_handler+0x25c/0x36c
[ 11.533121] 44000000.ocp:L3 Custom Error: MASTER DSP2_DMA TARGET L4_PER3_P3 (Read): Data Access in User mode during Functional access
[ 11.533140] Modules linked in: ads7846 ad5724r_spi snd_soc_tlv320aic3x rtc_ds1307 rtc_omap rtc_palmas extcon_palmas omap_remoteproc virtio_rpmsg_bus rpmsg_core remoteproc sch_fq_codel uio_module_drv(O) uio ftdi_sio usbserial gdbserverproxy(O) cryptodev(O) cmemk(O)
[ 11.533144] CPU: 0 PID: 27 Comm: irq/23-l3-app-i Tainted: G W O 4.9.65-rt23-06389-g750859d #30
[ 11.533145] Hardware name: Generic DRA74X (Flattened Device Tree)
[ 11.533147] Backtrace:
[ 11.533153] [<c020b2b4>] (dump_backtrace) from [<c020b570>] (show_stack+0x18/0x1c)
[ 11.533157] r7:00000009 r6:600f0113 r5:00000000 r4:c1024d98
[ 11.533163] [<c020b558>] (show_stack) from [<c04d3dbc>] (dump_stack+0x8c/0xa0)
[ 11.533167] [<c04d3d30>] (dump_stack) from [<c022da90>] (__warn+0xec/0x104)
[ 11.533171] r7:00000009 r6:c0bd2208 r5:00000000 r4:ef27be20
[ 11.533174] [<c022d9a4>] (__warn) from [<c022dae8>] (warn_slowpath_fmt+0x40/0x48)
[ 11.533178] r9:0000001b r8:ef235f10 r7:c0bd2538 r6:00000002 r5:c0bd2134 r4:c0bd21d8
[ 11.533183] [<c022daac>] (warn_slowpath_fmt) from [<c0503d1c>] (l3_interrupt_handler+0x25c/0x36c)
[ 11.533185] r3:ef235d80 r2:c0bd21d8
[ 11.533187] r4:80080003
[ 11.533192] [<c0503ac0>] (l3_interrupt_handler) from [<c02827b8>] (irq_forced_thread_fn+0x28/0x7c)
[ 11.533196] r10:c0282790 r9:ef23b280 r8:ef067e00 r7:00000001 r6:00000000 r5:ef067e00
[ 11.533197] r4:ef23b280
[ 11.533201] [<c0282790>] (irq_forced_thread_fn) from [<c0282b1c>] (irq_thread+0x124/0x1f8)
[ 11.533204] r7:00000001 r6:00000000 r5:ef27a000 r4:ef23b2a4
[ 11.533209] [<c02829f8>] (irq_thread) from [<c024b004>] (kthread+0x100/0x118)
[ 11.533213] r10:00000000 r9:00000000 r8:c02829f8 r7:ef23b280 r6:ef27a000 r5:ef23b2c0
[ 11.533215] r4:00000000
[ 11.533219] [<c024af04>] (kthread) from [<c0207c90>] (ret_from_fork+0x14/0x24)
[ 11.533223] r8:00000000 r7:00000000 r6:00000000 r5:c024af04 r4:ef23b2c0
[ 11.533224] ---[ end trace 0000000000000a0d ]---
[ 11.533232] ------------[ cut here ]------------

2.the system will crash when i change the openvx firmware at filesystem.

pkill ti-mctd                            # Kill CMEM multi-process daemon. This releases all CMEM memory used by OpenCL memory allocation
cd /sys/bus/platform/drivers/omap-rproc/ # Prepare to send commands for remoteproc
echo 40800000.dsp > unbind               # Release DSP1
echo 41000000.dsp > unbind               # Release DSP2
rm /lib/firmware/dra7-dsp1-fw.xe66       # 
ln -s /lib/firmware/dra7-dsp1-fw.xe66.openvx /lib/firmware/dra7-dsp1-fw.xe66 # Link TIOVX firmware for DSP1
rm /lib/firmware/dra7-dsp2-fw.xe66       # 
ln -s /lib/firmware/dra7-dsp2-fw.xe66.openvx /lib/firmware/dra7-dsp2-fw.xe66  # Link TIOVX firmware for DSP2
echo 40800000.dsp > bind                 # Load new DSP1 firmware (now, for OpenVX, as set in previous steps)
echo 41000000.dsp > bind                 # Load new DSP2 firmware (now, for OpenVX, as set in previous steps)
cd -                                     # Return to original folder

the log is same as 1.

3. the system will hang when system booting or changing the firmware at filesytem.

[   12.783915] xhci-hcd xhci-hcd.2.auto: xHCI Host Controller
[   12.789440] xhci-hcd xhci-hcd.2.auto: new USB bus registered, assigned bus number 3
[   12.798031] xhci-hcd xhci-hcd.2.auto: hcc params 0x0220f04c hci version 0x100 quirks 0x02010010
[   12.808093] xhci-hcd xhci-hcd.2.auto: irq 483, io mem 0x488d0000
[   12.815005] hub 3-0:1.0: USB hub found
[   12.818789] hub 3-0:1.0: 1 port detected
[   12.823803] xhci-hcd xhci-hcd.2.auto: xHCI Host Controller
[   12.829815] xhci-hcd xhci-hcd.2.auto: new USB bus registered, assigned bus number 4
[   12.838715] usb usb4: We don't know the algorithms for LPM for this host, disabling LPM.
[   12.848153] hub 4-0:1.0: USB hub found
[   12.852394] hub 4-0:1.0: 1 port detected
[   12.862909] remoteproc remoteproc3: powering up 41000000.dsp
[   12.869088] remoteproc remoteproc3: Booting fw image dra7-dsp2-fw.xe66, size 8814504
[   12.884099] omap-iommu 41501000.mmu: 41501000.mmu: version 3.0
[   12.890012] omap-iommu 41502000.mmu: 41502000.mmu: version 3.0
[   12.905355] virtio_rpmsg_bus virtio2: rpmsg host is online

It do not hang on a static place.but the system will hang after "remoteproc remoteproc3: Booting fw image dra7-dsp2-fw.xe66, size 8814504"


Thanks.

0 Rex Chang over 7 years ago in reply to yu chen

TI__Guru 50170 points

HI, CY,

I can reproduce the issue. We'll look internally to see what may cause the issue. Thanks for letting us know. There may not be a quick fix or work around for it. You would need to work your project when the system can boot successfully till we have a fix.

I created a bug record in our jira system and development team will go from there. I'll close this issue for now and will post back if we have the resolution.

Rex

0 Rex Chang over 7 years ago in reply to Rex Chang

TI__Guru 50170 points

Hi, CY,

For now as the workaround. Don't reboot EVM with OpenVX images, but using OpenCL. Follow the instruction in OpenVX document to change DSP image to OpenVX using unbind/bind, and run the demo/test. Once it is done, change the DSP image link back to OpenCL's before rebooting the EVM. That is always use OpenCL images during EVM booting.

Rex

0 yu chen over 7 years ago in reply to Rex Chang

Expert 1465 points

Hi,Rex

Thanks for your reply.

I try,but it do not work fine.

Which reboot do you mean? hareware or software? i try hareware reboot,it still hang or crash sometimes.

0 Rex Chang over 7 years ago in reply to yu chen

TI__Guru 50170 points

Hi, CY,

Before doing a reboot (software or hardware), switch the DSP images back to either OpenCL or no images. OpenVX images can't be used during reboot. If you ran OpenVX images, unbind, re-ln to OpenCL image, bind, then reboot or power cycle it.

Rex

0 Rex Chang over 7 years ago in reply to Rex Chang

TI__Guru 50170 points

Hi, CY,

The documentation on the procedure of running TIOVX test section will be modified as below adding "Switch from OpenVX, back to OpenCL firmware" at the end in the next release:

Switch from OpenCL to OpenVX firmware:

Run the command below to switch from OpenCL to OpenVx firmware:

reload-dsp-fw.sh tiovx # load openvx firmware and restart dsps

Run TIOVX test application

First, it is necessary to copy test vectors from git.ti.com/.../test_data to EVM filesystem (e.g. ~/tiovx/test_data).Then run following commands:

export VX_TEST_DATA_PATH=/home/root/tiovx/test_data # Set environment variable to point to location of test vectors on EVM
tiovx-app_host 2>&1 | tee log.txt # Run test application, and log output to log.txt
At the end of test (taking roughly 24mins) you can expect report like this:

...
[ N7 ] Execution time for 307200 pixels (avg = 3.584000 ms, min = 3.584000 ms, max = 3.584000 ms)
[ N8 ] Execution time for 307200 pixels (avg = 171.797000 ms, min = 171.797000 ms, max = 171.797000 ms)
[ N9 ] Execution time for 307200 pixels (avg = 366.952000 ms, min = 366.952000 ms, max = 366.952000 ms)
[ G4 ] Execution time for 307200 pixels (avg = 500.146000 ms, min = 500.146000 ms, max = 500.146000 ms)
[ N1 ] Execution time for 256 pixels (avg = 0.278000 ms, min = 0.278000 ms, max = 0.278000 ms)
[ N2 ] Execution time for 256 pixels (avg = 0.230000 ms, min = 0.230000 ms, max = 0.230000 ms)
[ N3 ] Execution time for 256 pixels (avg = 0.281000 ms, min = 0.281000 ms, max = 0.281000 ms)
[ N4 ] Execution time for 256 pixels (avg = 0.303000 ms, min = 0.303000 ms, max = 0.303000 ms)
[ N5 ] Execution time for 256 pixels (avg = 0.285000 ms, min = 0.285000 ms, max = 0.285000 ms)
[ G5 ] Execution time for 256 pixels (avg = 2.169000 ms, min = 2.169000 ms, max = 2.169000 ms)
[ N1 ] Execution time for 256 pixels (avg = 0.243000 ms, min = 0.243000 ms, max = 0.243000 ms)
[ N2 ] Execution time for 256 pixels (avg = 0.301000 ms, min = 0.301000 ms, max = 0.301000 ms)
[ G6 ] Execution time for 256 pixels (avg = 0.871000 ms, min = 0.871000 ms, max = 0.871000 ms)
[ N1 ] Execution time for 256 pixels (avg = 0.352000 ms, min = 0.352000 ms, max = 0.352000 ms)
[ N2 ] Execution time for 256 pixels (avg = 0.246000 ms, min = 0.246000 ms, max = 0.246000 ms)
[ N2 ] Execution time for 256 pixels (avg = 0.324000 ms, min = 0.324000 ms, max = 0.324000 ms)
[ G7 ] Execution time for 256 pixels (avg = 1.502000 ms, min = 1.502000 ms, max = 1.502000 ms)
[ N1 ] Execution time for 256 pixels (avg = 75.37000 ms, min = 75.37000 ms, max = 75.37000 ms)
[ G8 ] Execution time for 256 pixels (avg = 60.474000 ms, min = 60.474000 ms, max = 60.474000 ms)
[ DONE ] tivxMaxNodes.MaxNodes/0/few_strong_corners/MIN_DISTANCE=3.0/SENSITIVITY=0.10/GRADIENT_SIZE=3/BLOCK_SIZE=5/k=3/VX_INTERPOLATION_NEAREST_NEIGHBOR
[ -------- ] 1 tests from test case tivxMaxNodes

[ ======== ]
[ ALL DONE ] 6217 test(s) from 110 test case(s) ran
[ PASSED ] 6217 test(s)
[ FAILED ] 0 test(s)
[ DISABLED ] 7397 test(s)

To be conformant 6217 required test(s) must pass. Disabled 7397 test(s) are optional.

#REPORT: 20170927134830 ALL 13614 7397 6217 6217 6217 0 (version 1.1-20170301)
<-- main:
Please note that last ~3000 lines of test log include performance data (execution time and number of pixels processed) useful for further evaluation.

Switch from OpenVX, back to OpenCL firmware:

After finishing running the TIOVX test application, switch the firmware back to the default for OpenCL:

reload-dsp-fw.sh opencl # load opencl firmware and restart dsps

Processors

Processors forum

Linux/AM5728: TIOVX kernel boot issue