Modbus RTU Slow compared to Version 2.5.3

[jannikgoebel]

Versions

Duplicate of #1650

• Python: 3.11.4
• OS: Windows
• Pymodbus: Server: 3.5.0dev Client: 3.5.0dev / 2.5.3
• Modbus Hardware (if used): FTDI based USB<->RS485 Converter. One is Client and one is Server.

Pymodbus Specific

• Server: rtu- async
• Client: rtu- sync

Description

In the past I have run several test systems with version 2.5.3 as client. Now I would like to switch to the new version 3.x. Unfortunately I noticed a performance decrease.

With version 2.5.3 the command to read 10 input registers can be executed on average every 65ms.

With the versions 3.x in the example the newest Dev version, I come only on a reading time of at least 120ms. Also with other version like version 3.1.3 the problem appears.

I have attached screenshots from the oscilloscope to illustrate this. You can clearly see that the response from the server is about the same speed as the response with V2.5.3. But the internal processing time is much higher.

Code and Logs

Server

Basic async Server described in #1697 running on V3.5.0dev

Client V2.5.3

import time
from pymodbus.client.sync import ModbusSerialClient
client = ModbusSerialClient(method='rtu', port="COM50", baudrate=19200)
client.connect()
import logging
# _logger = logging.getLogger("main")
logging.basicConfig(
    format='%(asctime)s.%(msecs)03d %(levelname)-8s %(message)s',
    level=logging.DEBUG,
    datefmt='%Y-%m-%d %H:%M:%S'
)
_logger = logging.getLogger()
fh = logging.FileHandler("V253.log")
fh.setLevel(logging.DEBUG)
_logger.addHandler(fh)
_logger.setLevel("DEBUG")

sum = 0
for i in range(0,100):
    start = time.time()
    _logger.debug(f"Start {time.time()}")
    x = client.read_input_registers(0,10,unit=2)
    _logger.debug(f"Finish {time.time()}")
    sum += time.time() - start
    print(f"{i} {time.time() - start} {x.registers}")

print(f"Average time per request {sum/100}")

V253.log

Client V3.5.0dev

from pymodbus.client import ModbusSerialClient
from pymodbus.transaction import ModbusRtuFramer
from pymodbus import pymodbus_apply_logging_config
import time
pymodbus_apply_logging_config()

import logging
# _logger = logging.getLogger("main")
logging.basicConfig(
    format='%(asctime)s.%(msecs)03d %(levelname)-8s %(message)s',
    level=logging.DEBUG,
    datefmt='%Y-%m-%d %H:%M:%S'
)
_logger = logging.getLogger()
fh = logging.FileHandler("dev.log")
fh.setLevel(logging.DEBUG)
_logger.addHandler(fh)
_logger.setLevel("DEBUG")

client = ModbusSerialClient(port="COM50", framer=ModbusRtuFramer, baudrate=19200, timeout=0)

client.connect()
sum = 0
for i in range(0,100):
    start = time.time()
    _logger.debug(f"Start {time.time()}")
    x = client.read_input_registers(0,10,slave=2)
    _logger.debug(f"Finish {time.time()}")
    sum += time.time() - start
    print(f"{i} {time.time() - start} {x.registers}")
print(f"Average time per request {sum/100}")

dev.log

[janiversen]

Pull requests are welcome. We are currently in the process of reworking the async client/server. From my own experience the new transport layer is a factor faster than what you had in v2.5.3, but the current connection to the upper layer is a bit of patch work, and might not be perfect. We have tried to make a few changes to the sync client as possible (compared to 3.0.0).

Since you have it all setup then why not do some performance timing and find the bugger that eats the time. I do not have a windows system, so I am only doing CI testing on windows.

The modbus integration in homeasisstant is currently using v3.3.1, and there I have no performance problems (running on RPI 4). When I want to stress HA I read a couple of registers every 25ms.

[janiversen]

If you can pinpoint the problem, I can sure help fix it....but without a pointer I can only hope to cure the problem by pure chance.

[janiversen]

remark:

   client.read_input_registers(0,10,unit=2)

is no longer permitted, and thinking of the default you address device 1. Address is also very odd, normally not permitted.

but since you have not added the pymodbus log call, I cannot tell you if the library detects any problems.

[janiversen]

While I was waiting for v3.4.1 to complete, I made an example that compared performance, please see:

https://github.com/pymodbus-dev/pymodbus/blob/dev/examples/client_performance.py

The result is interesting, but not unexpected (especially not on windows, where polling like sync does is very expensive):

(pymodbus) jan@MacMini examples % ./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.

So if you want performance, switch to async. As you can see from the 2 examples, the code is nearly identical (all based on v3.4.1).

We are currently planning to replace the lower layers of the sync clients with the transport interface, this is due in v3.5.0. Then intention is to replace all but the external class (ModbusClient) with async, for reasons of speed and maintenance.

We did it a while ago in the server, and have had very few problems.

Having said that, if you can pinpoint function that causes the slowness we are ready to look at it.

[jannikgoebel]

I will try using the async and compare the results.

For my understanding this call is correct for the V2.5.3 script. rr = client.read_holding_registers(1, 1, unit=UNIT)

I added the log as an external file. For V2.5.3 is was a bit hard to get the right format, because there was no premade function for it.

I try to pinpoint the code, which takes up the time, but my python skill is unforunately not so good yet. Asyncronous processes are unfortunately also not so easy to debug. To me it looks like the code part that reads the serial port is experiencing a delay in recognizing that the message is complete. If you can give me tips on how to debug the timing better, I'll try to do those tests.

[janiversen]

The call might be correct for v2.5.3 but not for 3.x (seems I looked at your 2.5.3 example sorry about that).

There is a pre-made function in 3.x just for that purpose:

logging.basicConfig(
    format='%(asctime)s.%(msecs)03d %(levelname)-8s %(message)s',
    level=logging.DEBUG,
    datefmt='%Y-%m-%d %H:%M:%S'
)
_logger = logging.getLogger()
fh = logging.FileHandler("dev.log")
fh.setLevel(logging.DEBUG)
_logger.addHandler(fh)
_logger.setLevel("DEBUG")

might work for you, which you were asked to use, when you filed the issue (or look at our examples).

[janiversen]

Python have a performance timer, that can show how much time is used in each function, that is what you need to use.

[jannikgoebel]

Today I tried the Async client and with that I get a read time of ~70ms. So about the performance, which I also had with the version 2.5.3.

So the problem is also solved for me. If I still find time again, I'll try to get to the bottom of the cause.

[janiversen]

In a couple of months, the sync code will be all gone (apart from the class you instantiate) so that all internal code is async.