CAN question: how to trace frame errors?

CAN question: how to trace frame errors?

[Holger Schurig]

Hi people,

I have two i.MX6 based boards with built-in FLEXCAN. On both boards I
loaded can_raw.

When I now run "cangen can0 -g 0 -x" one one board, I get frame errors
on the others (no matter if I run candump on the receiving side).


root@left:~# ifconfig can0; ip -s link show can0
can0      Link encap:UNSPEC  HWaddr
00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
          UP RUNNING NOARP  MTU:16  Metric:1
          RX packets:20249437 errors:6 dropped:0 overruns:0 frame:6
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:10
          RX bytes:116445504 (111.0 MiB)  TX bytes:0 (0.0 B)
          Interrupt:142

3: can0: <NOARP,UP,LOWER_UP,ECHO> mtu 16 qdisc pfifo_fast state
UNKNOWN mode DEFAULT group default qlen 10
    link/can
    RX: bytes  packets  errors  dropped overrun mcast
    116445504  20249437 6       0       6       0
    TX: bytes  packets  errors  dropped carrier collsns
    0          0        0       0       0       0


In drivers/net/can/flexcan.c I activated all the netdev_dbg() calls,
to see if it is the flexcan IP inside the i.MX6 that gives me a bus
error. This is unfortunately not the case.

And now I'm at a loss to find out where the CAN frames errors might be
come from. I'm not fluent in the Linux networking layers, I even don't
yet know in which struct the frame and error counters reside.



PS: kernel is 3.18.14 with the patches to flexcan from 4.1-rc7 and
also the drivers/net/can patch "can: dev: Consolidate and unify state
change handling". However, I noticed this frame errors the first times
before I applied the patches.

Holger

Re: CAN question: how to trace frame errors?

[Marc Kleine-Budde]

[-- Attachment #1: Type: text/plain, Size: 1854 bytes --]

On 06/12/2015 11:29 AM, Holger Schurig wrote:
> Hi people,
> 
> I have two i.MX6 based boards with built-in FLEXCAN. On both boards I
> loaded can_raw.
> 
> When I now run "cangen can0 -g 0 -x" one one board, I get frame errors
> on the others (no matter if I run candump on the receiving side).
> 
> 
> root@left:~# ifconfig can0; ip -s link show can0
> can0      Link encap:UNSPEC  HWaddr
> 00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00
>           UP RUNNING NOARP  MTU:16  Metric:1
>           RX packets:20249437 errors:6 dropped:0 overruns:0 frame:6
>           TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
>           collisions:0 txqueuelen:10
>           RX bytes:116445504 (111.0 MiB)  TX bytes:0 (0.0 B)
>           Interrupt:142
> 
> 3: can0: <NOARP,UP,LOWER_UP,ECHO> mtu 16 qdisc pfifo_fast state
> UNKNOWN mode DEFAULT group default qlen 10
>     link/can
>     RX: bytes  packets  errors  dropped overrun mcast
>     116445504  20249437 6       0       6       0

These are probably RX-FIFO overrun errors:

>         /* FIFO overflow */                                                      
>         if (reg_iflag1 & FLEXCAN_IFLAG_RX_FIFO_OVERFLOW) {                       
>                 flexcan_write(FLEXCAN_IFLAG_RX_FIFO_OVERFLOW, &regs->iflag1);    
>                 dev->stats.rx_over_errors++;                                     
>                 dev->stats.rx_errors++;                                          
>         }                                                                        

Marc
-- 
Pengutronix e.K.                  | Marc Kleine-Budde           |
Industrial Linux Solutions        | Phone: +49-231-2826-924     |
Vertretung West/Dortmund          | Fax:   +49-5121-206917-5555 |
Amtsgericht Hildesheim, HRA 2686  | http://www.pengutronix.de   |


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 455 bytes --]

Re: CAN question: how to trace frame errors?

[Holger Schurig]

