can: isotp: omit unintended hrtimer restart on socket release

PATCH In review Oliver Hartkopp 3 participants 10 messages Jun 18, 2021 – Aug 30, 2021

Subsystems (2)

CAN network drivers CAN network layer

lore

Share & tools

lore

Oliver Hartkopp

author maintainer

2021-06-18 17:37 UTC #0 lore raw

PATCH 1/1 can: isotp: omit unintended hrtimer restart on socket release

When closing the isotp socket the potentially running hrtimers are canceled before removing the subscription for CAN idendifiers via can_rx_unregister().

This may lead to an unintended (re)start of a hrtimer in isotp_rcv_cf() and isotp_rcv_fc() in the case that a CAN frame is received by isotp_rcv() while the subscription removal is processed.

However, isotp_rcv() is called under RCU protection, so after calling can_rx_unregister, we may call synchronize_rcu in order to wait for any RCU read-side critical sections to finish. This prevents the reception of CAN frames after hrtimer_cancel() and therefore the unintended (re)start of the hrtimers.

Signed-off-by Oliver Hartkopp <[email protected]>

---
 net/can/isotp.c | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

net/can/isotp.c +4 -3

index be6183f8ca11..234cc4ad179a 100644
@@ -1026,13 +1026,10 @@ static int isotp_release(struct socket *sock)
 	list_del(&so->notifier);
 	spin_unlock(&isotp_notifier_lock);
 
 	lock_sock(sk);
 
-	hrtimer_cancel(&so->txtimer);
-	hrtimer_cancel(&so->rxtimer);
-
 	/* remove current filters & unregister */
 	if (so->bound && (!(so->opt.flags & CAN_ISOTP_SF_BROADCAST))) {
 		if (so->ifindex) {
 			struct net_device *dev;

@@ -1040,14 +1037,18 @@ static int isotp_release(struct socket *sock)
 			if (dev) {
 				can_rx_unregister(net, dev, so->rxid,
 						  SINGLE_MASK(so->rxid),
 						  isotp_rcv, sk);
 				dev_put(dev);
+				synchronize_rcu();
 			}
 		}
 	}
 
+	hrtimer_cancel(&so->txtimer);
+	hrtimer_cancel(&so->rxtimer);
+
 	so->ifindex = 0;
 	so->bound = 0;
 
 	sock_orphan(sk);
 	sock->sk = NULL;

Signature · 1 line

2.30.2

Marc Kleine-Budde

maintainer

2021-06-19 21:36 UTC #1 lore raw

Quoted 8 lines · Oliver Hartkopp

When closing the isotp socket the potentially running hrtimers are canceled before removing the subscription for CAN idendifiers via can_rx_unregister().
This may lead to an unintended (re)start of a hrtimer in isotp_rcv_cf() and isotp_rcv_fc() in the case that a CAN frame is received by isotp_rcv() while the subscription removal is processed.

Quoted 7 lines

However, isotp_rcv() is called under RCU protection, so after calling can_rx_unregister, we may call synchronize_rcu in order to wait for any RCU read-side critical sections to finish. This prevents the reception of CAN frames after hrtimer_cancel() and therefore the unintended (re)start of the hrtimers.
Signed-off-by Oliver Hartkopp <[email protected]>

Added to linux-can/testing

Thanks,
Marc

Signature · 4 lines

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

Sven Schuchmann

2021-08-28 13:20 UTC #2 lore raw

In reply to Oliver Hartkopp

Hello,
sorry, I'm late for the party :-)
But I found that this patch decreases the performance of ISO-TP Stack.

I have created two testscripts where one plays the server and the other one is running a test and measuring the time how long it takes to transfer an ISO-TP Frame with 1000 Bytes.

Without this patch it takes about 35ms to transfer the frame, with this patch it takes about 145ms over vcan0.

Anyone an idea on this?

Sven

bring up a vcan0 interface with:
sudo modprobe vcan
sudo ip link add dev vcan0 type vcan
sudo ifconfig vcan0 up

here are the scripts:
--- isotp_server.sh ---
#!/bin/bash
iface=vcan0
echo "Wait for Messages on $iface"
while true; do

    exec 3< <(isotprecv -s 77E -d 714 -b F -p AA:AA $iface)
    rxpid=$!
    wait $rxpid
    output=$(cat <&3)
    echo "7F 01 11" | isotpsend -s 77E -d 714 -p AA:AA -L 16:8:0 $iface

