Occasional several-second pauses

[CiaranWoodward]

Running a simple packet spamming program between a kernel driven ca8210 and a usb dongle (baremetal), I notice occasional pauses in the kernel driver which cause packets to be missed (and in this case, a confirm seems to be lost).

Node 00 is the kernel driven node, node 01 is the usb node. Note that around 35 seconds in, no more packets are received, and the confirm is also missed (the application I am running will not attempt to send another packet before the previous one is confirmed). After about 7 seconds, receive packets start coming in again, but some appear to be permanently lost, and the confirm is definitely lost.

|----||----|----|---||----|----|---|
|----||---NODE 00---||---NODE 01---|
|TIME||Tx  |Rx  |Err||Tx  |Rx  |Err|
|  20|| 345| 344|  0|| 344| 345|  0|
|  21|| 362| 362|  0|| 362| 362|  0|
|  22|| 380| 379|  0|| 379| 380|  0|
|  23|| 397| 396|  0|| 396| 397|  0|
|  24|| 414| 413|  0|| 413| 414|  0|
|  25|| 431| 431|  0|| 431| 431|  0|
|  26|| 437| 437|  0|| 448| 438|  0|
|  27|| 449| 465|  0|| 465| 449|  0|
|  28|| 467| 482|  0|| 482| 467|  0|
|  29|| 484| 499|  0|| 499| 484|  0|
|  30|| 501| 516|  0|| 516| 501|  0|
|  31|| 518| 534|  0|| 534| 518|  0|
|  32|| 536| 551|  0|| 551| 536|  0|
|  33|| 553| 569|  0|| 569| 553|  0|
|  34|| 571| 586|  0|| 586| 571|  0|
|  35|| 588| 603|  0|| 603| 588|  0|
|  36|| 588| 603|  0|| 620| 589|  0|
|  37|| 588| 603|  0|| 637| 589|  0|
|  38|| 588| 603|  0|| 654| 589|  0|
|  39|| 588| 603|  0|| 671| 589|  0|
|----||----|----|---||----|----|---|
|----||---NODE 00---||---NODE 01---|
|TIME||Tx  |Rx  |Err||Tx  |Rx  |Err|
|  40|| 588| 603|  0|| 688| 589|  0|
|  41|| 588| 603|  0|| 705| 589|  0|
|  42|| 588| 603|  0|| 722| 589|  0|
|  43|| 588| 603|  0|| 739| 589|  0|
|  44|| 588| 679|  0|| 757| 589|  0|
|  45|| 588| 696|  0|| 774| 589|  0|
|  46|| 588| 713|  0|| 791| 589|  0|

I initially thought this may have been down to an issue with select() in kernel_exchange, as the time out is 5 seconds. However, reducing this timeout had no effect.

This is the kernel log around the same time. Looks like the kfifo is overflowing. Last full read was at 15:11:16.