> These are probably RX-FIFO overrun errors:

You're right.

13:03:16 kernel: ##HS flexcan_irq FIFO overrun

That really puzzles me. The errors occured originally when someuse
used a Kvazer to generate 80% load at 500 kB/s. In my tests, I used 1
MB/s and cangen (no Kvazer here). The i.MX6 was otherwise idle:

root@left:~# uptime
 13:08:43 up 20 min,  2 users,  load average: 0.00, 0.01, 0.03

Re: CAN question: how to trace frame errors?

[Tom Evans]

On 12/06/2015 8:01 PM, Holger Schurig wrote:
>> These are probably RX-FIFO overrun errors:
>
> You're right.
>
> 13:03:16 kernel: ##HS flexcan_irq FIFO overrun
>
> That really puzzles me. The errors occured originally when someuse
> used a Kvazer to generate 80% load at 500 kB/s. In my tests, I used 1
> MB/s and cangen (no Kvazer here). The i.MX6 was otherwise idle:

Idle has nothing to do with it. The problem is the latency.

Let's do the maths.

The worst case CAN message arrival rate is with standard ID CAN messages 
with zero bytes of data. These are about 50 bits long. So at 500kHz they 
arrive at 10kHz or 100us interval. FlexCAN has a six message FIFO. So it 
can receive six without overflowing, but the seventh will blow it. So it 
has to (start to) be unloaded within 700us.

Since the CPU is running at 800MHz, that's only 560,000 instructions to 
respond to an interrupt. And it isn't managing it. That's what "Not Real 
Time" means - half a million instructions isn't enough time.

Except it isn't "respond to an interrupt" as the FlexCAN driver doesn't 
receive the 8-byte messages during the interrupt. It schedules a NAPI 
service routine to read the data, and they can easily be delayed that 
long waiting for a slot.

Do you have a Frame Buffer? Is it write-through or cache-flushed? I've 
read that a flush of a frame-buffer-sized chunk of memory can take the 
L2 cache a very long time to complete. Think MILLIseconds. That locks up 
ALL CORES unless the other ones are lucky enough to stay inside both 
their L1 caches.

We couldn't handle CAN losing data (and run at 1 MBit) so I rewrote the 
3.4 FlexCAN driver to unload the FIFO into a ring buffer during 
interrupts and to have the NAPI routine unload that. No problems since then.

 > kernel is 3.18.14

Then you SHOULD be better off than we were, running 3.4. In that version 
the FlexCAN controller uses NAPI (and always has) while the Ethernet 
controller didn't, but would happily try and unload 100 Ethernet packets 
all the way to the network layer in the interrupt routine, blocking the 
FlexCAN interrupts and NAPI run.

So check your Ethernet driver and see if it uses NAPI and if there's any 
work-limiting in the interrupt routine.

Flood ping (ping -f -l 20) one of them and see if that makes the 
overruns worse during your CAN test.

Run cangen with an 8-byte CAN packet and see if the lower arrival rate 
fixes it. Change the message length and see if you can use that to 
"measure the latency".

Then see what other interrupts you're getting. Try:

     while true; do cat /proc/interrupts; sleep 1; done

See which interrupt counts (apart from FlexCAN) are increasing quickly.

Then you'll want to FTRACE (CONFIG_PERF_EVENTS) the kernel. The Kernel 
Tracing is very good and very powerful. Learning how to run this is a 
skill very worth having. You want to find where it is spending its time 
between the interrupt and the NAPI run.

In our case we found our kernel was spending the majority of its time in 
mutex, spinlock and slub debugging. It got six times faster when I got 
rid of those.

Tom

Re: CAN question: how to trace frame errors?

[Holger Schurig]

Thanks for the thorought answer.

> so I rewrote the 3.4 FlexCAN driver to unload the FIFO into a ring buffer
> during interrupts and to have the NAPI routine unload tha