done

--- isotp_test.sh ---
#!/bin/bash
databyte=01
numbytes=1000
iface=vcan0
echo "Test iso-tp with $numbytes byte frames on $iface (data:$databyte)" message="01 " # invalid service 01
for (( i=1; i<=$numbytes; i++ ))
do
message="$message$databyte "
done
i=1
timemin=10000
timemax=0
timesum=0
while true; do

    ts=$(date +%s%N)
    exec 3< <(isotprecv -s 714 -d 77E -b 5 $iface)
    rxpid=$!
    echo $message | isotpsend -s 714 -d 77E -p AA:AA -L 16:8:0 $iface
    wait $rxpid
    output=$(cat <&3)
    timediff=$((($(date +%s%N) - $ts)/1000000))
    if [ "7F 01 11 " != "$output" ]; then
        echo "ERROR: $i >$output<"
        break
    fi
    if [ $timediff -gt $timemax ]; then
        timemax=$timediff
    fi
    if [ $timediff -lt $timemin ]; then
        timemin=$timediff
    fi
    ((timesum=timesum+timediff))
    timeavg=$(echo "$timesum / $i" | bc -l)
    printf "%5d / curr:%5d / min:%5d / max:%5d / avg:%7.1f\n" $i $timediff $timemin $timemax $timeavg
    ((i=i+1))

done
------

Sven Schuchmann
Schleißheimer Soft- und
Hardwareentwicklung GmbH
Am Kalkofen 10
61206 Nieder-Wöllstadt
GERMANY
Phone: +49 6034 9148 711
Fax: +49 6034 9148 91
Email: [email protected]

Court of Registration: Amtsgericht Friedberg
Registration Number: HRB 1581
Management Board:
Hans-Joachim Schleißheimer
Christine Schleißheimer

Quoted 65 lines

-----Ursprüngliche Nachricht-----
Von: Oliver Hartkopp <[email protected]>
Gesendet: Freitag, 18. Juni 2021 19:37
An: [email protected]
Cc: Oliver Hartkopp <[email protected]>
Betreff: [PATCH] can: isotp: omit unintended hrtimer restart on socket release
When closing the isotp socket the potentially running hrtimers are canceled before removing the subscription for CAN idendifiers via can_rx_unregister().
This may lead to an unintended (re)start of a hrtimer in isotp_rcv_cf() and isotp_rcv_fc() in the case that a CAN frame is received by isotp_rcv() while the subscription removal is processed.
However, isotp_rcv() is called under RCU protection, so after calling can_rx_unregister, we may call synchronize_rcu in order to wait for any RCU read-side critical sections to finish. This prevents the reception of CAN frames after hrtimer_cancel() and therefore the unintended (re)start of the hrtimers.
Signed-off-by Oliver Hartkopp <[email protected]>
---
 net/can/isotp.c | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)
net/can/isotp.c +4 -4
index be6183f8ca11..234cc4ad179a 100644
@@ -1026,13 +1026,10 @@ static int isotp_release(struct socket *sock)
 	list_del(&so->notifier);
 	spin_unlock(&isotp_notifier_lock);
 
 	lock_sock(sk);
 
-	hrtimer_cancel(&so->txtimer);
-	hrtimer_cancel(&so->rxtimer);
-
 	/* remove current filters & unregister */
 	if (so->bound && (!(so->opt.flags & CAN_ISOTP_SF_BROADCAST))) {
 		if (so->ifindex) {
 			struct net_device *dev;
 
@@ -1040,14 +1037,18 @@ static int isotp_release(struct socket *sock)
 			if (dev) {
 				can_rx_unregister(net, dev, so->rxid,
 						  SINGLE_MASK(so->rxid),
 						  isotp_rcv, sk);
 				dev_put(dev);
+				synchronize_rcu();
 			}
 		}
 	}
 
+	hrtimer_cancel(&so->txtimer);
+	hrtimer_cancel(&so->rxtimer);
+
 	so->ifindex = 0;
 	so->bound = 0;
 
 	sock_orphan(sk);
 	sock->sk = NULL;
--
2.30.2

Oliver Hartkopp

author maintainer

2021-08-29 11:21 UTC #3 lore raw

Hello Sven,

Quoted 1 line · Sven Schuchmann

sorry, I'm late for the party :-)

NP ;-)

Quoted 1 line

