can: fix loss of frames due to wrong assumption in raw_rcv

I've detected a massive loss of can frames on i.MX6 using flexcan driver with 4.1-rc8 and tracked this down to following commit:
514ac99c64b22d83b52dfee3b8becaa69a92bc4a - "can: fix multiple delivery of a single CAN frame for overlapping CAN filters"

514ac99c64b22d83b52dfee3b8becaa69a92bc4a introduces a frame equality check. Since the sk_buff pointer is not sufficient to do this (buffers are reused), the check also compares time stamps.
In short: pointer+time stamp was assumed as unique key to a specific frame.
The problem with this is, that the time stamp is an optional property and not set per default.
In our case (flexcan) the time stamp is always zero, so the equality check is reduced to equality of buffer pointers, resulting in a lot of dropped frames.

Possible solutions I thought of:
1. Every driver has to set a time stamp
(possibly error prone and hard to enforce?)
2. Change the equality check
3. Fulfil the requirements of the equality check by setting a time stamp per default.

This patch fixes the problem with solution 3. A time stamp is set at time of allocation in alloc_can_skb.

The time stamp may be overridden later, but the function of the equality check is ensured.

I'm not really deep in linux network subsystem, so there may exists more elegant solutions for the problem.

Signed-off-by Manfred Schlaegl <[email protected]>

---
 drivers/net/can/dev.c |    1 +
 1 file changed, 1 insertion(+)

drivers/net/can/dev.c +0 -0

index b0f6924..282e2e7 100644

Quoted 10 lines

514ac99c64b22d83b52dfee3b8becaa69a92bc4a introduces a frame equality check. Since the sk_buff pointer is not sufficient to do this (buffers are reused), the check also compares time stamps.
In short: pointer+time stamp was assumed as unique key to a specific frame.
The problem with this is, that the time stamp is an optional property and not set per default.
In our case (flexcan) the time stamp is always zero, so the equality check is reduced to equality of buffer pointers, resulting in a lot of dropped frames.

The question is why your system did not generate a timestamp at the time of skb reception.

Usually when netif_rx(), netif_rx_ni() is invoked the timestamp is set in the following reception process.

flexcan.c only uses netif_receive_skb() - but all theses functions set the timestamp

	net_timestamp_check(netdev_tstamp_prequeue, skb);

depending on netdev_tstamp_prequeue which is configured by

/proc/sys/net/core/netdev_tstamp_prequeue

See the idea of netdev_tstamp_prequeue here:

http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/net/core/sysctl_net_core.c?id=3b098e2d7c693796cc4dffb07caa249fc0f70771

Can you tell me the output of /proc/sys/net/core/netdev_tstamp_prequeue on your machine?

Thanks again for your investigation!

Quoted 2 lines

Can you tell me the output of /proc/sys/net/core/netdev_tstamp_prequeue on your machine?

/proc/sys/net/core/netdev_tstamp_prequeue is set to 1 (unmodified, default)

I tried to dig a little deeper in timestamping:
1. (net/core/dev.c) I found that static_key_false(&netstamp_needed) is always 0, resulting that the timestamp is never set by net_timestamp_check in netif_receive_skb_internal.
2. (net/core/dev.c) static_key_false(&netstamp_needed) is 0 because net_enable_timestamp is never called.
3. (net/core/sock.c) net_enable_timestamp is never called because SK_FLAGS_TIMESTAMP is not set
4. (net/core/sock.c) SK_FLAGS_TIMESTAMP is not set because neither of SOCK_TIMESTAMP or SOCK_TIMESTAMPING_RX_SOFTWARE is set
5. (net/core/sock.c) SOCK_TIMESTAMP or SOCK_TIMESTAMPING_RX_SOFTWARE is not set because timestamping is an optional feature (according to http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/networking/timestamping.txt?id=b953c0d234bc72e8489d3bf51a276c5c4ec85345) not enabled in my use case (even if netdev_tstamp_prequeue is set to 1)

So the original assumption for the was correct: The correctness of the skb equality check depends on a feature that is not enabled by default (respectively user configurable). Do you agree with this?

Quoted 10 lines · Oliver Hartkopp