Sep 12 15:11:20 Raspi2B-A kernel: [18116.703051] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703059] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703067] 00 00 00 00 00 00 ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703076] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703084] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703092] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703100] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703108] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703117] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703126] ca8210 spi0.0: READ CMD DURING TX
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703136] ca8210 spi0.0: test_interface: Buffering upstream message:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703145] 20 28 02 aa 1a 22 00 ff ff ff ff ff ff 02 aa 1a   (..."..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703154] 0c 00 ff ff ff ff ff ff 0a ff 41 00 00 00 00 01  ..........A.....
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703162] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703174] ca8210 spi0.0: ca8210_net_rx(), CmdID = 32
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703186] ca8210 spi0.0: skb buffer length = 10
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703197] ca8210 spi0.0: security level: 0x0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703207] ca8210 spi0.0: srcAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703216] ca8210 spi0.0: srcPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703226] ca8210 spi0.0: dstAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.703236] ca8210 spi0.0: dstPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761160] ca8210 spi0.0: irq: Interrupt occurred
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761206] ca8210 spi0.0: ca8210_spi_transfer called
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761883] ca8210 spi0.0: spi transfer complete. status: 0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761895] ca8210 spi0.0: spi transfer out:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761922] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761931] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761939] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761948] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761956] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761964] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761972] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761980] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761988] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.761996] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762005] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762013] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762021] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762029] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762070] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762080] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762090] ca8210 spi0.0: spi transfer in:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762099] 20 28 02 aa 1a 22 00 ff ff ff ff ff ff 02 aa 1a   (..."..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762108] 0c 00 ff ff ff ff ff ff 0a ff 42 00 00 00 00 01  ..........B.....
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762116] 02 03 04 05 06 07 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762124] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762133] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762141] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762149] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762158] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762166] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762174] 00 00 00 00 00 00 ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762182] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762191] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762199] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762207] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762215] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762223] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762233] ca8210 spi0.0: READ CMD DURING TX
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762243] ca8210 spi0.0: test_interface: Buffering upstream message:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762252] 20 28 02 aa 1a 22 00 ff ff ff ff ff ff 02 aa 1a   (..."..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762260] 0c 00 ff ff ff ff ff ff 0a ff 42 00 00 00 00 01  ..........B.....
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762268] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762280] ca8210 spi0.0: ca8210_net_rx(), CmdID = 32
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762293] ca8210 spi0.0: skb buffer length = 10
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762303] ca8210 spi0.0: security level: 0x0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762312] ca8210 spi0.0: srcAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762322] ca8210 spi0.0: srcPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762332] ca8210 spi0.0: dstAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.762342] ca8210 spi0.0: dstPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.821414] ca8210 spi0.0: irq: Interrupt occurred
Sep 12 15:11:20 Raspi2B-A kernel: [18116.821502] ca8210 spi0.0: ca8210_spi_transfer called
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822200] ca8210 spi0.0: spi transfer complete. status: 0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822213] ca8210 spi0.0: spi transfer out:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822225] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822234] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822242] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822250] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822258] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822266] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822275] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822283] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822291] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822299] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822307] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822316] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822324] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822332] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822340] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822349] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822358] ca8210 spi0.0: spi transfer in:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822367] 20 28 02 aa 1a 22 00 ff ff ff ff ff ff 02 aa 1a   (..."..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822375] 0c 00 ff ff ff ff ff ff 0a ff 43 00 00 00 00 01  ..........C.....
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822384] 02 03 04 05 06 07 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822392] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822400] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822409] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822417] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822425] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822434] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822442] 00 00 00 00 00 00 ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822450] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822458] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822467] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822475] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822483] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822491] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822501] ca8210 spi0.0: READ CMD DURING TX
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822510] ca8210 spi0.0: test_interface: Buffering upstream message:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822519] 20 28 02 aa 1a 22 00 ff ff ff ff ff ff 02 aa 1a   (..."..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822528] 0c 00 ff ff ff ff ff ff 0a ff 43 00 00 00 00 01  ..........C.....
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822536] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822546] ca8210 spi0.0: test_interface: fifo full, discarding oldest entry...
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822562] ca8210 spi0.0: ca8210_net_rx(), CmdID = 32
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822573] ca8210 spi0.0: skb buffer length = 10
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822583] ca8210 spi0.0: security level: 0x0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822593] ca8210 spi0.0: srcAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822603] ca8210 spi0.0: srcPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822613] ca8210 spi0.0: dstAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.822623] ca8210 spi0.0: dstPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879177] ca8210 spi0.0: irq: Interrupt occurred
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879227] ca8210 spi0.0: ca8210_spi_transfer called
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879908] ca8210 spi0.0: spi transfer complete. status: 0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879938] ca8210 spi0.0: spi transfer out:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879952] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879961] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879969] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879977] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879985] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.879994] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880002] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880010] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880018] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880027] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880035] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880043] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880085] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880095] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880104] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880113] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880122] ca8210 spi0.0: spi transfer in:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880131] 20 28 02 aa 1a 22 00 ff ff ff ff ff ff 02 aa 1a   (..."..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880140] 0c 00 ff ff ff ff ff ff 0a ff 44 00 00 00 00 01  ..........D.....
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880148] 02 03 04 05 06 07 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880157] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880165] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880173] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880182] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880190] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880198] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880207] 00 00 00 00 00 00 ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880215] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880223] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880231] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880239] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880247] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880255] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880265] ca8210 spi0.0: READ CMD DURING TX
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880275] ca8210 spi0.0: test_interface: Buffering upstream message:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880284] 20 28 02 aa 1a 22 00 ff ff ff ff ff ff 02 aa 1a   (..."..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880293] 0c 00 ff ff ff ff ff ff 0a ff 44 00 00 00 00 01  ..........D.....
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880301] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880311] ca8210 spi0.0: test_interface: fifo full, discarding oldest entry...
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880325] ca8210 spi0.0: ca8210_net_rx(), CmdID = 32
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880337] ca8210 spi0.0: skb buffer length = 10
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880348] ca8210 spi0.0: security level: 0x0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880357] ca8210 spi0.0: srcAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880367] ca8210 spi0.0: srcPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880377] ca8210 spi0.0: dstAddrMode: 0x2
Sep 12 15:11:20 Raspi2B-A kernel: [18116.880387] ca8210 spi0.0: dstPanId: 0x1aaa
Sep 12 15:11:20 Raspi2B-A kernel: [18116.938782] ca8210 spi0.0: irq: Interrupt occurred
Sep 12 15:11:20 Raspi2B-A kernel: [18116.938827] ca8210 spi0.0: ca8210_spi_transfer called
Sep 12 15:11:20 Raspi2B-A kernel: [18116.939509] ca8210 spi0.0: spi transfer complete. status: 0
Sep 12 15:11:20 Raspi2B-A kernel: [18116.939522] ca8210 spi0.0: spi transfer out:
Sep 12 15:11:20 Raspi2B-A kernel: [18116.939534] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.939542] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 12 15:11:20 Raspi2B-A kernel: [18116.939550] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................

