pymodbus
pymodbus copied to clipboard
Published
20 hours ago •
pymodbus-dev
pymodbus-dev
Slow read operation when sync serial client and servers are running at the same time
Versions
- Python:python3.7
- OS: Linux raspberrypi 5.10.63-v7l+
- Pymodbus: 2.5.3
- Modbus Hardware (if used): none
Pymodbus Specific
- Server: tcp/rtu/ascii - sync/async: rtu-sync-serial
- Client: tcp/rtu/ascii - sync/async: rtu-sync-serial
Description
I have two serial ports each configured as server and client. I am doing a speed test of reading a single and bulk reading of the holding register. Each server/client is configured with 300ms timeout and 9600 bps. The bulk read performs a single read command with reading 120 registers. The client measures the duration of the read operation using perf_counter() to measure the elapsed time of the read operation. 100ms for reading a single register and 300ms for reading 120 registers seems too slow.
When the client performs the same task with an external device, the performance becomes much better. Reading a single register takes about 20ms. This gives me an idea of where the issue is coming from the sync-server code.
Code and Logs
reading operation
read_start = perf_counter()
data = modbus.read_regs(slave, address, num_of_regs)
read_end = perf_counter()
Modbus context definition
store = ModbusSlaveContext(
di=ModbusSparseDataBlock({0x32:dummy_data}),
co=ModbusSparseDataBlock({0x32:dummy_data}),
hr=ModbusSparseDataBlock({0x32:dummy_data}),
ir=ModbusSparseDataBlock({0x32:dummy_data})
)
# code and logs here.
Same problem here, using the serial client & serial server examples with RTU @ 9600bps . In fact my guess is that the issue is in sync version of the slave (server), not a hardware / rasp problem
If i run the aasynchronous version of the slave(requires the twisted package), both sync and async master (client) examples run ok, without any issues, passing all the assert tests.
BUT when i run the slave(server) in sync mode, results are really unreliable, in either case of the master mode (sync or async). Some times times out, others frames are not complete etc.
I guess that deserves some investigation.
@sjpark608 I suggest you try the asynchronous version of slave simulator (uses twisted package). I am not a fan of twisted, because for whatever reason when i install it, it seems to change python filterwarnings(), so that deprecationwarnings pop up each time I run other python scripts. So, I test it and then uninstall, because i do not really need a serial slave simulator.
@bsense-rius Thanks for sharing your experience and your suggestions. I will try the async version and let you know the progress.
Do you have a pic of your setup ? Are the serial ports real (USB ports etc) or virtual serial ports ?
Hi, the schematic is deemed confidential, but both serial ports are two separate pairs of physical serial lines (RX1/TX1 and RX2/TX2) connected to a raspberry pi. I configured each line as a server and a client.
I also tried connecting one serial port on the raspberry pi to a laptop through a USB to serial cable using FTDI chip. And configured the laptop as server/client and the raspberry pi as client/server. All synchronous server and client configs are synchronous. This also showed the same delay issue.
I have tried asynchronous server and synchronous client. The issue persists.
Can you enable debug logs on both server and client and paste the output here?
Can you enable debug logs on both server and client and paste the output here?
Here is debug output of the server and client.
Server config port: ttyAMA1, baudrate 9600, timeout: 300ms Client config port: ttyAMA0, baudrate 9600, timeout:300ms
Client: 10 single-register read operations
single regs test
Enter number of reads: 10
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - IDLE
DEBUG:pymodbus.transaction:Running transaction 1
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 100ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 2
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419963.086268, Current Time stamp - 1643419963.091312
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 303ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 3
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419963.389234, Current Time stamp - 1643419963.395681
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 301ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 4
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419963.692148, Current Time stamp - 1643419963.697948
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 303ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 5
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419963.995494, Current Time stamp - 1643419964.002822
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 300ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 6
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419964.298889, Current Time stamp - 1643419964.305295
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 303ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 7
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419964.602225, Current Time stamp - 1643419964.609721
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 302ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 8
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419964.905247, Current Time stamp - 1643419964.912964
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 301ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 9
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419965.208604, Current Time stamp - 1643419965.215332
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 301ms
INFO:__main__:Reading Slave 247, 1 register at address 50
DEBUG:pymodbus.transaction:Current transaction state - TRANSACTION_COMPLETE
DEBUG:pymodbus.transaction:Running transaction 10
DEBUG:pymodbus.transaction:SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
DEBUG:pymodbus.framer.rtu_framer:Changing state to IDLE - Last Frame End - 1643419965.511904, Current Time stamp - 1643419965.518205
DEBUG:pymodbus.framer.rtu_framer:Waiting for 3.5 char before next send - 4.01 ms
DEBUG:pymodbus.client.sync:New Transaction state 'SENDING'
DEBUG:pymodbus.transaction:Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
DEBUG:pymodbus.transaction:Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
DEBUG:pymodbus.transaction:RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
DEBUG:pymodbus.framer.rtu_framer:Getting Frame - 0x3 0x2 0x0 0x1
DEBUG:pymodbus.factory:Factory Response[ReadHoldingRegistersResponse: 3]
DEBUG:pymodbus.framer.rtu_framer:Frame advanced, resetting header!!
DEBUG:pymodbus.transaction:Adding transaction 247
DEBUG:pymodbus.transaction:Getting transaction 247
DEBUG:pymodbus.transaction:Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
INFO:modbus_ftx:read regs: [1]
INFO:__main__:Read duration: 303ms
{'ftx_read': 10, 'ftx_error': 0, 'ftx_success': 10, 'reads_per_sec': 5, 'read_times_ms': 2817, 'avg_read_time_ms': 282.0, 'time_elapsed_s': 2, 'error_rate': 0.0}
Server: 10 single-register read
2022-01-28 17:31:53,803 MainThread DEBUG sync :46 Client Connected [/dev/ttyAMA1:/dev/ttyAMA1]
2022-01-28 17:31:53,804 MainThread DEBUG sync :581 Started thread to serve client
2022-01-28 17:32:43,072 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:43,072 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:43,073 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:43,073 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:43,074 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:43,074 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:43,376 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:43,376 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:43,376 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:43,377 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:43,377 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:43,378 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:43,678 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:43,679 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:43,679 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:43,680 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:43,680 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:43,680 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:43,981 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:43,982 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:43,982 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:43,983 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:43,983 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:43,984 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:44,285 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:44,285 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:44,286 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:44,286 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:44,287 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:44,287 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:44,588 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:44,589 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:44,589 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:44,589 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:44,590 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:44,590 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:44,892 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:44,892 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:44,892 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:44,893 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:44,893 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:44,893 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:45,194 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:45,195 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:45,195 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:45,196 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:45,196 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:45,197 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:45,498 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:45,498 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:45,499 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:45,499 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:45,500 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:45,500 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-28 17:32:45,801 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-28 17:32:45,802 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-28 17:32:45,802 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-28 17:32:45,803 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-28 17:32:45,803 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-28 17:32:45,803 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
Thanks for the logs, I see you are logging the total consumed for each transaction. However, I want to know the time spent in each stage. Could you please update your logging to include the timestamp ?
import logging
FORMAT = ('%(asctime)-15s %(threadName)-15s '
'%(levelname)-8s %(module)-15s:%(lineno)-8s %(message)s')
logging.basicConfig(format=FORMAT)
log = logging.getLogger()
log.setLevel(logging.DEBUG)
Apologies for not being explicit. Thanks in advance.
Thanks for the logs, I see you are logging the total consumed for each transaction. However, I want to know the time spent in each stage. Could you please update your logging to include the timestamp ?
import logging FORMAT = ('%(asctime)-15s %(threadName)-15s ' '%(levelname)-8s %(module)-15s:%(lineno)-8s %(message)s') logging.basicConfig(format=FORMAT) log = logging.getLogger() log.setLevel(logging.DEBUG)Apologies for not being explicit. Thanks in advance.
I just realized the client logging configuration was different from the server. The server and client configurations are the same as the previous logging.
Client: 10 single-register read operations
2022-01-31 09:58:37,142 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:37,143 MainThread DEBUG transaction :140 Current transaction state - IDLE
2022-01-31 09:58:37,143 MainThread DEBUG transaction :145 Running transaction 1
2022-01-31 09:58:37,144 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:37,144 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:37,145 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:37,216 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:37,216 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:37,217 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:37,217 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:37,217 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:37,218 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:37,218 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:37,218 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:37,219 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:37,219 MainThread INFO test_modbus :28 Read duration: 76ms
2022-01-31 09:58:37,219 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:37,220 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:37,220 MainThread DEBUG transaction :145 Running transaction 2
2022-01-31 09:58:37,220 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:37,221 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651917.215939, Current Time stamp - 1643651917.221246
2022-01-31 09:58:37,221 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:37,226 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:37,226 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:37,520 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:37,520 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:37,521 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:37,521 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:37,522 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:37,522 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:37,522 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:37,523 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:37,523 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:37,523 MainThread INFO test_modbus :28 Read duration: 303ms
2022-01-31 09:58:37,523 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:37,524 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:37,524 MainThread DEBUG transaction :145 Running transaction 3
2022-01-31 09:58:37,525 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:37,525 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651917.520397, Current Time stamp - 1643651917.52533
2022-01-31 09:58:37,525 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:37,530 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:37,530 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:37,824 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:37,825 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:37,825 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:37,826 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:37,826 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:37,826 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:37,827 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:37,827 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:37,827 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:37,828 MainThread INFO test_modbus :28 Read duration: 303ms
2022-01-31 09:58:37,828 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:37,828 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:37,829 MainThread DEBUG transaction :145 Running transaction 4
2022-01-31 09:58:37,829 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:37,829 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651917.824795, Current Time stamp - 1643651917.829756
2022-01-31 09:58:37,830 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:37,834 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:37,835 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:38,128 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:38,129 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:38,129 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:38,130 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:38,130 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:38,130 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:38,130 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:38,131 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:38,131 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:38,131 MainThread INFO test_modbus :28 Read duration: 303ms
2022-01-31 09:58:38,131 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:38,132 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:38,132 MainThread DEBUG transaction :145 Running transaction 5
2022-01-31 09:58:38,132 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:38,133 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651918.128854, Current Time stamp - 1643651918.133144
2022-01-31 09:58:38,133 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:38,137 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:38,138 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:38,432 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:38,433 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:38,433 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:38,433 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:38,434 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:38,434 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:38,434 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:38,435 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:38,435 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:38,435 MainThread INFO test_modbus :28 Read duration: 303ms
2022-01-31 09:58:38,436 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:38,436 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:38,436 MainThread DEBUG transaction :145 Running transaction 6
2022-01-31 09:58:38,437 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:38,437 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651918.432641, Current Time stamp - 1643651918.437516
2022-01-31 09:58:38,437 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:38,442 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:38,442 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:38,737 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:38,737 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:38,738 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:38,738 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:38,738 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:38,739 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:38,739 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:38,739 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:38,739 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:38,740 MainThread INFO test_modbus :28 Read duration: 303ms
2022-01-31 09:58:38,740 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:38,740 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:38,741 MainThread DEBUG transaction :145 Running transaction 7
2022-01-31 09:58:38,741 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:38,742 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651918.737019, Current Time stamp - 1643651918.742002
2022-01-31 09:58:38,742 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:38,746 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:38,747 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:39,040 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:39,040 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:39,041 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:39,041 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:39,041 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,042 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:39,042 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:39,042 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:39,042 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:39,043 MainThread INFO test_modbus :28 Read duration: 302ms
2022-01-31 09:58:39,043 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:39,043 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:39,044 MainThread DEBUG transaction :145 Running transaction 8
2022-01-31 09:58:39,044 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:39,045 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651919.040059, Current Time stamp - 1643651919.044919
2022-01-31 09:58:39,045 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:39,049 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:39,050 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:39,343 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:39,343 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:39,344 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:39,344 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:39,345 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,345 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:39,345 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:39,346 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:39,346 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:39,346 MainThread INFO test_modbus :28 Read duration: 302ms
2022-01-31 09:58:39,346 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:39,347 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:39,347 MainThread DEBUG transaction :145 Running transaction 9
2022-01-31 09:58:39,348 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:39,348 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651919.343407, Current Time stamp - 1643651919.348303
2022-01-31 09:58:39,348 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:39,353 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:39,353 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:39,646 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:39,647 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:39,647 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:39,647 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:39,648 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,648 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:39,648 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:39,649 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:39,649 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:39,649 MainThread INFO test_modbus :28 Read duration: 302ms
2022-01-31 09:58:39,650 MainThread INFO test_modbus :23 Reading Slave 247, 1 register at address 50
2022-01-31 09:58:39,650 MainThread DEBUG transaction :140 Current transaction state - TRANSACTION_COMPLETE
2022-01-31 09:58:39,650 MainThread DEBUG transaction :145 Running transaction 10
2022-01-31 09:58:39,651 MainThread DEBUG transaction :273 SEND: 0xf7 0x3 0x0 0x32 0x0 0x1 0x31 0x53
2022-01-31 09:58:39,651 MainThread DEBUG rtu_framer :269 Changing state to IDLE - Last Frame End - 1643651919.646638, Current Time stamp - 1643651919.651659
2022-01-31 09:58:39,652 MainThread DEBUG rtu_framer :277 Waiting for 3.5 char before next send - 4.01 ms
2022-01-31 09:58:39,656 MainThread DEBUG sync :76 New Transaction state 'SENDING'
2022-01-31 09:58:39,656 MainThread DEBUG transaction :287 Changing transaction state from 'SENDING' to 'WAITING FOR REPLY'
2022-01-31 09:58:39,950 MainThread DEBUG transaction :375 Changing transaction state from 'WAITING FOR REPLY' to 'PROCESSING REPLY'
2022-01-31 09:58:39,950 MainThread DEBUG transaction :297 RECV: 0xf7 0x3 0x2 0x0 0x1 0xb1 0x91
2022-01-31 09:58:39,951 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x2 0x0 0x1
2022-01-31 09:58:39,951 MainThread DEBUG factory :266 Factory Response[ReadHoldingRegistersResponse: 3]
2022-01-31 09:58:39,951 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,952 MainThread DEBUG transaction :454 Adding transaction 247
2022-01-31 09:58:39,952 MainThread DEBUG transaction :465 Getting transaction 247
2022-01-31 09:58:39,952 MainThread DEBUG transaction :224 Changing transaction state from 'PROCESSING REPLY' to 'TRANSACTION_COMPLETE'
2022-01-31 09:58:39,952 MainThread INFO modbus_ftx :148 read regs: [1]
2022-01-31 09:58:39,953 MainThread INFO test_modbus :28 Read duration: 302ms
{'ftx_read': 10, 'ftx_error': 0, 'ftx_success': 10, 'reads_per_sec': 5, 'read_times_ms': 2799, 'avg_read_time_ms': 280.0, 'time_elapsed_s': 2, 'error_rate': 0.0}
Server: 10 single-register read operations
2022-01-31 09:58:29,690 MainThread DEBUG sync :46 Client Connected [/dev/ttyAMA1:/dev/ttyAMA1]
2022-01-31 09:58:29,691 MainThread DEBUG sync :581 Started thread to serve client
2022-01-31 09:58:37,202 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:37,202 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:37,203 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:37,203 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:37,204 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:37,204 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:37,505 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:37,506 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:37,506 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:37,507 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:37,508 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:37,509 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:37,810 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:37,810 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:37,811 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:37,811 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:37,812 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:37,813 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:38,114 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:38,115 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:38,115 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:38,116 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:38,117 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:38,117 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:38,418 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:38,419 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:38,419 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:38,420 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:38,420 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:38,421 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:38,722 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:38,722 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:38,723 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:38,724 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:38,724 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:38,725 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:39,027 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:39,027 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:39,027 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,028 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:39,028 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:39,028 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:39,329 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:39,330 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:39,330 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,331 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:39,331 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:39,332 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:39,633 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:39,633 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:39,634 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,634 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:39,634 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:39,635 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
2022-01-31 09:58:39,936 MainThread DEBUG rtu_framer :185 Getting Frame - 0x3 0x0 0x32 0x0 0x1
2022-01-31 09:58:39,936 MainThread DEBUG factory :137 Factory Request[ReadHoldingRegistersRequest: 3]
2022-01-31 09:58:39,937 MainThread DEBUG rtu_framer :107 Frame advanced, resetting header!!
2022-01-31 09:58:39,937 MainThread DEBUG context :64 validate: fc-[3] address-51: count-1
2022-01-31 09:58:39,938 MainThread DEBUG context :78 getValues fc-[3] address-51: count-1
2022-01-31 09:58:39,938 MainThread DEBUG sync :144 send: [ReadHoldingRegistersResponse (1)]- b'f703020001b191'
@sjpark608 thanks for the logs, I will take a look and try to reproduce the issue.
@dhoomakethu eagerly waiting for your response.
I am also trying same, like two serial cable connected with rtu configuration. One COM port act as server and another COM port act as server. but setting up address on server and reading exact value on slave I have facing issue.
I have created issue request on following link https://github.com/riptideio/pymodbus/issues/860
@sjpark608 apologies, this got derailed. I will spend some time to see if this could be reproduced.
We now have a test that among others addresses this issue test/test_examples.py, furthermore I did some testing: examples/server_sync + examples/client_sync using 2 USB rs-485 adapters, no delay, limiting factor were the baud rate. examples/server_sync + examples/client_async using 2 USB rs-485 adapters, no delays same speed as above. examples/server_async + examples/client_async using 2 USB rs-485 adapters, a bit faster but the limiting factor is still baud rate.
In general using a sync server is really asking for something slow.