But the point becomes an issue when there's no userspace application that requires timestamps.

I did my testing wile having at least one "candump" instances running, which enables timestamping. So when there's no one requesting timestamps the check in can_rcv does not perform properly.

Therefor my patch grabs your idea to set the timestamps for CAN skbs unconditionally. But there were some more places in the code where we need to take care about that.

The original patch contains:

(quoted diff) +9 -0

+    /* eliminate multiple filter matches for the same skb */
+    if (this_cpu_ptr(ro->uniq)->skb == oskb &&
+        ktime_equal(this_cpu_ptr(ro->uniq)->tstamp, oskb->tstamp)) {
+        return;
+    } else {
+        this_cpu_ptr(ro->uniq)->skb = oskb;
+        this_cpu_ptr(ro->uniq)->tstamp = oskb->tstamp;
+    }
+

Mightn't it be more robust if the above check didn't filter out a packet if either of the timestamps weren't set (were zero)? Assuming the structures are zeroed before this gets set.

Hi Tom,

Quoted 24 lines · Tom Evans

Quoted 10 lines · Oliver Hartkopp

But the point becomes an issue when there's no userspace application that requires timestamps.

I did my testing wile having at least one "candump" instances running, which enables timestamping. So when there's no one requesting timestamps the check in can_rcv does not perform properly.

Therefor my patch grabs your idea to set the timestamps for CAN skbs unconditionally. But there were some more places in the code where we need to take care about that.

The original patch contains:

(quoted diff) +9 -0

+    /* eliminate multiple filter matches for the same skb */
+    if (this_cpu_ptr(ro->uniq)->skb == oskb &&
+        ktime_equal(this_cpu_ptr(ro->uniq)->tstamp, oskb->tstamp)) {
+        return;
+    } else {
+        this_cpu_ptr(ro->uniq)->skb = oskb;
+        this_cpu_ptr(ro->uniq)->tstamp = oskb->tstamp;
+    }
+

Quoted 3 lines

Mightn't it be more robust if the above check didn't filter out a packet if either of the timestamps weren't set (were zero)? Assuming the structures are zeroed before this gets set.

Yes. But the source just moved on with the introduction of joined filters. And when you don't have a unique skb detection the joint filter mechanic fails totally.

An alternative to force the timestamp to be set would be to add another 'counter' to struct can_skb_priv which is just increased by the driver with every received CAN frame.

But I wonder if its worth the effort in opposite to just enable timestamping in every skb. What do you think?

Quoted 6 lines · Oliver Hartkopp

An alternative to force the timestamp to be set would be to add another 'counter' to struct can_skb_priv which is just increased by the driver with every received CAN frame.

But I wonder if its worth the effort in opposite to just enable timestamping in every skb. What do you think?

From a programming standpoint, using a "timestamp" as a "unique identifier"
is opaque and a poor design. If the SKB requires a "unique identifier" then it should be provided with something that has that description and purpose.

The timestamp may be optional for a reason. Maybe some platforms simply don't provide a high resolution timestamp, and/or the timestamp comes with a high overhead. Can you guarantee that all current, future and past platforms support a low overhead and high resolution timestamp?

A new "feature" probably shouldn't change something that was optional to being compulsory. Would all existing CAN drivers need to be rewritten to add this timestamping, or is the timestamp added in higher (and more generic) layers, and in the one place?

Quoted 5 lines · Tom Evans

Quoted 4 lines · Oliver Hartkopp

An alternative to force the timestamp to be set would be to add another 'counter' to struct can_skb_priv which is just increased by the driver with every received CAN frame.

Quoted 7 lines

Quoted 2 lines

But I wonder if its worth the effort in opposite to just enable timestamping in every skb. What do you think?

From a programming standpoint, using a "timestamp" as a "unique
identifier"
is opaque and a poor design. If the SKB requires a "unique identifier" then it should be provided with something that has that description and purpose.

Hey Tom,

Quoted 4 lines

The timestamp may be optional for a reason. Maybe some platforms simply don't provide a high resolution timestamp, and/or the timestamp comes with a high overhead. Can you guarantee that all current, future and past platforms support a low overhead and high resolution timestamp?