Can you publish it?  I might mangle it into a form so that I can sent
it as a patch to Linux HEAD (and use it by myself, LOL)

> Since the CPU is running at 800MHz, that's only 560,000 instructions

I'm running with 1 GHz, but that's still not stellar. I think I'll
look into the things you mentioned (e.g. I'm using the framebuffer
from staging, CONFIG_FRM_IMX, but I don't have the debug things
enabled you mentioned).

Re: CAN question: how to trace frame errors?

[Tom Evans]

On 13/06/2015 12:24 AM, Holger Schurig wrote:
> Thanks for the thorought answer.
>
>> so I rewrote the 3.4 FlexCAN driver to unload the FIFO into a ring buffer
>> during interrupts and to have the NAPI routine unload tha
>
> Can you publish it?

This is Open Source, so yes.

> I might mangle it into a form so that I can sent
> it as a patch to Linux HEAD (and use it by myself, LOL)

I have sent the patch to flexcan.c in kernel 3.4 to Holger. It is a 
fairly obvious modification with the buffer-reading code moved to the 
interrupt routine, loading up a ring buffer.

>> Since the CPU is running at 800MHz, that's only 560,000 instructions
>
> I'm running with 1 GHz, but that's still not stellar. I think I'll
> look into the things you mentioned (e.g. I'm using the framebuffer
> from staging, CONFIG_FRM_IMX, but I don't have the debug things
> enabled you mentioned).

The CPU is seriously busy. It is very busy doing things in the order it 
(and all the programmers who wrote it) think is appropriate, but it 
isn't doing what we need to get the job done.

Changing the driver is a "bandage" fixing the first annoying symptom of 
the underlying problem. I found the problem in our case (the 
CONFIG_DEBUG stuff mainly), but put in the driver changes as well as I 
wanted it to stay fixed in the face of kernel changes.

Another thing I changed. CPUs have had multiple interrupt priorities 
(with interrupts being able to interrupt other ones) all the way back to 
the PDP11, then carried through the 68000 and ColdFire chips. But not in 
Linux on ARM on these chips (at least TZIC in i.MX53 in 3.4). There's 
only a single level of interrupt, and while the CPU supports different 
interrupt priorities, the 3.4 TZIC code simply doesn't provide the 
functions to change it. As a result the interrupt priority is that 
implemented by tzic_handle_irq(), which is to take the first-one-set in 
HIPND registers 0 to 3, in that order. In the i.MX53 that puts the FEC 
interrupt ahead of the CAN ones. I think it puts about 74 interrupts 
ahead of the CAN ones. So I added code to allow the interrupt priorities 
to be changed so as to reverse that.

Tom

Re: CAN question: how to trace frame errors?

[Holger Schurig]

> and while the CPU supports different interrupt priorities, the 3.4 TZIC code
> simply doesn't provide the functions to change it.

I don't know the i.MX5x and it's TZIC, only the i.MX6 ... and only a
bit. But I think there it's not a limitation in the silicon, but in
the software (Linux in our case, e.g. drivers/irqchips/gic*). The
i.MX6 uses the GIC (described in the ARM MPCORE reference manual). And
there it says:

------------------------
The interrupt distributor centralizes all interrupt sources before
dispatching them to each individual Cortex-A9 processor. The Interrupt
Distributor arbitrates in the following priority order:
1. Highest priority interrupts. These have the lowest value in the
Interrupt Priority Register (ICDIPTR)
2. For interrupts with the same priority value, the Interrupt
Distributor arbitrates on the interrupt ID number. It dispatches the
smaller ID number first
3. For aliased SGI with the same priority value and the same ID
number, the Interrupt Distributor arbitrates on the source CPU number.
It dispatches the smaller CPU number first.
------------------------

This register ICDIPTR is called GIC_DIST_PRI in Linux and they all get
set to a fixed value. So it's the IRQ number that set's the IRQ
priority in current Linux.