But I found that this patch decreases the performance of ISO-TP Stack.

AFAICS the performance (aka throughput) of the ISO-TP stack is not touched but the grace period when closing an ISO-TP socket is increased.

Quoted 8 lines

I have created two testscripts where one plays the server and the other one is running a test and measuring the time how long it takes to transfer an ISO-TP Frame with 1000 Bytes.
Without this patch it takes about 35ms to transfer the frame, with this patch it takes about 145ms over vcan0.
Anyone an idea on this?

Yes. We now syncronize the removal of data structures to prevent a use-after-free issue at socket close time.

The synchronize_rcu() call does this job at specific times which leads to this extended time the close() syscall needs to perform.

Quoted 11 lines

bring up a vcan0 interface with:
sudo modprobe vcan
sudo ip link add dev vcan0 type vcan
sudo ifconfig vcan0 up
here are the scripts:
--- isotp_server.sh ---
#!/bin/bash
iface=vcan0
echo "Wait for Messages on $iface"
while true; do

Quoted 6 lines

     exec 3< <(isotprecv -s 77E -d 714 -b F -p AA:AA $iface)
     rxpid=$!
     wait $rxpid
     output=$(cat <&3)
     echo "7F 01 11" | isotpsend -s 77E -d 714 -p AA:AA -L 16:8:0 $iface

done

IMO the issue arises with the use of isotpsend and isotprecv.
These tools are intended to get a hands-on impression how the isotp stack works.

This kind of use in a script leads to the creation and (now delayed) *removal* of isotp sockets for *each* single PDU transfer.

The better approach would be to write a C program that creates ONE socket and simply read() from that socket and write() to it.

This should boost your performance even more.

Is the performance a real requirement for your use-case or is this decreased socket close rate a finding which does not really affect your work?

Best regards,
Oliver

Sven Schuchmann

2021-08-29 18:28 UTC #4 lore raw

Hello Oliver,

Quoted 12 lines

Quoted 1 line
But I found that this patch decreases the performance of ISO-TP Stack.
AFAICS the performance (aka throughput) of the ISO-TP stack is not touched but the grace period when closing an ISO-TP socket is increased.
Quoted 7 lines
I have created two testscripts where one plays the server and the other one is running a test and measuring the time how long it takes to transfer an ISO-TP Frame with 1000 Bytes.
Without this patch it takes about 35ms to transfer the frame, with this patch it takes about 145ms over vcan0.

Quoted 7 lines

Quoted 1 line
Anyone an idea on this?
Yes. We now syncronize the removal of data structures to prevent a use-after-free issue at socket close time.
The synchronize_rcu() call does this job at specific times which leads to this extended time the close() syscall needs to perform.

understood

Quoted 19 lines

Quoted 12 lines
bring up a vcan0 interface with:
sudo modprobe vcan
sudo ip link add dev vcan0 type vcan
sudo ifconfig vcan0 up
here are the scripts:
--- isotp_server.sh ---
#!/bin/bash
iface=vcan0
echo "Wait for Messages on $iface"
while true; do
Quoted 6 lines
     exec 3< <(isotprecv -s 77E -d 714 -b F -p AA:AA $iface)
     rxpid=$!
     wait $rxpid
     output=$(cat <&3)
     echo "7F 01 11" | isotpsend -s 77E -d 714 -p AA:AA -L 16:8:0 $iface
done

Quoted 6 lines

IMO the issue arises with the use of isotpsend and isotprecv. These tools are intended to get a hands-on impression how the isotp stack works.
This kind of use in a script leads to the creation and (now delayed) *removal* of isotp sockets for *each* single PDU transfer.

Maybe I am wrong but I see something different.
e.g. without this patch:

 (000.000240)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
 (000.000261)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000496)  canfd0  714   [8]  2C 01 01 01 01 01 01 01

and with this patch:

 (000.000414)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
 (000.000262)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.001536)  canfd0  714   [8]  2C 01 01 01 01 01 01 01

So within one PDU transfer the first Consecutive Frame after a Flow Control is taking about 10ms longer (the consecutive frames are sent by ISO-TP Stack here, Tested against a "real" ECU.) So if I transfer a lot of data within one PDU,
the more Flow Controls I have and the more "delays" after each FC, and this increases the time for the whole PDU.)

Quoted 6 lines

The better approach would be to write a C program that creates ONE socket and simply read() from that socket and write() to it.
This should boost your performance even more.

