Async Serial Communication Slow

[DaneSlattery]

Versions

• Python: Python 3.12.3
• OS: Ubuntu 24 x86_64
• Pymodbus: dev + 3.8.3
• Modbus Hardware (if used): Waveshare USB to RS485

Pymodbus Specific

• Client: rtu - sync/async

Description

I am attempting to read and write registers on a specific serial device. I started with a basic synchronous client, but found the read/writes to be too slow. I expected the asynchronous client to vastly increase performance, but it seems like the execute method is blocking until timeout (default 3s), even though the device has replied.

I saw this behaviour on version 3.8.3 and then built the latest development version to see if it has been fixed in the pre-release (it hasn't).

If I adjust the timeout, the reads are much faster, but I don't think this is intended. If the device has replied, the async code should not block.

Code and Logs

code is based on https://github.com/pymodbus-dev/pymodbus/blob/901a87d885af009b4f272999877bccb155ff064b/examples/client_performance.py, but adapted to read registers on my known devic.

#!/usr/bin/env python3
"""Test performance of client: sync vs. async.

This example show how much faster the async version is.

example run:

(pymodbus) % ./client_performance.py
--- Testing sync client v3.4.1
running 1000 call (each 10 registers), took 114.10 seconds
Averages 114.10 ms pr call and 11.41 ms pr register.
--- Testing async client v3.4.1
running 1000 call (each 10 registers), took 0.33 seconds
Averages 0.33 ms pr call and 0.03 ms pr register.
"""
import asyncio
import time

from pymodbus import FramerType, pymodbus_apply_logging_config
from pymodbus.client import AsyncModbusSerialClient, ModbusSerialClient


LOOP_COUNT = 1000
REGISTER_COUNT = 4


async def run_async_client_test():
    """Run async client."""
    print("--- Testing async client v3.4.1")
    pymodbus_apply_logging_config("DEBUG")
    client = AsyncModbusSerialClient(
        "/dev/ttyUSB0",
        framer=FramerType.RTU,
        baudrate=9600,
    )
    await client.connect()
    assert client.connected

    start_time = time.time()
    for _i in range(LOOP_COUNT):
        rr = await client.read_holding_registers(600, count=REGISTER_COUNT, slave=1)
        if rr.isError():
            print(f"Received Modbus library error({rr})")
            break
    client.close()
    run_time = time.time() - start_time
    avg_call = (run_time / LOOP_COUNT) * 1000
    avg_register = avg_call / REGISTER_COUNT
    print(
        f"running {LOOP_COUNT} call (each {REGISTER_COUNT} registers), took {
            run_time:.2f} seconds"
    )
    print(f"Averages {avg_call:.2f} ms pr call and {
          avg_register:.2f} ms pr register.")


if __name__ == "__main__":
    asyncio.run(run_async_client_test())

Note in the logs below the 3s delay between reads

-- Testing async client v3.4.1
2025-01-09 10:51:52,068 DEBUG base:56 Connecting to /dev/ttyUSB0:0.
2025-01-09 10:51:52,068 DEBUG transport:242 Connecting comm
2025-01-09 10:51:52,069 DEBUG transport:277 Connected to comm
2025-01-09 10:51:52,170 DEBUG transport:386 send: 0x1 0x3 0x2 0x58 0x0 0x4 0xc4 0x62
2025-01-09 10:51:52,185 DEBUG transport:329 recv: 0x1 0x3 0x8 0x0 0xff old_data:  addr=None
2025-01-09 10:51:52,186 DEBUG base:91 Processing: 0x1 0x3 0x8 0x0 0xff
2025-01-09 10:51:52,186 DEBUG rtu:113 Frame - not ready
2025-01-09 10:51:52,186 DEBUG transport:341 recv, unused data waiting for next packet: 0x1 0x3 0x8 0x0 0xff
2025-01-09 10:51:52,201 DEBUG transport:329 recv: 0x0 0x1 0x0 0x1 0x0 0x1 0x37 0x18 old_data: 0x1 0x3 0x8 0x0 0xff addr=None
2025-01-09 10:51:52,202 DEBUG base:91 Processing: 0x1 0x3 0x8 0x0 0xff 0x0 0x1 0x0 0x1 0x0 0x1 0x37 0x18
2025-01-09 10:51:52,202 DEBUG decoders:113 decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[], registers=[255, 1, 1, 1], status=1) 
2025-01-09 10:51:52,202 DEBUG base:101 Frame advanced, resetting header!!
2025-01-09 10:51:52,202 DEBUG transport:386 send: 0x1 0x3 0x2 0x58 0x0 0x4 0xc4 0x62
2025-01-09 10:51:55,205 DEBUG transport:386 send: 0x1 0x3 0x2 0x58 0x0 0x4 0xc4 0x62
2025-01-09 10:51:55,225 DEBUG transport:329 recv: 0x1 0x3 0x8 0x0 0xff 0x0 0x1 0x0 0x1 0x0 old_data:  addr=None
2025-01-09 10:51:55,225 DEBUG base:91 Processing: 0x1 0x3 0x8 0x0 0xff 0x0 0x1 0x0 0x1 0x0
2025-01-09 10:51:55,225 DEBUG rtu:113 Frame - not ready
2025-01-09 10:51:55,225 DEBUG transport:341 recv, unused data waiting for next packet: 0x1 0x3 0x8 0x0 0xff 0x0 0x1 0x0 0x1 0x0
2025-01-09 10:51:55,241 DEBUG transport:329 recv: 0x1 0x37 0x18 old_data: 0x1 0x3 0x8 0x0 0xff 0x0 0x1 0x0 0x1 0x0 addr=None
2025-01-09 10:51:55,241 DEBUG base:91 Processing: 0x1 0x3 0x8 0x0 0xff 0x0 0x1 0x0 0x1 0x0 0x1 0x37 0x18
2025-01-09 10:51:55,241 DEBUG decoders:113 decoded PDU function_code(3 sub -1) -> ReadHoldingRegistersResponse(dev_id=0, transaction_id=0, address=0, count=0, bits=[], registers=[255, 1, 1, 1], status=1) 

[janiversen]

The 3 second delay is because your device did not respond to the first send, so the retry mechanism resend the frame.

[janiversen]

Async do return as soon as a valid response is received, but for some reason your device did not respond to the first request, and when resending it responded 2 times, The problem might be in your rs485 converter.