I have used the CAN stuff on two PowerPC, one ARM and several x86 platforms - always with enabled timestamping - without any problems in performance.

Quoted 4 lines

A new "feature" probably shouldn't change something that was optional to being compulsory. Would all existing CAN drivers need to be rewritten to add this timestamping, or is the timestamp added in higher (and more generic) layers, and in the one place?

The point is that out-of-tree drivers (like the PEAK-System driver) would need to set the timestamp too to take advantage of the joint filter feature. The mainline drivers are adapted for now with the stable patch

http://git.kernel.org/cgit/linux/kernel/git/davem/net.git/commit/?id=36c01245eb8046c16eee6431e7dbfbb302635fa8

But I felt not very comfortable with this fix. The point is that I have to take care that the processing of an incoming skb in can_receive() in af_can.c is done in 'one step' with an unique skb. So marking the skb for the joint filter feature in raw_rcv() can probably be done in can_receive().

I'm looking for a SMP save solution for this - to finally revert the fix above. So thanks for the 'wake-up call' by naming the timestamping solution a 'poor design' ;-)

Best regards,
Oliver

Signature · 3 lines

To unsubscribe from this list: send the line "unsubscribe linux-can" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Stephane Grosjean <[email protected]> hat am 25. Juni 2015 um 10:32 geschrieben:

Hi everyone,

I follow this thread carefully and, with your permission, I'd like to speak in.

As we always help our customers in using the mainline drivers products line too, I just wanted to inform you that I currently have one who tells that he's facing some loss of frames with the PEAK-System PCAN-USB adapter, in case of "relatively" high bus load... He's running two Kernels (3.19 and the last 4.1 patched with this recent "fix"). At the moment, he says he always notes some frame leakage, especially when he (for example) "resizes windows on his desktop"...

The curious things are:

0 - frames are lost when running his socket-can application over the mainline peak-usb driver
1 - frames are lost when running his socket-can application over our "pcan" driver (built in so-called "netdev" mode, that is, rx frames are forwarded to socket-can using netif_rx())
2 - *but* no frame are lost when running the "ioctl()" test applications above our "pcan" driver (built in so-called "chardev" mode, that is, rx frames are stored into internal fifos before being given to applications) 3 - in both cases #0 and #1, "can0" network stats don't show any rx_dropped nor rx_fifo_errors errors at all (even if sometimes, he says he notes some "real" rx_over_errors raised up by the peak-usb driver).

I don't succeed to reproduce this issue with my "old" 3.16 Kernel at the moment. Before going on with installing the 3.19 Kernel, could the above "leakage" be explained by the last changes made in linux-can?

Many thanks for your help,

Regards,

Stéphane

Quoted 53 lines · Oliver Hartkopp

Quoted 10 lines · Tom Evans

Quoted 8 lines · Oliver Hartkopp

An alternative to force the timestamp to be set would be to add another 'counter' to struct can_skb_priv which is just increased by the driver with
every received CAN frame.

But I wonder if its worth the effort in opposite to just enable timestamping
in every skb. What do you think?

Quoted 5 lines

From a programming standpoint, using a "timestamp" as a "unique
identifier"
is opaque and a poor design. If the SKB requires a "unique identifier" then it
should be provided with something that has that description and purpose.

Hey Tom,

Quoted 6 lines

The timestamp may be optional for a reason. Maybe some platforms simply don't
provide a high resolution timestamp, and/or the timestamp comes with a high
overhead. Can you guarantee that all current, future and past platforms support a low overhead and high resolution timestamp?

I have used the CAN stuff on two PowerPC, one ARM and several x86 platforms - always with enabled timestamping - without any problems in performance.

Quoted 7 lines

A new "feature" probably shouldn't change something that was optional to being
compulsory. Would all existing CAN drivers need to be rewritten to add this
timestamping, or is the timestamp added in higher (and more generic) layers,
and in the one place?

The point is that out-of-tree drivers (like the PEAK-System driver) would need to set the timestamp too to take advantage of the joint filter feature.
The mainline drivers are adapted for now with the stable patch

http://git.kernel.org/cgit/linux/kernel/git/davem/net.git/commit/?id=36c01245eb8046c16eee6431e7dbfbb302635fa8

