Modbus lag

sipvoip · February 18, 2017, 9:27pm

Sorry about that, try now.

ssalonen · February 18, 2017, 9:39pm

While I dig into the logs tomorrow, you might want to try one thing.

In order to rule out any hardware issues, you would like to replace the server, not the client. You could setup diagslave (many instances with different ports if necessary) for each endpoint you have. Would be nice to know if you get transaction id errors then…

Best
Sami

sipvoip · February 18, 2017, 9:42pm

Was I not doing that?

nathan@marge linux $ ./modpoll -c 1 -r 2 -m tcp 10.88.64.46 -t 1
modpoll 3.4 - FieldTalk™ Modbus® Master Simulator
Copyright © 2002-2013 proconX Pty Ltd
Visit http://www.modbusdriver.com for Modbus libraries and tools.

Protocol configuration: MODBUS/TCP
Slave configuration…: address = 1, start reference = 2, count = 1
Communication…: 10.88.64.46, port 502, t/o 1.00 s, poll rate 1000 ms
Data type…: discrete input

– Polling slave… (Ctrl-C to stop)
[2]: 0
– Polling slave… (Ctrl-C to stop)
[2]: 0
– Polling slave… (Ctrl-C to stop)
[2]: 1
– Polling slave… (Ctrl-C to stop)
[2]: 1
– Polling slave… (Ctrl-C to stop)
[2]: 1
– Polling slave… (Ctrl-C to stop)
[2]: 0
– Polling slave… (Ctrl-C to stop)
[2]: 0
– Polling slave… (Ctrl-C to stop)
[2]: 0
– Polling slave… (Ctrl-C to stop)
[2]: 0
– Polling slave… (Ctrl-C to stop)

That was I believe pulling from the client and it updated from 0 to 1 the second I opened the door.

ssalonen · February 19, 2017, 10:38am

Well the terminology is a bit confusing but it goes like this

modbus slave is your physical slave. With modbus tcp, slave is tcp server
modbus master is openhab. With modbus tcp, master is the tcp client

The client (=master) initates the read/write requests.

When you used modpoll, it is another client, similar to openhab. Did you have the openhab running the same time you run modpoll?

I can think of the following ways to test this

run instances of diagslave, one corresponding to your slave ips. That should be five slaves corresponding to the ip addressed ending with .45, .46, .47, .48 and , .49. Start openhab and see if you get any issues.
you can try “simulate” opening a door by calling pollmb.py (see this section in wiki for more details)
run openhab against real hardware. At the same time (when opening door), run modpoll to see if you can pick up the changes. This is also a good test since the slave device will be under stress (requests bombarded by openhab)

Best,
Sami

ssalonen · February 19, 2017, 11:37am

@sipvoip

Now with improved logging I can comment more.

With the last log, there is only single “transaction id match” error, so that should not be the root cause after all.

The queries to to the slaves seem to be bottlenecked. For example, coils are read from 10.88.64.45 every ~10s.

$ grep -B5 "Sending request.*ReadCoils" ~/Downloads/modbus.log|grep  64.45|grep borrowing
2017-02-18 16:23:02 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=55674]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 1 ms
2017-02-18 16:23:11 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=55715]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 1 ms
2017-02-18 16:23:22 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=55758]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:23:33 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=55804]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 1 ms
2017-02-18 16:23:44 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=55860]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 1 ms
2017-02-18 16:23:54 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=55929]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:24:09 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=55990]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 1 ms
2017-02-18 16:24:21 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56042]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:24:32 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56099]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:24:42 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56145]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:24:55 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56197]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:25:08 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56253]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:25:21 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56320]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:25:31 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56367]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:25:43 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56412]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:25:55 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56467]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:26:07 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56531]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:26:18 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56585]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:26:30 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56621]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:26:41 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56679]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms

I believe this matches the lag you observe.

We can analyze how long does the binding wait in order to get a connection (using command like: grep borrowing ~/Downloads/modbus.log|rev|cut -d' ' -f1-5|rev|grep 10.88.64.45)

10.88.64.45: 0-1 ms
10.88.64.46: 1000ms or 2000ms often, just couple of times 1ms
10.88.64.47: 1000ms or 2000ms often, just couple of times 1ms
10.88.64.48: 1000ms or 2000ms often, just couple of times 1ms
10.88.64.49: almost always 1-3ms, once 1000ms