And btw, thanks for your patch. I'll probably rewrite it to use kfifo,
which is a ringbuffer already contained in Linux (see
include/linux/kfifo.h), I think that will increase it's chance of
inclusion.

Re: CAN question: how to trace frame errors?

[Tom Evans]

On 14/06/2015 6:28 AM, Holger Schurig wrote:
>> and while the CPU supports different interrupt priorities, the 3.4 TZIC code
>> simply doesn't provide the functions to change it.
>
> I don't know the i.MX5x and it's TZIC, only the i.MX6 ... and only a
> bit. But I think there it's not a limitation in the silicon, but in
> the software (Linux in our case, e.g. drivers/irqchips/gic*).

I think Linux has to cater for the "lowest common denominator hardware", 
so features like priority interrupts aren't used/supported for the cases 
where they simply aren't present.

> And btw, thanks for your patch. I'll probably rewrite it to use kfifo,
> which is a ringbuffer already contained in Linux (see
> include/linux/kfifo.h), I think that will increase it's chance of
> inclusion.

I think there'll be a architectural/philosophical push-back against a 
change that makes an interrupt service routine take longer. I'll let 
those with more experience than me make this case.

Data point. Reading pretty much any peripheral register (in any ISR) 
takes 180ns on an i.MX53, and I'd expect similar with the i.MX6 [1]. 
Reading the entire FIFO would take four reads/message plus another 
couple for the status words for each entry, so about 7us or 7000 CPU 
clocks at 1GHz.

But here's a compromise. The FlexCAN controller has nearly 70 different 
interrupt sources, although normally only a few are enabled. 
FLEXCANx_IFLAG1[bit 5] is "at least one frame in FIFO" and 
FLEXCANx_IFLAG1[bit 6] is "FIFO nearly full" (4 out of 6).

So I'd suggest enabling both of them and having the code work like it 
does now for the normal interrupt, but have the "FIFO nearly full" one 
trigger an unload (to the ring buffer) within the interrupt. That would 
result in a fast interrupt routine most of the time, only taking a bit 
longer when needed to avoid overflow. Synchronising the reads in the ISR 
and the ones in NAPI "left as an interesting exercise for the 
programmer" (especially trying to test it properly :-).

Slow peripheral reads (even OCRAM is slow) discussed here:

https://community.freescale.com/thread/355199

Tom

Re: CAN question: how to trace frame errors?

[Holger Schurig]

Just a little feedback. Tom sent me his flexcan-ringbuffer patch. I
modified this patch to use not a self-written ringbuffer, but kfifo.
If someone wants it, I can post that here. However, this only helped a
little bit. I had less frame loss, but not zero frame loss for 80% CAN
bus utilization. For example, when I updated my image (on eMMC, via
i.MX6 SDHCI) over ethernet (i.MX6 FEC), I still had frame losses. I
even modified the GIC to give the IRQs 182/183 more priority, but
because an IRQ doesn't preempt another IRQ this wasn't even noticable.

Then I tried 3.18-rt10 (CONFIG_PREEMPT_RT). That completely removed
the CAN frame losses.

Success?

Not at all. A Linux with CONFIG_PREMEMPT_RT is basically another Linux
that behaves a bit like Linux, but really isn't. And it's a lot more
unstable. I had problems with eth0 (FEC), e.g. it didn't survive a
flood ping. One time logging in at the text console hanged. And after
an rsync update of the image the ext4 filesystem was corrupt. So my
CONFIG_PREEMPT_RT attempt just showed that really the latency is the
killer, due to the very small RxFIFO with only 6 places.

I tried to find out with FTRACE to see who creates the most latency,
but results where incongruent. I now forgot the name of the function,
but it showed to me that some sleep mode function was creating the
most latency. Changing things like NOHZ to 1000 Hz polling didn't help
either.
--
To unsubscribe from this list: send the line "unsubscribe linux-can" in

Re: CAN question: how to trace frame errors?