Sure, I do have this. These two scripts are only lets say a "reproducer".

Quoted 3 lines

Is the performance a real requirement for your use-case or is this decreased socket close rate a finding which does not really affect your work?

We have a application here which flashes a ECU over CAN according to VW80126. So transferring the data as quick as possible to the ECU is a use-case.

Sven

Oliver Hartkopp

author maintainer

2021-08-29 20:14 UTC #5 lore raw

Quoted 52 lines · Sven Schuchmann

Hello Oliver,
Quoted 12 lines
Quoted 1 line
But I found that this patch decreases the performance of ISO-TP Stack.
AFAICS the performance (aka throughput) of the ISO-TP stack is not touched but the grace period when closing an ISO-TP socket is increased.
Quoted 7 lines
I have created two testscripts where one plays the server and the other one is running a test and measuring the time how long it takes to transfer an ISO-TP Frame with 1000 Bytes.
Without this patch it takes about 35ms to transfer the frame, with this patch it takes about 145ms over vcan0.
Quoted 7 lines
Quoted 1 line
Anyone an idea on this?
Yes. We now syncronize the removal of data structures to prevent a use-after-free issue at socket close time.
The synchronize_rcu() call does this job at specific times which leads to this extended time the close() syscall needs to perform.
understood
Quoted 19 lines
Quoted 12 lines
bring up a vcan0 interface with:
sudo modprobe vcan
sudo ip link add dev vcan0 type vcan
sudo ifconfig vcan0 up
here are the scripts:
--- isotp_server.sh ---
#!/bin/bash
iface=vcan0
echo "Wait for Messages on $iface"
while true; do
Quoted 6 lines
      exec 3< <(isotprecv -s 77E -d 714 -b F -p AA:AA $iface)
      rxpid=$!
      wait $rxpid
      output=$(cat <&3)
      echo "7F 01 11" | isotpsend -s 77E -d 714 -p AA:AA -L 16:8:0 $iface
done
Quoted 6 lines
IMO the issue arises with the use of isotpsend and isotprecv. These tools are intended to get a hands-on impression how the isotp stack works.
This kind of use in a script leads to the creation and (now delayed) *removal* of isotp sockets for *each* single PDU transfer.
Maybe I am wrong but I see something different.
e.g. without this patch:

Quoted 9 lines

  (000.000240)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000261)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000496)  canfd0  714   [8]  2C 01 01 01 01 01 01 01

and with this patch:

  (000.000414)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000262)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.001536)  canfd0  714   [8]  2C 01 01 01 01 01 01 01

I'm running a 5.14.0-rc7-00011-g6e764bcd1cf7 kernel here and see this:

 (000.000001)  vcan0  714   [8]  2B 01 01 01 01 01 01 01
 (000.000015)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000005)  vcan0  714   [8]  2C 01 01 01 01 01 01 01

Test iso-tp with 1000 byte frames on vcan0 (data:01)

    1 / curr:   40 / min:   40 / max:   40 / avg:   40.0
    2 / curr:   30 / min:   30 / max:   40 / avg:   35.0
    3 / curr:   35 / min:   30 / max:   40 / avg:   35.0
    4 / curr:   52 / min:   30 / max:   52 / avg:   39.2
    5 / curr:   40 / min:   30 / max:   52 / avg:   39.4

(..)

when running your scripts from the initial post.

Is you canfd0 interface a real hardware?

Best regards,
Oliver

Quoted 25 lines

So within one PDU transfer the first Consecutive Frame after a Flow Control is taking about 10ms longer (the consecutive frames are sent by ISO-TP Stack here, Tested against a "real" ECU.) So if I transfer a lot of data within one PDU,
the more Flow Controls I have and the more "delays" after each FC, and this increases the time for the whole PDU.)
Quoted 6 lines
The better approach would be to write a C program that creates ONE socket and simply read() from that socket and write() to it.
This should boost your performance even more.
Sure, I do have this. These two scripts are only lets say a "reproducer".
Quoted 3 lines
Is the performance a real requirement for your use-case or is this decreased socket close rate a finding which does not really affect your work?
We have a application here which flashes a ECU over CAN according to VW80126. So transferring the data as quick as possible to the ECU is a use-case.
Sven

Marc Kleine-Budde

maintainer

2021-08-29 20:28 UTC #6 lore raw

Quoted 31 lines · Oliver Hartkopp

