3.7.3 has a delay in the serial communication
Closed this issue · 12 comments
Versions
- Python: 3.11.8
- OS:Pop!_OS 22.04 LTS
- Pymodbus: 3.7.3
- Modbus Hardware (if used): custom PCB
Pymodbus Specific
- Client: rtu - sync
Description
We use ModbusSerialClient(port=port, framer=FramerType.RTU, baudrate=115200, timeout=1)
When upgrading the package to the newest release 3.7.3, we noticed an rather large delay between messages. These delays were about 2 seconds between sending a message and then receiving a message. We then downgraded the pymodbus back to version 3.7.2, and the communication delays were not there anymore.
same here on macOS
my timeout setting is 0.1s, still got the long delay
You do not tell if you use sync or async version, but I assume sync.
Please add a debug log as pr issue template, so we can see where the time is spent.
For performance you should use the async client, but the sync should not have a delay of 2 seconds.
The typical problem for a long delay is if the usb driver do not deliver the whole frame and pymodbus have to make several recv calls.
Just tested on my Mac mini, with the standard examples:
% time ./client_calls.py --comm serial --port /dev/ttys010
./client_calls.py --comm serial --port /dev/ttys010 0,10s user 0,03s system 30% cpu 0,407 total
0,4 second for 38 requests...so it seems the delay is due to how you use pymodbus (or how the usb driver delivers data).
Once you post a debug log, it is easy to see why you have delay.
My test code
import pymodbus.client as ModbusClient
import time
client = ModbusClient.ModbusSerialClient(
"/dev/cu.usbserial-110",
timeout=0.1,
retries=3,
baudrate=19200,
bytesize=8,
parity="N",
stopbits=1,
)
t0 = time.time()
client.connect()
while True:
r = client.read_holding_registers(0x4, 1, slave=0x1)
print(r.registers)
print(time.time() - t0)With 3.7.2
[65534]
0.5415279865264893
[65534]
0.5757172107696533
[65534]
0.6073360443115234
[65534]
0.6386821269989014
[65534]
0.6724522113800049
[65534]
0.7062540054321289
[65534]
0.7371621131896973
[65534]
0.7709403038024902
[65534]
0.8046951293945312
[65534]
0.8361661434173584
[65534]
0.8725309371948242
...
With 3.7.3:
[65534]
2.0475847721099854
[65534]
4.094855785369873
[65534]
6.142652750015259
[65534]
8.194524765014648
[65534]
10.24574899673462
[65534]
12.294071674346924
As I wrote, that does not help anything....please run with debug log enabled, as the issue template showed how to do.
Without a debug log, we cannot help you!
Ah, sorry, I missed the chance to read the template..
Here is the log, <PAUSE HERE> is where the output paused
import pymodbus
import pymodbus.client as ModbusClient
import time
pymodbus.pymodbus_apply_logging_config("DEBUG")
client = ModbusClient.ModbusSerialClient(
"/dev/cu.usbserial-110",
timeout=0.1,
retries=3,
baudrate=19200,
bytesize=8,
parity="N",
stopbits=1,
)
t0 = time.time()
client.connect()
while True:
r = client.read_holding_registers(0x4, 1, slave=0x1)
print(r.registers)
print(time.time() - t0)With 3.7.3:
2024-10-21 23:07:12,125 DEBUG transaction:182 Current transaction state - IDLE
2024-10-21 23:07:12,125 DEBUG transaction:188 Running transaction 1
2024-10-21 23:07:12,125 DEBUG transaction:296 SEND: 0x1 0x3 0x0 0x4 0x0 0x1 0xc5 0xcb
2024-10-21 23:07:12,125 DEBUG base:247 New Transaction state "SENDING"
2024-10-21 23:07:12,126 DEBUG transaction:320 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-10-21 23:07:12,155 DEBUG transaction:412 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-10-21 23:07:12,155 DEBUG transaction:327 RECV: 0x1 0x3 0x2 0xff 0xfe 0x78 0x34
2024-10-21 23:07:12,155 DEBUG base:101 Processing: 0x1 0x3 0x2 0xff 0xfe 0x78 0x34
2024-10-21 23:07:12,155 DEBUG factory:259 Factory Response[ReadHoldingRegistersResponse': 3]
2024-10-21 23:07:12,155 DEBUG base:119 Frame advanced, resetting header!!
2024-10-21 23:07:12,155 DEBUG transaction:66 Adding transaction 0
2024-10-21 23:07:12,155 DEBUG transaction:77 Getting transaction 1
2024-10-21 23:07:12,155 DEBUG transaction:77 Getting transaction 0
<PAUSE HERE>
2024-10-21 23:07:13,661 DEBUG transaction:253 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
[65534]
2.0459089279174805
With 3.7.2:
2024-10-21 23:10:22,354 DEBUG logging:103 Current transaction state - TRANSACTION_COMPLETE
2024-10-21 23:10:22,354 DEBUG logging:103 Running transaction 39
2024-10-21 23:10:22,354 DEBUG logging:103 SEND: 0x1 0x3 0x0 0x4 0x0 0x1 0xc5 0xcb
2024-10-21 23:10:22,354 DEBUG logging:103 Resetting frame - Current Frame in buffer -
2024-10-21 23:10:22,354 DEBUG logging:103 Changing state to IDLE - Last Frame End - 1729523422.354649 Current Time stamp - 1729523422.354981
2024-10-21 23:10:22,355 DEBUG logging:103 Waiting for 3.5 char before next send - 1.823 ms
2024-10-21 23:10:22,357 DEBUG logging:103 New Transaction state "SENDING"
2024-10-21 23:10:22,357 DEBUG logging:103 Changing transaction state from "SENDING" to "WAITING FOR REPLY"
2024-10-21 23:10:22,386 DEBUG logging:103 Changing transaction state from "WAITING FOR REPLY" to "PROCESSING REPLY"
2024-10-21 23:10:22,386 DEBUG logging:103 RECV: 0x1 0x3 0x2 0xff 0xfe 0x78 0x34
2024-10-21 23:10:22,386 DEBUG logging:103 Processing: 0x1 0x3 0x2 0xff 0xfe 0x78 0x34
2024-10-21 23:10:22,386 DEBUG logging:103 Getting Frame - 0x3 0x2 0xff 0xfe
2024-10-21 23:10:22,386 DEBUG logging:103 Factory Response[ReadHoldingRegistersResponse': 3]
2024-10-21 23:10:22,386 DEBUG logging:103 Frame advanced, resetting header!!
2024-10-21 23:10:22,386 DEBUG logging:103 Adding transaction 0
2024-10-21 23:10:22,386 DEBUG logging:103 Getting transaction 0
2024-10-21 23:10:22,386 DEBUG logging:103 Changing transaction state from "PROCESSING REPLY" to "TRANSACTION_COMPLETE"
Seems you found something, which seems to be a bug, I will try to simulate it.
If possible please do the same test with dev, that would help quite a lot to know if we already solved it (by accident).
Found it (I hope)....in the refactoring a client.close() was not indented correctly, leading to a close/connect with every request.
The reason I did have a timing problem, is probably due to my serial connection, which connect extremely fast.
Sorry for the bug.
Can you please check dev, once #2401 is merged, and confirm it works (or not).
the pull request will be part of v3.7.4 that are due in 1-2 weeks.
Thanks for the confirmation....have a nice day/night in your lovely country.
@buganini Thank you for posting the debug log. I wasnt able to do it due to not having the hardware there yesterday.
@janiversen Thank you for the information. en your help.