Send new request takes too long after receiving response from server

[KC6320]

Relative timestamps Differential timestamps. for easier understanding

733 -> request ID 7B3 -> response ID

request frame takes on average more than 100 ms after receiving a server response. Is this the reason for p2 timeout of 50ms

I am using latest version of udsoncan over isotp over peak can. All on python windows. @pylessard

[KC6320]

I am using only one server at the moment with peak-can usb. I am using queue to pass all messages from can layer to isotp. I have defined own rxfn in isotp to read from queue. I still have timeout issues

[KC6320]

I have set the config client.config["use_server_timing"] = False for the above can log. If I set it to True timeout will occur

[pylessard]

Hi, Look at the existing issues. You are Chinese aren't you? Many Chinese users all have the same timeout value of 50ms coming from the server. I got this problem report several times now.

This one changed the sleep time : https://github.com/pylessard/python-udsoncan/issues/80 There's another one where somebody implemnted a spinwait between send and response to avoid sleeping. Can't find it quickly.

[KC6320]

No I am not Chinese ! 😄 So I did use the set sleep time as other users. I receive a positive response only till security access but then I got a timeout when I try to write DID of 17 bytes. The timeout occur before second CF was sent out.

DEBUG:isotp:Sending : <733> (8) b'2136343945323546' <--- CF 1 DEBUG:can.pcan:Data: bytearray(b'!649E25F') DEBUG:can.pcan:Type: <class 'bytearray'> DEBUG:isotp:Receiving : <103> (8) b'b20c000000000515' (Ignored since app messages) DEBUG:isotp:Receiving : <113> (8) b'3606020c01705001' (Ignored since app messages) DEBUG:Connection:No data received: [TimeoutException] - Did not receive frame IsoTP Transport layer in time (timeout=0.05 sec) ERROR:UdsClient:[TimeoutException] : Did not receive response in time. P2 timeout time has expired (timeout=0.050 sec) INFO:Connection:Connection closed

