Poor PCAN Peak performance

[belliriccardo]

Describe the bug

To put it simply, I have a script that implements a simple protocol to flash a device via canbus. I'm using the python-can library, and have access to a PCAN peak and a VN1630 from Vector. Very easy to use, just change the interface and channel (at a speed of 500k, can non-fd, every other setting is the default) and the script works flawlessly with both hardware devices.
The problem I'm having is actually with performance: with no modifications to the script (except obviously to the channel and interface), with the PCAN Peak the bus usage sits at around 30%, and with the VN1630 at around 74%. Obviously the latter finishes much quicker. I tried profiling using cProfile and Snakeviz to visualize the results, and here they are:

Using the PCAN Peak:

Using the Vector VN1630:

As you can see, the vast majority of the time in both cases is spent inside the _winapi.WaitForSingleObject call; and in fact, being called approx. 82k times in both cases, with the Peak the "percall" time is much higher than with the VN1630.

Am I missing something? Is this due to some driver implementation detail? Can this be fixed/improved/circumvented without touching the device's drivers?

To Reproduce

I'll link both .prof files in case anyone else want to take a look at it:
programperf.zip

Expected behavior

The performance of both devices should match, or at least not be so great.

Additional context

OS and version: Windows 10
Python version: 3.11.3
python-can version: 4.2.2

[zariiii9003]

I don't see much difference in the logic. Maybe the messages remain in the transmit buffer a little longer, or the PCAN driver takes longer to signal the windows event handle.
You could try to connect your Peak interface and just listen to the communication between VN1630 and ECU and check the wait times in snakeviz.

Unrelated: Could you try, whether you get better results with https://github.com/zariiii9003/python-can-cvector ? This won't help you, i'm just curious 😄

[belliriccardo]

Hi @zariiii9003, I have tested your library and it seems to work just fine; however the speeds achieved are the same as with the regular 'vector' interface, with bus usage at around 74% usage at 500k bitrate. My usecase might be not relevant though, as it is kinda spammy already.
As for the other matter, I also think that the problem has something to do with the driver's internal implementation, and is "outside" of python itself.

[zariiii9003]

Thanks for trying! I guess the performance is not limited by python then.

[asilk27]

I'm running into this issue as well. I'm listening to a device that is constantly broadcasting CAN messages, but the PCAN interface is so slow that it actually misses some messages. I did not have this issue when I was using the raw PCAN API. I'll use that for now until this is resolved.

Will try to resolve it if I have time.

[asilk27]

Resolved the issue. For me I was doing this:

def readMessage():
    #If no CAN message is read within 1 second, return None
  with can.Bus() as bus:
        msg = bus.recv(timeout=1)
        if msg:
            
           return msg
        
        return None

When really I should've been doing this:

bus = can.Bus(channel='PCAN_USBBUS1', interface='pcan')
def readMessage():
    #If no CAN message is read within 1 second, return None
  
     msg = bus.recv(timeout=1)
     if msg:
            
        return msg
        
     return None

Before I was instantiating a new bus each time I wanted to read a message. Now I'm using the same bus to read messages.

Rookie mistake, but I'd rather own up to it than shamefully delete my message 😅. Hope this helps anyone else.

[j-c-cook]

Thanks for trying! I guess the performance is not limited by python then.

@zariiii9003 I've only witnessed performance issues associated with python-can on an embedded chip set. However, it's well known that Python is not geared for embedded chips.

@belliriccardo I'm wondering if the PCAN hardware is limited in some way. I setup socketcan send messages with a sequential signal going from 0 to 100000 and found the average interval to be 0.00418 seconds and the max to be 0.255 seconds. This means that sending messages from a bash script using socketcan without a time delay will average 238 messages per second.

#!/bin/bash

# Note: 250 kb/s

interface=can0
can_id=123

for ((i=0;i<=100000;i++)); do
    data=$(printf "%016x\n" "$i")

    cansend $interface "${can_id}#${data}"
done

[belliriccardo]

Hi @j-c-cook, I ran a similar test in pure python to see if the performance is limited in some way by python itself and these are the results I got; using this simple script:

import can
from time import perf_counter, sleep

message = can.Message(arbitration_id=123, is_extended_id=False, data=[0] * 8)
times = []

with can.Bus('PCAN_USBBUS2', 'pcan', bitrate=250000) as can_bus:
    for _ in range(100000):
        try:
            t_start = perf_counter()
            can_bus.send(message)
            times.append(perf_counter() - t_start)
        except can.CanOperationError:
            # Transmit queue is full
            sleep(0.01)  # or lower
            pass  # or continue

print(f'Mean send time (s): {(sum(times)/len(times)):.6f}')
print(f'Max send time  (s): {(max(times)):.6f}')
print(f'Min send time  (s): {(min(times)):.6f}')
print(f'Ten fastest times:  {sorted(times)[:10]}')
print(f'Ten slowest times:  {sorted(times)[-10:]}')

I get these results:

Mean send time (s): 0.000020
Max send time  (s): 0.006112
Min send time  (s): 0.000009
Ten fastest times:  [8.899995009414852e-06, 8.899995009414852e-06, 8.899995009414852e-06, 8.899995009414852e-06, 8.899995009414852e-06, 8.90000956133008e-06, 8.90000956133008e-06, 8.90000956133008e-06, 8.90000956133008e-06, 8.90000956133008e-06]
Ten slowest times:  [0.0007200999971246347, 0.000752199994167313, 0.000752499996451661, 0.000771800012444146, 0.0008121999999275431, 0.0008333000005222857, 0.000992799992673099, 0.0010022000060416758, 0.0016423999913968146, 0.0061120000027585775]

I tried to closely match your configuration, so 100000 messages with non-ext id @ 250k baud; also while monitoring the network with another pcan peak (and busmaster) the bus usage gets up to 99.99% usage, while the cpu usage of the python process barely gets above 0.3-0.5%. I also tried again with 500k baud and these are the results:

Mean send time (s): 0.000013
Max send time  (s): 0.000787
Min send time  (s): 0.000009
Ten fastest times:  [8.799994247965515e-06, 8.799994247965515e-06, 8.799994247965515e-06, 8.799994247965515e-06, 8.799994247965515e-06, 8.799994247965515e-06, 8.799994247965515e-06, 8.799994247965515e-06, 8.800008799880743e-06, 8.800008799880743e-06]
Ten slowest times:  [0.0003724999987753108, 0.00039339999784715474, 0.00040869999793358147, 0.00042579999717418104, 0.00045779999345541, 0.000458099995739758, 0.0004884999943897128, 0.0005256000004010275, 0.0005451000033644959, 0.0007870999979786575]

Also with this configuration the bus usage gets around 98-99% (although reducing sleep time gets it up to 99.99% again), with little cpu usage. This however still doesn't have anything to do with the original issue; that was the receiving time of can messages; it seemed like there was a delay in the notification time of new can messages from the driver to windows. Unfortunately I haven't had time to investigate this further; I'll also link the post I opened in the PEAK official forums, if anyone is interested: https://forum.peak-system.com/viewtopic.php?f=41&t=7462&sid=d09810bcd566779cac35a9aae8106aca&start=10