mcp25xxfd reports errors in the kernel log

[enmasse]

Hi,

I'm evaluating the PICAN FD Duo board from Skpang. To test it out, I've connected can0 to can1 and running cangen -g 0 -m can0. After a short period of time, the command will exit with a message write: No buffer space available.

Kernel:
root@signalserver-canfd:~# uname -a Linux signalserver-canfd 4.14.98ms7-v7+ #75 SMP Sat Feb 16 22:22:33 UTC 2019 armv7l GNU/Linux

Looking in the kernel log I can see the following messages:

[  323.947188] IPv6: ADDRCONF(NETDEV_CHANGE): can0: link becomes ready
[  323.963571] IPv6: ADDRCONF(NETDEV_CHANGE): can1: link becomes ready
[  343.344348] can: controller area network core (rev 20170425 abi 9)
[  343.344444] NET: Registered protocol family 29
[  343.352870] can: raw protocol (rev 20170425)
[  343.361683] NOHZ: local_softirq_pending 08
[  343.363120] NOHZ: local_softirq_pending 08
[  343.366264] NOHZ: local_softirq_pending 08
[  343.367370] NOHZ: local_softirq_pending 08
[  343.368599] NOHZ: local_softirq_pending 08
[  343.369537] NOHZ: local_softirq_pending 08
[  343.370786] NOHZ: local_softirq_pending 08
[  343.374552] NOHZ: local_softirq_pending 08
[  343.375805] NOHZ: local_softirq_pending 08
[  343.376777] NOHZ: local_softirq_pending 08
[  402.700957] mcp25xxfd spi0.1 can0: Something is wrong - we got a TEF interrupt but we were not able to detect a finished fifo
[  402.701055] mcp25xxfd spi0.1 can0: tefif: fifo 1 not pending - tef data: id: 0b066825 flags: 00000217, ts: 04947926 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  402.702035] mcp25xxfd spi0.1 can0: tefif: fifo 2 not pending - tef data: id: 03c34c04 flags: 00000435, ts: 04947d64 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  402.703176] mcp25xxfd spi0.1 can0: tefif: fifo 3 not pending - tef data: id: 00000479 flags: 0000068b, ts: 04948196 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  402.703214] mcp25xxfd spi0.1 can0: tefif: fifo 4 not pending - tef data: id: 14d04342 flags: 0000089c, ts: 049485bf - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  402.704475] mcp25xxfd spi0.1 can0: tefif: fifo 5 not pending - tef data: id: 00000253 flags: 00000ac0, ts: 049489d3 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  402.704512] mcp25xxfd spi0.1 can0: tefif: fifo 6 not pending - tef data: id: 177f51db flags: 00000c9e, ts: 04948e1a - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  402.704546] mcp25xxfd spi0.1 can0: tefif: fifo 7 not pending - tef data: id: 041ee9fb flags: 00000e15, ts: 04949245 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced

I've tried different values for -g, but it just takes slightly longer to fail. Also I've tried to half spimaxfrequency following the suggestion in the kernel log.

[msperl]

this may be due to some bugs - please try the latest version I have just published

[enmasse]

No, this is still happening:

[  156.474627] can: controller area network core (rev 20170425 abi 9)
[  156.474726] NET: Registered protocol family 29
[  156.484418] can: raw protocol (rev 20170425)
[  156.488317] NOHZ: local_softirq_pending 08
[  156.488422] NOHZ: local_softirq_pending 08
[  156.491721] NOHZ: local_softirq_pending 08
[  156.491800] NOHZ: local_softirq_pending 08
[  156.491874] NOHZ: local_softirq_pending 08
[  156.491919] NOHZ: local_softirq_pending 08
[  156.492017] NOHZ: local_softirq_pending 08
[  156.492044] NOHZ: local_softirq_pending 08
[  156.492169] NOHZ: local_softirq_pending 08
[  156.492294] NOHZ: local_softirq_pending 08
[  169.584554] mcp25xxfd spi0.1 can0: Something is wrong - we got a TEF interrupt but we were not able to detect a finished fifo
[  169.584676] mcp25xxfd spi0.1 can0: tefif: fifo 6 not pending - tef data: id: 081f6bd7 flags: 00000c18, ts: 04485841 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  169.585603] mcp25xxfd spi0.1 can0: tefif: fifo 1 not pending - tef data: id: 10d8d200 flags: 000002dd, ts: 04485c89 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  248.568010] mcp25xxfd spi0.1 can0: tefif: fifo 0 not pending - tef data: id: 00000000 flags: 00000000, ts: 00000000 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  248.568151] mcp25xxfd spi0.1 can0: tefif: fifo 0 not pending - tef data: id: 00000000 flags: 00000000, ts: 00000000 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  248.568219] mcp25xxfd spi0.1 can0: tefif: fifo 0 not pending - tef data: id: 00000000 flags: 00000000, ts: 00000000 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  248.570112] mcp25xxfd spi0.1 can0: tefif: fifo 0 not pending - tef data: id: 00000000 flags: 00000000, ts: 00000000 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[  248.570152] mcp25xxfd spi0.1 can0: tefif: fifo 0 not pending - tef data: id: 00000000 flags: 00000000, ts: 00000000 - this may be a problem with spi signal quality- try reducing spi-clock speed if this can get reproduced
[1]+  Killed                  cangen -g 1 -m can0
root@signalserver-canfd:~# uname -a
Linux signalserver-canfd 4.19.40ms7-v7+ #81 SMP Sat May 11 17:33:45 UTC 2019 armv7l GNU/Linux

[enmasse]

I'd be happy to help out debugging or providing more information to help you solve this issue.

[msperl]

I would need a bit more details!

Things like:
spi clock speed configured
Description of test setup
Description of test - how are you testing?
Description of can bus parameters (baud,...)
Output of head /sys/kernel/debug/mcp25xxfd*/spi*
Output of ip -details link show can0
Output of uname -a
Version of code - is it really 8.2?

Other things that may be of interest - some that i can not think of right now

[msperl]

Looking at it some more I came to realize:

You seem to be using:

• a Raspberry Pi 3*
• using spi 0.1 - so i guess that that you use spi-bcm2835 with (at least) 2 chip selects

It leaves open some other questions...

[enmasse]

Configuration file:
config.txt

File I use to set up interfaces:
ifup-canfd.txt

Output from /sys/kernel/debug/mcp25xxfd*/spi* as you requested:

root@signalserver-canfd:~# find /sys/kernel/debug/mcp25xxfd-spi0.0/ -name "spi_*" -exec echo "{}:" \; -exec cat "{}" \;
/sys/kernel/debug/mcp25xxfd-spi0.0/spi_crc_read_split:
0
/sys/kernel/debug/mcp25xxfd-spi0.0/spi_crc_read:
1
/sys/kernel/debug/mcp25xxfd-spi0.0/spi_use_speed_hz:
20000000
/sys/kernel/debug/mcp25xxfd-spi0.0/spi_normal_speed_hz:
20000000
/sys/kernel/debug/mcp25xxfd-spi0.0/spi_setup_speed_hz:
10000000

root@signalserver-canfd:~# find /sys/kernel/debug/mcp25xxfd-spi0.1/ -name "spi_*" -exec echo "{}:" \; -exec cat "{}" \;
/sys/kernel/debug/mcp25xxfd-spi0.1/spi_crc_read_split:
0
/sys/kernel/debug/mcp25xxfd-spi0.1/spi_crc_read:
1
/sys/kernel/debug/mcp25xxfd-spi0.1/spi_use_speed_hz:
20000000
/sys/kernel/debug/mcp25xxfd-spi0.1/spi_normal_speed_hz:
20000000
/sys/kernel/debug/mcp25xxfd-spi0.1/spi_setup_speed_hz:
10000000

Output from ip -details as you requested:

root@signalserver-canfd:~# ip -details link show type can
3: can0: <NOARP,UP,LOWER_UP,ECHO> mtu 72 qdisc pfifo_fast state UNKNOWN mode DEFAULT group default qlen 1000
    link/can  promiscuity 0 
    can <FD> state ERROR-ACTIVE (berr-counter tx 0 rx 0) restart-ms 0 
	  bitrate 500000 sample-point 0.800 
	  tq 25 prop-seg 31 phase-seg1 32 phase-seg2 16 sjw 1
	  mcp25xxfd: tseg1 2..256 tseg2 1..128 sjw 1..128 brp 1..256 brp-inc 1
	  dbitrate 2000000 dsample-point 0.800 
	  dtq 25 dprop-seg 7 dphase-seg1 8 dphase-seg2 4 dsjw 1
	  mcp25xxfd: dtseg1 1..32 dtseg2 1..16 dsjw 1..16 dbrp 1..256 dbrp-inc 1
	  clock 40000000numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535 
4: can1: <NOARP,UP,LOWER_UP,ECHO> mtu 72 qdisc pfifo_fast state UNKNOWN mode DEFAULT group default qlen 1000
    link/can  promiscuity 0 
    can <FD> state ERROR-ACTIVE (berr-counter tx 0 rx 0) restart-ms 0 
	  bitrate 500000 sample-point 0.800 
	  tq 25 prop-seg 31 phase-seg1 32 phase-seg2 16 sjw 1
	  mcp25xxfd: tseg1 2..256 tseg2 1..128 sjw 1..128 brp 1..256 brp-inc 1
	  dbitrate 2000000 dsample-point 0.800 
	  dtq 25 dprop-seg 7 dphase-seg1 8 dphase-seg2 4 dsjw 1
	  mcp25xxfd: dtseg1 1..32 dtseg2 1..16 dsjw 1..16 dbrp 1..256 dbrp-inc 1
	  clock 40000000numtxqueues 1 numrxqueues 1 gso_max_size 65536 gso_max_segs 65535 

Output from uname -a:

root@signalserver-canfd:~# uname -a 
Linux signalserver-canfd 4.19.40ms7-v7+ #81 SMP Sat May 11 17:33:45 UTC 2019 armv7l GNU/Linux

Not sure how to show you that I really run your software. I pulled the kernel directly from your release page. :)

Image of test setup:

Reproducing the error:
cangen -g 1 -m can0 & candump can1

Tell me if you need anything else.

[enmasse]

From config.txt:

dtparam=i2c_arm=on
dtparam=i2c_vc=on
dtparam=spi=on
dtoverlay=mcp2517fd-can0,oscillator=40000000,interrupt=25
dtoverlay=mcp2517fd-can1,oscillator=40000000,interrupt=05

That can1 is tied to interrupt 05 seems a little bit odd, but it's according to instructions from SkPang. On the previous version of the PICAN DUO shield the interrupts for the can interfaces were in sequence.

[enmasse]

Please let me know if you're able to reproduce the error or if I could assist in isolating the bug further.

[irrwisch1]

I was having the same issue and as a workaround I reverted those two commits that optimize TEF reading
d86b484#diff-8a495b05736235e49b1a602651e1a187
65c507a#diff-8a495b05736235e49b1a602651e1a187

The problems (hopefully) seems to be gone now without those two commits, however I didn't dig into it much further.

[enmasse]

Thanks @jlanger, I will try to do the same when I figure out how to build the kernel.

[enmasse]

I recompiled the kernel from commit cf733ff just before the TEF optimizations as just reverting the commits resulted in some compile errors that I didn't care to investigate.
It looks promising. I'm able to run cangen -g 1 -m can0 & candump can1 in my setup without the error reoccurring.

...after a while I get this message though:
write: No buffer space available

But it could be just a matter of increasing txqueuelen.

Edit: When running the code from this commit, with increased txqueuelen I get a kernel panic. I can post it on request, but because it's not the latest there might be a fix in a later commit.

[irrwisch1]

I also did some more testing and it specifically seems to be this commit
65c507a#diff-8a495b05736235e49b1a602651e1a187
That's making trouble. The first TEF optimization commit seems to work fine.

@enmasse: Yes if you revert that commit you need to re-add some variable definitions in mcp25xxfd_can_debugfs.c to make it build again.

[enmasse]

@jlanger, it depends on what you mean when you say first or second commit, they're dated in the opposite order of when they're commited. :)

I reverted only commit 65c507a but then I still get the error.