But I felt not very comfortable with this fix. The point is that I have to take care that the processing of an incoming skb in can_receive() in af_can.c is done in 'one step' with an unique skb. So marking the skb for the joint filter feature in raw_rcv() can probably be done in can_receive().

Quoted 11 lines

I'm looking for a SMP save solution for this - to finally revert the fix above. So thanks for the 'wake-up call' by naming the timestamping solution a 'poor design' ;-)

Best regards,
Oliver

Signature · 3 lines

To unsubscribe from this list: send the line "unsubscribe linux-can" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

--
PEAK-System Technik GmbH
Sitz der Gesellschaft Darmstadt
Handelsregister Darmstadt HRB 9183
Geschaeftsfuehrung: Alexander Gach, Uwe Wilhelm
--
--
To unsubscribe from this list: send the line "unsubscribe linux-can" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 8 lines

Stephane Grosjean <[email protected]>

(..)
tells that he's facing some loss of frames with the PEAK-System PCAN-USB adapter, in case of "relatively" high bus load... He's running two Kernels (3.19 and the last 4.1 patched with this recent "fix"). At the moment, he says he always notes some frame leakage, especially when he (for example) "resizes windows on his desktop"...

The patch

http://git.kernel.org/cgit/linux/kernel/git/davem/net-next.git/commit?id=36c01245eb8046c16eee6431e7dbfbb302635fa8

especially adds

    __net_timestamp(skb);

after dev_alloc_skb().

So you need to add this in pcan_netdev_rx() in pcan_netdev.c analogue to the patch above, e.g. directly after the successful dev_alloc_skb().

Can you check, if this fixes the issue with the (patched) 4.1 kernel?

Hi Stephane,

Quoted 7 lines · Oliver Hartkopp

Quoted 7 lines

Stephane Grosjean <[email protected]>
(..)
tells that he's facing some loss of frames with the PEAK-System PCAN-USB adapter, in case of "relatively" high bus load... He's running two Kernels (3.19 and the last 4.1 patched with this recent "fix"). At the moment, he says he always notes some frame leakage, especially when he (for example) "resizes windows on his desktop"...

Hi Stephane,
...
While testing the patches
...
I discovered an increase of out-of-order CAN frame receptions. My setup is a core i7 with a PCAN USB and a PCAN USB pro connected to my full busload CAN source (1MBit/s, ~8008 frames/s).

It's more with the PCAN USB and very few with PCAN USB pro.

I'm a bit confused as this effect seems to increase with Linux kernel version numbers.

Quoted 7 lines · Oliver Hartkopp

Hi Stephane,
...
While testing the patches
...
I discovered an increase of out-of-order CAN frame receptions. My setup is a core i7 with a PCAN USB and a PCAN USB pro connected to my full busload CAN source (1MBit/s, ~8008 frames/s).

Out of order reception is guaranteed with some CAN hardware and driver software, such as the MCP2515 controller and Linux. The chip doesn't implement a FIFO, but has two receive buffers which can give message swaps quite easily. This can be fixed in the driver, but nobody has. Details here:

http://www.microchip.com/forums/m620741.aspx

The PCAN-USB uses an SJA1000 which doesn't have that problem. It has a 64 byte FIFO. What is inside the PCAN-USB Pro isn't documented on their web page, but it may be faster or have less transaction overhead or latency or something.

The PCAN-USB Pro is "no longer manufactured", the replacement "PCAN-USB Pro FD" has an FPGA controller.

Quoted 1 line

It's more with the PCAN USB and very few with PCAN USB pro.

I'd guess the Pro has less overhead and can get messages over USB faster than the other one.

Quoted 2 lines

I'm a bit confused as this effect seems to increase with Linux kernel version numbers.

As for the later kernels being worse, that looks like a simple case of "bloat", with them taking longer to get around to servicing the interrupts and reading the messages. Earlier ones are probably reading CAN messages one at a time, with each one getting through the stack before the next one arrives. Later kernels are probably reading them in bursts. Slower controllers (PCAN-USB) expose this sooner.

Can you drop back to a single core to see if this is a multicore problem? It will either fix it or make it worse if it is a loading/delay problem.