[Marc Kleine-Budde]

[-- Attachment #1: Type: text/plain, Size: 595 bytes --]

On 06/22/2015 02:17 PM, Holger Schurig wrote:
> Just a little feedback. Tom sent me his flexcan-ringbuffer patch. I
> modified this patch to use not a self-written ringbuffer, but kfifo.
> If someone wants it, I can post that here. However, this only helped a
> little bit.

Please post it here.

Thanks,
Marc
-- 
Pengutronix e.K.                  | Marc Kleine-Budde           |
Industrial Linux Solutions        | Phone: +49-231-2826-924     |
Vertretung West/Dortmund          | Fax:   +49-5121-206917-5555 |
Amtsgericht Hildesheim, HRA 2686  | http://www.pengutronix.de   |


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 455 bytes --]

Re: CAN question: how to trace frame errors?

[Holger Schurig]

Okay, I'm now switched to Linux to 4.0.6, applied CONFIG_PREEMPT_RT
4.0.5-rt4 on top of it and enabled PREEMPT_RT_FULL. I had to disable
CPU_FREQ, otherwise I had weird errors (despite using the performance
governor). The system booted, but systemd said that a call to loadkeys
failed. I got the idea to remove CPU_FREQ from the Xinomai project :-)

Unfortuantely, removing CPU_FREQ also took IMX_THERMAL with it. So I
can't see the die temperature anymore in /sys/.

This time the system seems to behave more stable. I had however once a
hard lock when I started X11. Keyboard didn't work anymore, mouse
neither. Unfortunately I had not redirected output to the serial port.
And it only happened once so far. Still not convincing.

With that, I still had CAN frame losses until I applied the
flexcan-kfifo patch that I posted. I think that with a pristine
flexcan.c, the the latency [IRQ, flexcan_irq(), flexcan_poll()] is
still to long.



I'm not really fond of adding a 771 kB long patch (CONFIG_PREEMPT_RT)
to my system that worked stable since at least half a year. So I
pondered about using the FIQ. There's no other driver using a FIQ on
my system (e.g. I don't use sound/soc/imx-fiq-pcm.c for sound over
SSI). I think writing a ringbuffer in ARM assembly is doable. The FIQ
ISR would then read the FlexCAN registers and write them into the
ringbuffer. And in case of data in the RxFIFO, it would empty it and
write it to the ringbuffer as well. Emptying this ringbuffer could
then again happen in flexcan_poll(). One building block that I'm still
missing for this would be how the FIQ-ISR could signal from
FIQ-context back to the normal Linux context that there is now data in
the ringbuffer.

This sound like lots of hoops, but such a change would make FlexCAN be
able to receive CAN packets even with 100% busload and very small
package sizes. And I wouldn't have to deal with the complexity of the
realtime kernel. They are frankly over my head ...

Re: CAN question: how to trace frame errors?

[Tom Evans]

On 25/06/15 00:29, Holger Schurig wrote:
> Okay, I'm now switched to Linux to 4.0.6, applied CONFIG_PREEMPT_RT
> 4.0.5-rt4 on top of it and enabled PREEMPT_RT_FULL. I had to disable
> CPU_FREQ, otherwise I had weird errors (despite using the performance
> governor). The system booted, but systemd said that a call to loadkeys
> failed. I got the idea to remove CPU_FREQ from the Xinomai project :-)

Huge amount of work to make it less stable.

I would strongly suggest you put some more time on on FTRACE.

Linux really isn't meant to be locking interrupts out for that long. It isn't 
meant to be locking NAPI out for that long either.

There's a broken or at least severely inconsiderate driver or something 
locking out interrupts for a very long time. It would be very well worth 
finding this, and not just for the sake of CAN. It should be affecting other 
things too.

The trick is enabling the right tracer. Or just enable more of them than you 
have already. Then getting the trigger right (CAN saying it has overflowed).

Tom