And this will be followed by the exchange suddenly reading everything at once:

Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242590] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242602] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242615] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242627] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242639] ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242653] ca8210 spi0.0: READ CMD DURING TX
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242668] ca8210 spi0.0: test_interface: Buffering upstream message:
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242681] 20 28 02 aa 1a 0d 00 ff ff ff ff ff ff 02 aa 1a   (..............
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242694] 0c 00 ff ff ff ff ff ff 0a ff 06 00 00 00 00 01  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242706] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242774] ca8210 spi0.0: ca8210_net_rx(), CmdID = 32
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242794] ca8210 spi0.0: skb buffer length = 10
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242810] ca8210 spi0.0: security level: 0x0
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242824] ca8210 spi0.0: srcAddrMode: 0x2
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242839] ca8210 spi0.0: srcPanId: 0x1aaa
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242854] ca8210 spi0.0: dstAddrMode: 0x2
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.242868] ca8210 spi0.0: dstPanId: 0x1aaa
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.253736] ca8210 spi0.0: test_interface: Cmd len = 6
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.253764] ca8210 spi0.0: test_interface: Read
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.253783] 21 06 8a 00 00 00 00 00                          !.......
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.253944] ca8210 spi0.0: test_interface: Cmd len = 40
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.253962] ca8210 spi0.0: test_interface: Read
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.253977] 20 28 02 aa 1a 0d 00 ff ff ff ff ff ff 02 aa 1a   (..............
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.253990] 0c 00 ff ff ff ff ff ff 0a ff cc 00 00 00 00 01  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254002] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254155] ca8210 spi0.0: test_interface: Cmd len = 40
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254172] ca8210 spi0.0: test_interface: Read
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254187] 20 28 02 aa 1a 0d 00 ff ff ff ff ff ff 02 aa 1a   (..............
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254200] 0c 00 ff ff ff ff ff ff 0a ff cd 00 00 00 00 01  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254212] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254397] ca8210 spi0.0: test_interface: Cmd len = 40
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254414] ca8210 spi0.0: test_interface: Read
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254428] 20 28 02 aa 1a 0d 00 ff ff ff ff ff ff 02 aa 1a   (..............
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254442] 0c 00 ff ff ff ff ff ff 0a ff ce 00 00 00 00 01  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254454] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254633] ca8210 spi0.0: test_interface: Cmd len = 40
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254650] ca8210 spi0.0: test_interface: Read
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254664] 20 28 02 aa 1a 0d 00 ff ff ff ff ff ff 02 aa 1a   (..............
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254678] 0c 00 ff ff ff ff ff ff 0a ff cf 00 00 00 00 01  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254690] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254839] ca8210 spi0.0: test_interface: Cmd len = 40
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254855] ca8210 spi0.0: test_interface: Read
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254869] 20 28 02 aa 1a 0d 00 ff ff ff ff ff ff 02 aa 1a   (..............
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254883] 0c 00 ff ff ff ff ff ff 0a ff d0 00 00 00 00 01  ................
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.254895] 02 03 04 05 06 07 00 00 00 00                    ..........
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.255091] ca8210 spi0.0: test_interface: Cmd len = 40
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.255107] ca8210 spi0.0: test_interface: Read
Sep 14 11:05:34 Raspi2B-A kernel: [ 2614.255122] 20 28 02 aa 1a 0d 00 ff ff ff ff ff ff 02 aa 1a   (..............
etc.

[CiaranWoodward]

Upon further investigation, this wasn't down to the driver, but the kernel_exchange. Writing to the log file was causing occasional freezes of several seconds.