Turning Radio Off While Receving Causes the SPI Driver to Livelock

[bradjc]

This isn't a bug in this driver as far as I can tell, however there may be a temporary fix in the cc2520 kernel module as a workaround until the spi/rt support matures.

The issue as it appears on a high level is that in certain cases when turning the radio off while a packet is being received the spi0 process utilizes 100% cpu. After some tracing through functions it appears the spi driver gets into a weird state with a spin lock when dealing with the real time code. I think this then prevents the border router application from doing anything.

So, if the turn off strobe function had a way of detecting that the spi bus was being used that may stop this bug from happening. It's obviously not a fix, but debugging the real time code in the kernel is a bit out of my league, especially on the pi.

Here is what shows up in syslog when this happens:

Feb 24 23:00:44 raspberrypi kernel: [ 2040.880325] [cc2520] - radio turning off
Feb 24 23:00:44 raspberrypi kernel: [ 2042.036026] [sched_delayed] sched: RT throttling activated
Feb 24 23:02:45 raspberrypi kernel: [ 2163.017712] INFO: task br2:2624 blocked for more than 120 seconds.
Feb 24 23:02:45 raspberrypi kernel: [ 2163.017738] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 24 23:02:45 raspberrypi kernel: [ 2163.017753] br2             D c03abdfc     0  2624   2616 0x00000000
Feb 24 23:02:45 raspberrypi kernel: [ 2163.017839] [<c03abdfc>] (__schedule+0x2cc/0x610) from [<c03a9e94>] (schedule_timeout+0x13c/0x1b4)
Feb 24 23:02:45 raspberrypi kernel: [ 2163.017873] [<c03a9e94>] (schedule_timeout+0x13c/0x1b4) from [<c03aba30>] (wait_for_common+0xe8/0x144)
Feb 24 23:02:45 raspberrypi kernel: [ 2163.017916] [<c03aba30>] (wait_for_common+0xe8/0x144) from [<c026bf2c>] (__spi_sync+0xac/0x114)
Feb 24 23:02:45 raspberrypi kernel: [ 2163.017997] [<c026bf2c>] (__spi_sync+0xac/0x114) from [<bf0e84a0>] (cc2520_radio_strobe+0x70/0x84 [cc2520])
Feb 24 23:02:45 raspberrypi kernel: [ 2163.018078] [<bf0e84a0>] (cc2520_radio_strobe+0x70/0x84 [cc2520]) from [<bf0e8c54>] (cc2520_radio_off+0x14/0x1c [cc2520])
Feb 24 23:02:45 raspberrypi kernel: [ 2163.018139] [<bf0e8c54>] (cc2520_radio_off+0x14/0x1c [cc2520]) from [<bf0e90ac>] (interface_ioctl+0x170/0x480 [cc2520])
Feb 24 23:02:45 raspberrypi kernel: [ 2163.018193] [<bf0e90ac>] (interface_ioctl+0x170/0x480 [cc2520]) from [<c00d4f2c>] (do_vfs_ioctl+0x80/0x5dc)
Feb 24 23:02:45 raspberrypi kernel: [ 2163.018225] [<c00d4f2c>] (do_vfs_ioctl+0x80/0x5dc) from [<c00d54bc>] (sys_ioctl+0x34/0x60)
Feb 24 23:02:45 raspberrypi kernel: [ 2163.018259] [<c00d54bc>] (sys_ioctl+0x34/0x60) from [<c000e4c0>] (ret_fast_syscall+0x0/0x3c)
Feb 24 23:02:45 raspberrypi kernel: [ 2163.018272] INFO: lockdep is turned off.
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009068] INFO: task br2:2624 blocked for more than 120 seconds.
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009096] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009110] br2             D c03abdfc     0  2624   2616 0x00000000
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009195] [<c03abdfc>] (__schedule+0x2cc/0x610) from [<c03a9e94>] (schedule_timeout+0x13c/0x1b4)
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009231] [<c03a9e94>] (schedule_timeout+0x13c/0x1b4) from [<c03aba30>] (wait_for_common+0xe8/0x144)
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009275] [<c03aba30>] (wait_for_common+0xe8/0x144) from [<c026bf2c>] (__spi_sync+0xac/0x114)
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009358] [<c026bf2c>] (__spi_sync+0xac/0x114) from [<bf0e84a0>] (cc2520_radio_strobe+0x70/0x84 [cc2520])
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009423] [<bf0e84a0>] (cc2520_radio_strobe+0x70/0x84 [cc2520]) from [<bf0e8c54>] (cc2520_radio_off+0x14/0x1c [cc2520])
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009483] [<bf0e8c54>] (cc2520_radio_off+0x14/0x1c [cc2520]) from [<bf0e90ac>] (interface_ioctl+0x170/0x480 [cc2520])
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009537] [<bf0e90ac>] (interface_ioctl+0x170/0x480 [cc2520]) from [<c00d4f2c>] (do_vfs_ioctl+0x80/0x5dc)
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009567] [<c00d4f2c>] (do_vfs_ioctl+0x80/0x5dc) from [<c00d54bc>] (sys_ioctl+0x34/0x60)
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009603] [<c00d54bc>] (sys_ioctl+0x34/0x60) from [<c000e4c0>] (ret_fast_syscall+0x0/0x3c)
Feb 24 23:04:45 raspberrypi kernel: [ 2283.009615] INFO: lockdep is turned off.