Quoted 9 lines
Quoted 6 lines
IMO the issue arises with the use of isotpsend and isotprecv. These tools are intended to get a hands-on impression how the isotp stack works.
This kind of use in a script leads to the creation and (now delayed) *removal* of isotp sockets for *each* single PDU transfer.
Maybe I am wrong but I see something different.
e.g. without this patch:
Quoted 9 lines
  (000.000240)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000261)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000496)  canfd0  714   [8]  2C 01 01 01 01 01 01 01
and with this patch:
  (000.000414)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000262)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.001536)  canfd0  714   [8]  2C 01 01 01 01 01 01 01
I'm running a 5.14.0-rc7-00011-g6e764bcd1cf7 kernel here and see this:
 (000.000001)  vcan0  714   [8]  2B 01 01 01 01 01 01 01
 (000.000015)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000005)  vcan0  714   [8]  2C 01 01 01 01 01 01 01
Test iso-tp with 1000 byte frames on vcan0 (data:01)
    1 / curr:   40 / min:   40 / max:   40 / avg:   40.0
    2 / curr:   30 / min:   30 / max:   40 / avg:   35.0
    3 / curr:   35 / min:   30 / max:   40 / avg:   35.0
    4 / curr:   52 / min:   30 / max:   52 / avg:   39.2
    5 / curr:   40 / min:   30 / max:   52 / avg:   39.4

Quoted 5 lines

(..)
when running your scripts from the initial post.
Is you canfd0 interface a real hardware?

I can reproduce the issue here, on an embedded system with a real hardware CAN interface.

In j1939 we make use of rcu so that we don't need the synchronize_net(). Is it possible to use this is ISOTP, too?

regards,
Marc

Signature · 4 lines

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

Sven Schuchmann

2021-08-29 21:09 UTC #7 lore raw

In reply to Oliver Hartkopp

Hello Oliver,

Quoted 49 lines

Quoted 27 lines
Quoted 18 lines
Quoted 11 lines
bring up a vcan0 interface with:
sudo modprobe vcan
sudo ip link add dev vcan0 type vcan
sudo ifconfig vcan0 up
here are the scripts:
--- isotp_server.sh ---
#!/bin/bash
iface=vcan0
echo "Wait for Messages on $iface"
while true; do
Quoted 6 lines
      exec 3< <(isotprecv -s 77E -d 714 -b F -p AA:AA $iface)
      rxpid=$!
      wait $rxpid
      output=$(cat <&3)
      echo "7F 01 11" | isotpsend -s 77E -d 714 -p AA:AA -L 16:8:0 $iface
done
Quoted 6 lines
IMO the issue arises with the use of isotpsend and isotprecv. These tools are intended to get a hands-on impression how the isotp stack works.
This kind of use in a script leads to the creation and (now delayed) *removal* of isotp sockets for *each* single PDU transfer.
Maybe I am wrong but I see something different.
e.g. without this patch:
Quoted 9 lines
  (000.000240)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000261)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000496)  canfd0  714   [8]  2C 01 01 01 01 01 01 01
and with this patch:
  (000.000414)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000262)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.001536)  canfd0  714   [8]  2C 01 01 01 01 01 01 01
I'm running a 5.14.0-rc7-00011-g6e764bcd1cf7 kernel here and see this:
  (000.000001)  vcan0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000015)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000005)  vcan0  714   [8]  2C 01 01 01 01 01 01 01
Test iso-tp with 1000 byte frames on vcan0 (data:01)
     1 / curr:   40 / min:   40 / max:   40 / avg:   40.0
     2 / curr:   30 / min:   30 / max:   40 / avg:   35.0
     3 / curr:   35 / min:   30 / max:   40 / avg:   35.0
     4 / curr:   52 / min:   30 / max:   52 / avg:   39.2
     5 / curr:   40 / min:   30 / max:   52 / avg:   39.4

Quoted 6 lines

(..)
when running your scripts from the initial post.
Is you canfd0 interface a real hardware?

Yes, the canfd0 interface is a real hardware (a MCP2518FD connected to a RaspberryPi-4-Compute-Module).