This means that the slaves with ip ending with 46, 47 and 48 slow down polling in general. This is due to the fact that each “slave” (water, basement, etc.) are polled in turn, something like this:

poll water (45)
poll basement (46)
poll basement_shared (46)
poll basement_ponet (46)
poll first (47)
poll first_ponet (47)
poll first_shared (47)
poll second (48)
poll second_ponet (48)
poll second_shared (48)
poll shed (49)

By default, connection is closed after each read and write request. By default, the binding waits 60ms before proceeding with request to the same endpoint (same ip and port).

So in reality the basic polling goes like this:

poll water (45)
poll basement (46)
wait 60ms, poll basement_shared (46)
wait 60ms, poll basement_ponet (46)
poll first (47)
wait 60ms, poll first_ponet (47)
wait 60ms, poll first_shared (47)
poll second (48)
wait 60ms, poll second_ponet (48)
wait 60ms, poll second_shared (48)
poll shed (49)

I noticed that you had lot of writes happening at the same time, which means polling is “interrupted” due to the writes, something like this

poll water (45)
poll basement (46)
wait 60ms, poll basement_shared (46)
wait 60ms, poll basement_ponet (46)
poll first (47)
wait 60ms, write to ip .47
wait 60ms, poll first_ponet (47)
wait 60ms, write to ip .47
wait 60ms, poll first_shared (47)
poll second (48)
wait 60ms, poll second_ponet (48)
wait 60ms, poll second_shared (48)
poll shed (49)

This makes the poll take longer time.

With this hypothesis I have been investigating what happens between two polls to the same ip. I’m looking the following time interval:

2017-02-18 16:26:30 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56621]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms
2017-02-18 16:26:41 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (water): borrowing connection (got TCPMasterConnection@66c735a8[socket=Socket[addr=/10.88.64.45,port=502,localport=56679]]) for endpoint ModbusTCPSlaveEndpoint@34524c60[address=10.88.64.45,port=502] took 0 ms

Let’s check out all connection attemps in this interval:

grep " connecting" ~/Downloads/modbus_log_2017_02_18_16_26_from_30_to_41s.txt|cut -d' ' -f1,2,15
    2017-02-18 16:26:30 TCPMasterConnection@2297e31[socket=Socket[addr=/10.88.64.47,port=502,localport=58742]]
    2017-02-18 16:26:31 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37163]]
    2017-02-18 16:26:31 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34289]]
    2017-02-18 16:26:32 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37170]]
    2017-02-18 16:26:32 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34295]]
    2017-02-18 16:26:33 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37176]]
    2017-02-18 16:26:33 TCPMasterConnection@2297e31[socket=Socket[addr=/10.88.64.47,port=502,localport=58760]]
    2017-02-18 16:26:33 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34305]]
    2017-02-18 16:26:34 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37184]]
    2017-02-18 16:26:34 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34313]]
    2017-02-18 16:26:35 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37193]]
    2017-02-18 16:26:35 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34320]]
    2017-02-18 16:26:36 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37199]]
    2017-02-18 16:26:36 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34323]]
    2017-02-18 16:26:37 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37203]]
    2017-02-18 16:26:37 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34328]]
    2017-02-18 16:26:38 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37207]]
    2017-02-18 16:26:39 TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34333]]
    2017-02-18 16:26:39 TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37212]]
    2017-02-18 16:26:40 TCPMasterConnection@2297e31[socket=Socket[addr=/10.88.64.47,port=502,localport=58795]]


grep " connecting" ~/Downloads/modbus_log_2017_02_18_16_26_from_30_to_41s.txt|cut -d' ' -f1,2,15|cut -d'=' -f3|sort|uniq -c
   8 /10.88.64.46,port
   3 /10.88.64.47,port
   9 /10.88.64.48,port

During the ~10 second interval, 20 connections are made to other slaves.

We can confirm that all these connections need to wait the ~60ms period between transactions:

grep "delay between connections" ~/Downloads/modbus_log_2017_02_18_16_26_from_30_to_41s.txt|cut -d' ' -f1-2,5-6,15
2017-02-18 16:26:30 Waited 59ms TCPMasterConnection@2297e31[socket=Socket[addr=/10.88.64.47,port=502,localport=58742]]
2017-02-18 16:26:31 Waited 58ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37163]]
2017-02-18 16:26:31 Waited 58ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34289]]
2017-02-18 16:26:32 Waited 58ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37170]]
2017-02-18 16:26:32 Waited 59ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34295]]
2017-02-18 16:26:33 Waited 58ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37176]]
2017-02-18 16:26:33 Waited 57ms TCPMasterConnection@2297e31[socket=Socket[addr=/10.88.64.47,port=502,localport=58760]]
2017-02-18 16:26:33 Waited 57ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34305]]
2017-02-18 16:26:34 Waited 57ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37184]]
2017-02-18 16:26:34 Waited 57ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34313]]
2017-02-18 16:26:35 Waited 58ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37193]]
2017-02-18 16:26:35 Waited 57ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34320]]
2017-02-18 16:26:36 Waited 59ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37199]]
2017-02-18 16:26:36 Waited 57ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34323]]
2017-02-18 16:26:37 Waited 58ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37203]]
2017-02-18 16:26:37 Waited 58ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34328]]
2017-02-18 16:26:38 Waited 59ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37207]]
2017-02-18 16:26:39 Waited 58ms TCPMasterConnection@2a326a36[socket=Socket[addr=/10.88.64.46,port=502,localport=34333]]
2017-02-18 16:26:39 Waited 58ms TCPMasterConnection@17f95457[socket=Socket[addr=/10.88.64.48,port=502,localport=37212]]
2017-02-18 16:26:40 Waited 58ms TCPMasterConnection@2297e31[socket=Socket[addr=/10.88.64.47,port=502,localport=58795]]

Summary and next steps:

the performance could be improved by having separate poll threads for different endpoints (ip+port). Something that has been discussed in the context of error handling before here in community threads… Something I can consider for the openhab2 refactoring I’m working on…
currently it is hardcoded that at most single connection is allowed to the endpoint. Lifting this restriction or making it configurable should improve performance (assuming slave can deal with multiple clients – not all can). Something I can consider for openhab2.
Assuming your slave can handle the requests, you should be able to improve performance by reducing the wait time between transactions by configuring interTransactionDelayMillis connection string parameter. Consult Advanced connection parameters (since 1.9.0) section in wiki for more details.
If possible/feasible, reducing amouont of write commands certainly will improve the performance.

Let me know how it goes with the interTransactionDelayMillis connection parameter. Remember to configure the same connection settings to all openhab “slaves” sharing the same endpoint (in your case, ip).

Best,
Sami

sipvoip · February 19, 2017, 7:18pm

Trying to setup diagslave and I am getting:

2017-02-19 14:12:47 WARN  o.o.b.m.internal.ModbusSlave[:363]- ModbusSlave (digislave): Error getting a new connection for endpoint ModbusTCPSlaveEndpoint@159b64ea[address=10.88.64.6,port=502]. Error was: Unable to validate object
2017-02-19 14:12:47 TRACE o.o.b.m.internal.ModbusSlave[:366]- ModbusSlave (digislave): borrowing connection (got null) for endpoint ModbusTCPSlaveEndpoint@159b64ea[address=10.88.64.6,port=502] took 1 ms
2017-02-19 14:12:47 WARN  o.o.b.m.internal.ModbusSlave[:504]- ModbusSlave (digislave) not connected -- aborting read request net.wimpi.modbus.msg.ReadCoilsRequest@7bfc63b9. Endpoint ModbusTCPSlaveEndpoint@159b64ea[address=10.88.64.6,port=502]

My config looks right to me:

modbus:tcp.diagslave.connection=10.88.64.6:502:0
modbus:tcp.diagslave.length=55
modbus:tcp.diagslave.type=coil

I tried lowering the interTransactionDelayMillis to 0 and that I think helped a little, but the root of the problem is still there. I guess I will see if the manufacture knows anything, the load measured on the device is very low, less ten 10%.

The odd thing is that if I go from poll=100 to 800 the delay is still the same. Its also odd that I can’t see that delay (could be looking wrong) on wireshark.

sipvoip · February 19, 2017, 7:38pm

Figured out the Unable to validate object, it was firewalld runing on the box I was running diagslave on.

sipvoip · February 19, 2017, 7:43pm

Is it possible to run modbus binding more then once?

sipvoip · February 19, 2017, 11:00pm

While clearly not the right fix, I was able to fix my slow issue by setting receiveTimeoutMillis to 20 ms. This broke the connection and passed the device. I think the root issue is a bad software stack on my modbus devices. You can checkout the pcap at http://share.robotics.net/modbus.pcap.

rossko57 · February 19, 2017, 11:24pm