Reordering packets should be considered a serious bug as some CAN protocols can't handle this at all.

With

# echo 1 > /proc/irq/28/smp_affinity

I assigned the IRQ 28 to CPU0 and it now looks like this:

# cat /proc/interrupts
            CPU0       CPU1       CPU2       CPU3
   0:         23          0          0          0  IR-IO-APIC   2-edge      timer
(..)
  28:    9072996      53480     766233    2125901  IR-PCI-MSI 327680-edge      xhci_hcd
(..)

and all the out-of-order receptions were totally gone! \o/

/me again

Quoted 2 lines · Oliver Hartkopp

With

Quoted 4 lines

# echo 1 > /proc/irq/28/smp_affinity
..
and all the out-of-order receptions were totally gone! \o/

I ran the test for 11 hours now (3 x 8000 = 24.000 frames/s).

No single out-of-order frame this time - not even with the PCAN-USB.

CPU Affinity may fix this problem, but I suspect there should be a more "standard" fix. This sort of problem (multiple CPUs fielding interrupts and getting them out of order) should show up elsewhere. It might even swap bytes from a UART.

There must be a "standard synchronization technique" of some sort that provides the proper sequencing here. Can anyone else reading this thread who knows if this is right please chime in?

Google finds:

http://www.alexonlinux.com/why-interrupt-affinity-with-multiple-cores-is-not-such-a-good-thing

Hi Stephane,

Quoted 10 lines · Oliver Hartkopp

Hi Stephane,

Quoted 7 lines · Oliver Hartkopp

Quoted 7 lines

Stephane Grosjean <[email protected]>
(..)
tells that he's facing some loss of frames with the PEAK-System PCAN-USB adapter, in case of "relatively" high bus load... He's running two Kernels (3.19 and the last 4.1 patched with this recent "fix"). At the moment, he says he always notes some frame leakage, especially when he (for example) "resizes windows on his desktop"...

Is $COSTUMERs problem fixed now?

While testing the patches

can: fix loss of CAN frames in raw_rcv
http://git.kernel.org/cgit/linux/kernel/git/mkl/linux-can.git/commit/?h=testing&id=36c01245eb8046c16eee6431e7dbfbb302635fa8

and

can: replace timestamp as unique skb attribute
http://git.kernel.org/cgit/linux/kernel/git/mkl/linux-can.git/commit/?h=testing&id=a6ffebda241e513f6e839662d769b60b084d0957

I discovered an increase of out-of-order CAN frame receptions.
My setup is a core i7 with a PCAN USB and a PCAN USB pro connected to my full busload CAN source (1MBit/s, ~8008 frames/s).

With 3.16 the out-of-order CAN frame reception is 'relatively' seldom. It's more with the PCAN USB and very few with PCAN USB pro.

With the latest 4.2-merge the effect is reproducible after some time (~10min).

Examples:

drop detected: expected 204 received 212
drop detected: expected 237 received 204
drop detected: expected 212 received 237
drop detected: expected 68 received 69
drop detected: expected 70 received 68
drop detected: expected 69 received 70

Obviously the frames do not get lost BUT are reordered.

newcounter = frame.data[0];
if (((counter + 1) & 0xFF) != newcounter) {
printf(" drop detected: expected %u received %u\n", counter + 1,
newcounter);
}
counter = newcounter;

I'm a bit confused as this effect seems to increase with Linux kernel version numbers. I removed all the changes for 4.1 in the 4.2-merge kernel to have a 4.0 CAN subsystem (which was stable for a long time)
- but even this patch removal did not fix the out of order reception.

Good thing: The latest changes in 4.1 (which patches) do not drop CAN frames by accident.

Bad thing: Why is the out-of-order reception increasing in Linux?

I /assume/ some changes with RPS (receive packet steering) in the network layer ...

Regards,
Oliver

Signature · 3 lines

To unsubscribe from this list: send the line "unsubscribe linux-can" in
the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

${CUSTOMER}'s problem was rather a "loss of frame" issue than an "out-of-order" issue... In fact, it seems it was a simple "rookie" error of non-testing errno == ENOBUF after having written on the CAN socket.