I am running a 5.10.60 kernel.
With using the testscripts I provided I can see this:
with the patch:

    1 / curr:  147 / min:  147 / max:  147 / avg:  147.0
    2 / curr:  107 / min:  107 / max:  147 / avg:  127.0
    3 / curr:  118 / min:  107 / max:  147 / avg:  124.0
    4 / curr:  138 / min:  107 / max:  147 / avg:  127.5
    5 / curr:  115 / min:  107 / max:  147 / avg:  125.0
    6 / curr:  158 / min:  107 / max:  158 / avg:  130.5
    7 / curr:  140 / min:  107 / max:  158 / avg:  131.9

and without the patch:

   39 / curr:   42 / min:   28 / max:   45 / avg:   30.9
   40 / curr:   41 / min:   28 / max:   45 / avg:   31.2
   41 / curr:   28 / min:   28 / max:   45 / avg:   31.1
   42 / curr:   29 / min:   28 / max:   45 / avg:   31.0
   43 / curr:   31 / min:   28 / max:   45 / avg:   31.0
   44 / curr:   28 / min:   28 / max:   45 / avg:   31.0

but if I compare the candumps I can see:
with the patch:

 (000.000008)  vcan0  714   [8]  2F 01 01 01 01 01 01 01
 (000.000209)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000061)  vcan0  714   [8]  20 01 01 01 01 01 01 01

and without:

 (000.000004)  vcan0  714   [8]  2F 01 01 01 01 01 01 01
 (000.000069)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000017)  vcan0  714   [8]  20 01 01 01 01 01 01 01

sorry, I missed that: Over here the delay seems to be in the FC and not in the CF after the FC. This is what is different compared to the real hardware.

So to me it seems that the rcu implementation has changed on the way from 5.10 to 5.14?

Sven

Sven Schuchmann

2021-08-30 07:56 UTC #8 lore raw

Hello Oliver,

Quoted 92 lines

Quoted 49 lines
Quoted 27 lines
Quoted 18 lines
Quoted 11 lines
bring up a vcan0 interface with:
sudo modprobe vcan
sudo ip link add dev vcan0 type vcan
sudo ifconfig vcan0 up
here are the scripts:
--- isotp_server.sh ---
#!/bin/bash
iface=vcan0
echo "Wait for Messages on $iface"
while true; do
Quoted 6 lines
      exec 3< <(isotprecv -s 77E -d 714 -b F -p AA:AA $iface)
      rxpid=$!
      wait $rxpid
      output=$(cat <&3)
      echo "7F 01 11" | isotpsend -s 77E -d 714 -p AA:AA -L 16:8:0 $iface
done
Quoted 6 lines
IMO the issue arises with the use of isotpsend and isotprecv. These tools are intended to get a hands-on impression how the isotp stack works.
This kind of use in a script leads to the creation and (now delayed) *removal* of isotp sockets for *each* single PDU transfer.
Maybe I am wrong but I see something different.
e.g. without this patch:
Quoted 9 lines
  (000.000240)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000261)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000496)  canfd0  714   [8]  2C 01 01 01 01 01 01 01
and with this patch:
  (000.000414)  canfd0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000262)  canfd0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.001536)  canfd0  714   [8]  2C 01 01 01 01 01 01 01
I'm running a 5.14.0-rc7-00011-g6e764bcd1cf7 kernel here and see this:
  (000.000001)  vcan0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000015)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000005)  vcan0  714   [8]  2C 01 01 01 01 01 01 01
Test iso-tp with 1000 byte frames on vcan0 (data:01)
     1 / curr:   40 / min:   40 / max:   40 / avg:   40.0
     2 / curr:   30 / min:   30 / max:   40 / avg:   35.0
     3 / curr:   35 / min:   30 / max:   40 / avg:   35.0
     4 / curr:   52 / min:   30 / max:   52 / avg:   39.2
     5 / curr:   40 / min:   30 / max:   52 / avg:   39.4
Quoted 6 lines
(..)
when running your scripts from the initial post.
Is you canfd0 interface a real hardware?
Yes, the canfd0 interface is a real hardware (a MCP2518FD connected to a RaspberryPi-4-Compute-Module).
I am running a 5.10.60 kernel.
With using the testscripts I provided I can see this:
with the patch:
    1 / curr:  147 / min:  147 / max:  147 / avg:  147.0
    2 / curr:  107 / min:  107 / max:  147 / avg:  127.0
    3 / curr:  118 / min:  107 / max:  147 / avg:  124.0
    4 / curr:  138 / min:  107 / max:  147 / avg:  127.5
    5 / curr:  115 / min:  107 / max:  147 / avg:  125.0
    6 / curr:  158 / min:  107 / max:  158 / avg:  130.5
    7 / curr:  140 / min:  107 / max:  158 / avg:  131.9