I add up that polling cycle to around a half second, i.e. longer than the binding poll parameter. Curious, what happens here - requests pile up until they fail through timeout, or missed periodic polls are simply missed out? I’m presuming a cycle isn’t cut short and restarted.

Is it possible to make the binding issue a warning when poll cycle incomplete before next is scheduled?

ssalonen · February 20, 2017, 6:00am

Hi

@sipvoip What do you mean running modbus binding more than once?

The odd thing is that if I go from poll=100 to 800 the delay is still the same. Its also odd that I can’t see that delay (could be looking wrong) on wireshark.

This is expected as poll period is not the the bottleneck, but various delays happening during the cycle (e.g. delay between transactions, reading responses etc.). You can even use poll period of 1ms to “poll constantly”. (see also below on the wireshark analysis)

I was able to fix my slow issue by setting receiveTimeoutMillis to 20 ms

This is interesting. So basically if the modbus response read operations take more than that, the transaction fails.

It was hard to see from the logs whether time between request and response is high since the log timestamp used only second accuracy (not millisecond). Perhaps it could be seen from the pcap file.

I had a look at the pcap file and perhaps the see the issue. It is related to closing the connection (SYN)? You can see retransmissions of some messages (from master to slave, and vice versa). This seems to take the time you are suffering from (1s waited before master re-transmits, 1-2s waited before slave re-transmits).

I wonder if this all is related to discussion in issue 4972. Not sure really, since we do not see (abortive close) RST messages.

Did you succeed to try out the binding with diagslave? Would be interesting to capture the traffic there.

Given that connection closing (SYN/FIN retransmission) takes the time, you might be able to speed up by keeping the connections open longer. You can set reconnectAfterMillis to 600000 (which means 300s or 5min) to keep the connections 5 minutes open before re-opening them.

Best
Sami

ssalonen · February 20, 2017, 6:11am

Hi,

The “poll scheduling” is actually done by openhab framework, not by the binding.

I have investigated the details previously since “missing the poll window” is quite often the case (e.g. users running 1ms poll loop). The polling takes whatever it takes, and then next poll round will be started after the “poll period”. For example

poll all the slaves – takes 10s
sleep for “poll period”, e.g. 250ms
poll all the slaves – takes 10s.
etc…

For more details, the logic is found here AbstractActiveService

Best
Sami

sipvoip · February 20, 2017, 4:46pm

Would not 600000 be 10 min? Man, all I know is it fixed my issue. I just checked all my slaves and they 90% of the time they show up as 0 ms, and the rest are 1 ms. I don’t see anything higher then 1 ms for any slave.

I did and I did not see the issue with diagslave, so the issue must be with the PoKeys57 device. When I emailed them for support they said don’t close the connection every time.

BTW, why is the default reconectAfterMillis 0? I would think it makes more sense to keep the TCP socket open.

ssalonen · February 20, 2017, 6:59pm

Would not 600000 be 10 min?

Yeah my bad

BTW, why is the default reconectAfterMillis 0? I would think it makes more sense to keep the TCP socket open.

Well… That is a long story. Refer to this one for the discussion

github.com/openhab/openhab1-addons

Modbus binding should close TCP connection after every transaction

opened 08:31AM - 17 Jan 16 UTC

closed 03:03PM - 31 Jan 16 UTC

ssalonen

bug pr-submitted

During 1.8.0-SNAPSHOT development there was regression caused by my pull request… [#3512](https://github.com/openhab/openhab/pull/3512) that broke down installation for some users (for details consult [this community discussion](https://community.openhab.org/t/modbus-connection-problem/6108)). In the PR I had removed the code that closes TCP connection after every modbus transaction, i.e. after every read or write operation, ([original pull request](https://github.com/openhab/openhab/pull/3228) from @paolodenti to [issue #658](https://github.com/openhab/openhab/issues/658)). As result of this the binding keeps the connections open as long as possible, and reconnecting only in failure situations. However, as reported by @wtrucci, this is problematic behaviour when the modbus server is only able to serve one client at a time, and the user wishes to access the modbus server at the same time openhab is connected to it (as in the case of @wtrucci). Furthermore, if there are many slaves defined in openhab.cfg that point to the same modbus server (e.g. with different valuetype), many connections would be established to the same server.

Long story short: keeping the connection open causes serious issues in some cases. For example, if the slave can handle only single client at a time, openhab would essentially block the access to the slave from other consumers.

Great to hear that you got it working! Glad to help always.

Best
Sami