Timestamp of messages reported by BufferedReader are inaccurate

[mdabrowski1990]

Describe the bug

When a frame is received by a BufferedReader (probably all Listeners are affected), it often indicates a timestamp that has not been reached yet (time in a future).

To Reproduce

Connect two interfaces to a CAN bus. Then configure two CAN Bus objects and a BufferedReader. Then check timestamp of a transmitted/received messages.

• code snippet for transmitted frames

  
  from time import time
  from threading import Timer
  from can import Notifier, BufferedReader, Bus, Message

if name == "main": kvaser_bus_1 = Bus(interface="kvaser", channel=0, fd=True, receive_own_messages=True) kvaser_bus_2 = Bus(interface="kvaser", channel=1, fd=True, receive_own_messages=True) # connected with bus 1

buffered_reader = BufferedReader()
notifier = Notifier(bus=kvaser_bus_1, listeners=[buffered_reader])

message = Message(data=[0x12, 0x34, 0x56, 0x78, 0x9A, 0xBC, 0xDE, 0xF0], arbitration_id=0x100)

for _ in range(10):
    Timer(interval=0.1, function=kvaser_bus_1.send, args=(message, )).start()

    sent_message = buffered_reader.get_message(timeout=1)
    timestamp_after_send = time()

    print([sent_message.timestamp, timestamp_after_send, sent_message.timestamp <= timestamp_after_send])

kvaser_bus_1.shutdown()
kvaser_bus_2.shutdown()

- code snippet for received frames

from time import time from threading import Timer from can import Notifier, BufferedReader, Bus, Message

if name == "main": kvaser_bus_1 = Bus(interface="kvaser", channel=0, fd=True, receive_own_messages=True) kvaser_bus_2 = Bus(interface="kvaser", channel=1, fd=True, receive_own_messages=True) # connected with bus 1

buffered_reader = BufferedReader()
notifier = Notifier(bus=kvaser_bus_2, listeners=[buffered_reader])

message = Message(data=[0x12, 0x34, 0x56, 0x78, 0x9A, 0xBC, 0xDE, 0xF0], arbitration_id=0x100)

for _ in range(10):
    Timer(interval=0.1, function=kvaser_bus_1.send, args=(message, )).start()

    sent_message = buffered_reader.get_message(timeout=1)
    timestamp_after_send = time()

    print([sent_message.timestamp, timestamp_after_send, sent_message.timestamp <= timestamp_after_send])

kvaser_bus_1.shutdown()
kvaser_bus_2.shutdown()

Example output:

[1697032555.4744086, 1697032555.4744072, False] [1697032555.5841286, 1697032555.5841358, True] [1697032555.6927686, 1697032555.6920245, False] [1697032555.8017185, 1697032555.801458, False] [1697032555.9249885, 1697032555.925142, True] [1697032556.0496085, 1697032556.049515, False] [1697032556.1589985, 1697032556.158617, False] [1697032556.2835186, 1697032556.283603, True] [1697032556.3929286, 1697032556.3929098, False] [1697032556.5013385, 1697032556.5011282, False]

### Expected behavior
I would expect that timestamps of messages reported by `BufferedReader` would never indicate future timestamp (I am getting value of timestamp that has not been reached yet).

### Additional context

OS and version: Windows 11
Python version: 3.8
python-can version: 4.1.0
python-can interface/s (if applicable): Kvaser Hybrid Pro CAN/LIN

[zariiii9003]

The BufferedReader does not alter timestamps. The time offset is measured during KvaserBus instantiation, afterwards the message timestamps are received directly from the Kvaser driver.

Does the timestamp discrepancy happen immediately or after some time?

[mdabrowski1990]

I would say immediately (often in the first received message).

[zariiii9003]

Also i'm not sure whether your expectation is correct. The send function returns, when the Kvaser function call returns. That does not mean, that the message was already sent. The message was queued into some transmit buffer and may be send later.

[mdabrowski1990]

The same is observed for received messages - they couldn't be received before timestamp is achieved. So for sure this is an issue. Moreover, for transmitted frames this also shall not be the case as there is an arbitration on CAN, therefore some other CAN node might stop a transmission with an error frame for example, so you cannot be sure of an exact timestamp unless you fully transmit a message.

This ticket can be close though if BufferedReader doesnt alter timestamps as you mentioned. Thank you for clarifying this one and I will report it to Kvaser as it seems like they have some timing problem.

[mdabrowski1990]

I have reported issue to Kvaser (potentially it is a defect in their SDK). They assigned number INBOX-21158 to this problem. If you are interested in the outcome, I would keep you updated.

[mdabrowski1990]

Response from Kvaser:

There are a couple of misconceptions in your program.

• That Timer and the timestamps returned with a CAN frame are related.
• That the time checked on completion of a canWrite call is the time when the CAN frame has been placed on the CAN bus.

The timestamps generated by the Kvaser Hybrid Pro CAN/LIN are based on a counter clock within the unit. This counter is incremented based on a timer function and can drift based on the quality of the oscillator. We do use high quality oscillators to ensure proper bit timing. But no two clocks are exactly the same. This counter is used to increment a time domain associated with a handle to the channel. Each handle by default gets a unique time domain that is reset to zero when the handle goes bus on. The resulting time is the returned time stamp on a frame. Again, has nothing to do with a computer’s system clock or any timer within the PC. So, any clock in the PC can drift independent of the drift in the clock used for the timestamps.

With that said, if you used our direct API you do have the ability to place handles to channels on the same device or handles to channels on multiple Kvaser USB devices that support MagiSync in the same time domain. MagiSync guarantees that a tick on one Kvaser unit’s clock is synchronized with the tick on another Kvaser unit’s clock. Then by placing the handles in the same time domain, the time stamps represent the same moment in time (still not linked to any computer provided clock).

As for checking the time after a canWrite call completes, this does not take into consideration that the canWrite call just places the frame in a transmit buffer of our API. How long the frame sits in the transmit buffer will be dependent on the number of frames being written and received and other calls being placed to the unit. All such commands must be passed over the USB communication before the frame is actually transmitted. The Kvaser Hybrid does have the ability to receive an echo of frames transmitted on a handle in the handle’s receive buffer. The time stamp on this frame would be a better representation of when the frame was actually placed on the CAN bus.

However, you can still get inversion (on a much lower level). If I have two channels that support MagiSync connected to the same CAN bus and their handles are placed in the same time domain, the transmit echo for a sent frame channel 1 may still have a timestamp greater than the same frame received on channel 2. This usually only happens on a CAN bus that has extreme bursts of traffic or is heavily loaded. The reason for this inversion is receive interrupts are given a higher priority than transmit interrupts in our devices. The transmit echo placed in the receive buffer is timestamped when the frame has been successfully placed on the CAN bus causing an interrupt to notify us that we can place the next frame. But if a receive interrupt occurs at the same time, the receive interrupt gets priority and is handled first slowing down the application of a timestamp on the echo.