__isotp_params = { 'stmin': 0, 'blocksize': 0, 'wftmax': 0, 'tx_data_length': 8, 'tx_data_min_length': None, 'tx_padding': 0, # our firmware request padding to be 0x00 'rx_flowcontrol_timeout': 1000, 'rx_consecutive_frame_timeout': 1000, 'squash_stmin_requirement': False, 'max_frame_size': 4095 }

[pylessard]

Ok, do you mind sharing what is the ECU? I still wonder why so many people have this 50ms timeout.

Unfortunately, windows doesn't offer a great thread resolution (16ms) and the library calls a sleep when there's no data available. 50ms are consumed very quickly. If you find a way to improve this, I would be interested. The threaded connection can possibly be improved to save a call to sleep().

[KC6320]

It is a motor controller.

"the library calls a sleep when there's no data available. 50ms are consumed very quickly" For this I set the sleep timing via def set_sleep_timing(self, idle, wait_fc): to as much low as 1ms. So the call to sleep doesn't make much difference in the rx threaded task , right ? Correct me if I am wrong.

I couldn't find any sleep() in the library besides the below function in connections.py in udsoncan time.sleep(self.isotp_layer.sleep_time())

[pylessard]

Yeah. If you ask 1ms, windows will sleep at least 16ms. You can achieve better timing with the Linux kernel though.

It's the right sleep. You write, wait 16ms before it's written to python-can. I don't know if python-can introduce a delay or not. Then python-can writes to the driver. The os calls the driver, possibly fast, but at least 1 millesec delay here. Then transmission. Response is sent and the same happens the other way. The drivers receive the data, 16ms for the app to pickut up with python-can. Another 16ms because of the threaded architecture of the connection. The. You have the data back.

[martinjthompson]

This might get fixed in Python 3.11, which looks like it will use the "new" (Windows 10) high resolution waitable timer... https://github.com/python/cpython/commit/55868f1a335cd3853938082a5b25cfba66563135

On Wed, 1 Jun 2022 at 23:49, Pier-Yves Lessard @.***> wrote:

Yeah. If you ask 1ms, windows will sleep at least 16ms. You can achieve better timing with the Linux kernel though.

It's the right sleep. You write, wait 16ms before it's written to puthon-can. I don't know if python-can inteoduce a delay or not. Then python-can writes to the driver. The os calla the driver, possibly fast, but at least 1 millesec delay here. Then transmission. Response and the same happens the other way. The drivers receive the data, 16ms for the app to pickut up with python-can. Another 16ms because of the Threaded architecture of the connection. The. You have the data back.

— Reply to this email directly, view it on GitHub https://github.com/pylessard/python-udsoncan/issues/121#issuecomment-1144218836, or unsubscribe https://github.com/notifications/unsubscribe-auth/AADIII6SPTOCLPDO7MVPG2DVM7SHFANCNFSM5XSOKDOQ . You are receiving this because you are subscribed to this thread.Message ID: @.***>

-- @.*** https://parallelpoints.com/ http://parallelpoints.com/

[ziyangfu]

we have the same problem, I am Chinese @pylessard we can receive the can frame correctly from ECU about change_session(2) however, we can not receive the can frame about change_session(1), at the same time, we also can not capture the response frame via candump my platform： linux kernel 5.4, insmod can-isotp.ko udsoncan -> python-isotp(socketcan) -> can-isotp(kernel space)

config['use_server_timing'] = False   #  if True , P2 time out (0.05 ms)
client.change_session(2)
client.change_session(1)

error log:

[TimeoutException] : Did not receive response in time. P2 timeout time has expired (timeout=1.000 sec)
Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 1946, in send_request
    payload = self.conn.wait_frame(timeout=timeout_value, exception=True)	
  File "/usr/lib/python3.7/site-packages/udsoncan/connections.py", line 77, in wait_frame
    frame = self.specific_wait_frame(timeout=timeout)
  File "/usr/lib/python3.7/site-packages/udsoncan/connections.py", line 327, in specific_wait_frame
    raise TimeoutException("Did not received ISOTP frame in time (timeout=%s sec)" % timeout)
udsoncan.exceptions.TimeoutException: Did not received ISOTP frame in time (timeout=1 sec)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "./main.py", line 41, in <module>
    client.change_session(1)
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 128, in decorated
    return func(self, *args, **kwargs)
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 186, in change_session
    response = self.send_request(req)
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 1954, in send_request
    raise TimeoutException('Did not receive response in time. %s time has expired (timeout=%.3f sec)' % (timeout_name_to_report, timeout_value))
udsoncan.exceptions.TimeoutException: Did not receive response in time. P2 timeout time has expired (timeout=1.000 sec)

[ziyangfu]

config['use_server_timing'] = True  
client.change_session(2)
time.sleep(0.02)   
client.read_data_by_identifier([0xF191])  #  after sleep 20 ms,  receicved the response correctly

we have the same problem, I am Chinese @pylessard we can receive the can frame correctly from ECU about change_session(2) however, we can not receive the can frame about change_session(1), at the same time, we also can not capture the response frame via candump my platform： linux kernel 5.4, insmod can-isotp.ko udsoncan -> python-isotp(socketcan) -> can-isotp(kernel space)

config['use_server_timing'] = False   #  if True , P2 time out (0.05 ms)
client.change_session(2)
client.change_session(1)

error log:

[TimeoutException] : Did not receive response in time. P2 timeout time has expired (timeout=1.000 sec)
Traceback (most recent call last):
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 1946, in send_request
    payload = self.conn.wait_frame(timeout=timeout_value, exception=True)	
  File "/usr/lib/python3.7/site-packages/udsoncan/connections.py", line 77, in wait_frame
    frame = self.specific_wait_frame(timeout=timeout)
  File "/usr/lib/python3.7/site-packages/udsoncan/connections.py", line 327, in specific_wait_frame
    raise TimeoutException("Did not received ISOTP frame in time (timeout=%s sec)" % timeout)
udsoncan.exceptions.TimeoutException: Did not received ISOTP frame in time (timeout=1 sec)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "./main.py", line 41, in <module>
    client.change_session(1)
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 128, in decorated
    return func(self, *args, **kwargs)
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 186, in change_session
    response = self.send_request(req)
  File "/usr/lib/python3.7/site-packages/udsoncan/client.py", line 1954, in send_request
    raise TimeoutException('Did not receive response in time. %s time has expired (timeout=%.3f sec)' % (timeout_name_to_report, timeout_value))
udsoncan.exceptions.TimeoutException: Did not receive response in time. P2 timeout time has expired (timeout=1.000 sec)

[pylessard]

Yes I know, there is something to be improved in the timing. But still, 50ms for a software in the user space is a bit tight. Do you mind telling which controller has this 50ms timeout that keeps coming back?

[ziyangfu]

Hi pylessard udsoncan running in NXP iMX8 platform, and the ECU chip is TC389

when I change session to programming mode, the ECU can not response right away(I guess), therefore, I add a sleep to avoid this situation.

[pylessard]

Just to let you know that timing is being investigated right now. Most likely will be possible to achieve better timing from the pure python implementation of the isotp protocol

[pylessard]

Hi @ziyangfu. Is it possible to try the latest isotp v2.x + udsoncan with branch support-isotp-v2 ?

Use the isotp.NotifierBasedCanStack, like this

bus = VectorBus(channel=0, bitrate=500000)                                          # Link Layer (CAN protocol)
notifier = can.Notifier(bus, [can.Printer()])                                       # Add a debug listener that print all messages
tp_addr = isotp.Address(isotp.AddressingMode.Normal_11bits, txid=0x123, rxid=0x456) # Network layer addressing scheme
stack = isotp.NotifierBasedCanStack(bus=bus, notifier=notifier, address=tp_addr, params=isotp_params)  # Network/Transport layer (IsoTP protocol). Register a new listenenr
conn = PythonIsoTpConnection(stack)                                                 # interface between Application and Transport layer
with Client(conn, config=uds_config) as client:                                     # Application layer (UDS protocol)
   client.change_session(1)

You should get better timing.

I will close this issue if I don't get a response in the upcoming weeks. Cheers

[pylessard]

• isotp v2.x is release
• udsoncan v1.21 is released

These 2 should have better performances. I suggest to use a NotifierBasedCanStack.

Will close as I believe it is fixed. reopen if you think it deserves more work.