and without the patch:
   39 / curr:   42 / min:   28 / max:   45 / avg:   30.9
   40 / curr:   41 / min:   28 / max:   45 / avg:   31.2
   41 / curr:   28 / min:   28 / max:   45 / avg:   31.1
   42 / curr:   29 / min:   28 / max:   45 / avg:   31.0
   43 / curr:   31 / min:   28 / max:   45 / avg:   31.0
   44 / curr:   28 / min:   28 / max:   45 / avg:   31.0
but if I compare the candumps I can see:
with the patch:
 (000.000008)  vcan0  714   [8]  2F 01 01 01 01 01 01 01
 (000.000209)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000061)  vcan0  714   [8]  20 01 01 01 01 01 01 01
and without:
 (000.000004)  vcan0  714   [8]  2F 01 01 01 01 01 01 01
 (000.000069)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000017)  vcan0  714   [8]  20 01 01 01 01 01 01 01

Quoted 6 lines

sorry, I missed that: Over here the delay seems to be in the FC and not in the CF after the FC. This is what is different compared to the real hardware.
So to me it seems that the rcu implementation has changed on the way from 5.10 to 5.14?

Just checked with a 5.14.0-rc6 which contains the patch, same result:

   93 / curr:  143 / min:  129 / max:  200 / avg:  156.2
   94 / curr:  144 / min:  129 / max:  200 / avg:  156.0
   95 / curr:  141 / min:  129 / max:  200 / avg:  155.9
   96 / curr:  171 / min:  129 / max:  200 / avg:  156.0
   97 / curr:  138 / min:  129 / max:  200 / avg:  155.8
   98 / curr:  137 / min:  129 / max:  200 / avg:  155.6

 (000.000011)  vcan0  714   [8]  2B 01 01 01 01 01 01 01
 (000.000193)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
 (000.000037)  vcan0  714   [8]  2C 01 01 01 01 01 01 01

So maybe there is something wrong on the rpi?

Sven

Oliver Hartkopp

author maintainer

2021-08-30 12:44 UTC #9 lore raw

Hi Sven,

Quoted 29 lines · Sven Schuchmann

Quoted 13 lines
but if I compare the candumps I can see:
with the patch:
  (000.000008)  vcan0  714   [8]  2F 01 01 01 01 01 01 01
  (000.000209)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000061)  vcan0  714   [8]  20 01 01 01 01 01 01 01
and without:
  (000.000004)  vcan0  714   [8]  2F 01 01 01 01 01 01 01
  (000.000069)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000017)  vcan0  714   [8]  20 01 01 01 01 01 01 01
Quoted 6 lines
sorry, I missed that: Over here the delay seems to be in the FC and not in the CF after the FC. This is what is different compared to the real hardware.
So to me it seems that the rcu implementation has changed on the way from 5.10 to 5.14?
Just checked with a 5.14.0-rc6 which contains the patch, same result:
    93 / curr:  143 / min:  129 / max:  200 / avg:  156.2
    94 / curr:  144 / min:  129 / max:  200 / avg:  156.0
    95 / curr:  141 / min:  129 / max:  200 / avg:  155.9
    96 / curr:  171 / min:  129 / max:  200 / avg:  156.0
    97 / curr:  138 / min:  129 / max:  200 / avg:  155.8
    98 / curr:  137 / min:  129 / max:  200 / avg:  155.6

Quoted 5 lines

  (000.000011)  vcan0  714   [8]  2B 01 01 01 01 01 01 01
  (000.000193)  vcan0  77E   [8]  30 0F 00 AA AA AA AA AA
  (000.000037)  vcan0  714   [8]  2C 01 01 01 01 01 01 01

So maybe there is something wrong on the rpi?

I see a similar difference on my i7-8650U system:

"5" without and "65" with the patch.

The problem remains to be the added time that is now introduced at socket close time with the rcu_synchronize().

In your script you are waiting for isotprecv process to finally end with:

wait $rxpid

And that's the expectable effect ...

It looks like the script works fine without the 'wait' code (which does not wait for the process removal then).

@mkl: I assume we have to live with that increased time at socket close for security reasons, right?

Best regards,
Oliver

ps. Btw IMO a C program is still the better approach here. isotp[send|recv] open/close the sockets for each PDU in the given setup :-/