Modbus lag

Add-ons Bindings
10

Well that it is interesting warning message. Basically the binding gets responses that do match the request id (“transaction id”). Per the modbus spec, binding ignores these responses altogether. Haven’t seen this in real life before.

In any case, I agree with your assessment. The warnings do not come often enough to explain your issues.

I would recommend double confirming that new events are received fast enough from the slaves.Try this with poll 50ms: If you temporarily set updateunchangeditems=true, the events log should be easy to read… Alternatively you could try to enable verbose logging, and paste the results to pastebin.com and report back here.

Best,
Sami

11

Hi Nathan,

to track down the problem, would it be possible to set up a modbus poller specifically for that doorbell and sniff the network to see whether the state change is correctly transmitted to openHAB?

Regarding item changes: On my bananapi I see that after startup, when loads of updates flood the system, it may take some seconds until the updates are really processed in openHAB. When the system is running normal, updates are processed quite fast.

I also use modbus heavily, my number of items is similar to yours. However, state updates are reflected typically within one second or less at the GUI. My polling frequency at the moment is 500ms.

How is the CPU load on your system? Maybe a too high polling frequency causes heavy cpu load for the polling itself and leaves less cpu for Item handling.

I was already thinking of extending the binding in a way that one may configure different polling frequencies for different pollers. What would you think about that?

I introduced updateunchangeditems because of the heavy cpu load the binding caused before :slight_smile:

Yours

Wolfgang

1 Like
12

I know this is a old topic but new information has surfaced with the “Transaction id of the response does not match request” error message.

While fixing another issue I encountered a race condition in how the binding handles and checks the transaction IDs. You might want to test with experimental version in PR #5088 that has this one fixed

Best
Sami

13

Still seeing lag, by that I mean, if I open a door it takes a few seconds for that to show up in openhab, yet I am polling every 200 ms. Also, still seeing some errors, but I think there are less.

   2017-02-17 12:04:12 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (basement_ponet): Transaction id of the response (1069) does not match request net.wimpi.modbus.msg.WriteCoilRequest@72bbb194.  Endpoint 1074. Connection: ModbusTCPSlaveEnd
    point@39baf2f[address=10.88.64.46,port=502]. Ignoring response.
    2017-02-17 12:05:28 WARN  o.o.b.m.internal.ModbusSlave[:530]- ModbusSlave (second_ponet): Transaction id of the response (1236) does not match request net.wimpi.modbus.msg.ReadCoilsRequest@3bcfe21d id 1240.  Endpoint ModbusTCPSlaveEndpoint@52731f
    ed[address=10.88.64.48,port=502]. Connection: TCPMasterConnection@12268718[socket=Socket[addr=/10.88.64.48,port=502,localport=58338]]. Ignoring response.
    2017-02-17 12:32:19 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (second_ponet): Transaction id of the response (4584) does not match request net.wimpi.modbus.msg.WriteCoilRequest@2a53f288.  Endpoint 4589. Connection: ModbusTCPSlaveEndpo
    int@52731fed[address=10.88.64.48,port=502]. Ignoring response.
    2017-02-17 12:45:35 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (second_ponet): Transaction id of the response (6346) does not match request net.wimpi.modbus.msg.WriteCoilRequest@6cbef38.  Endpoint 6350. Connection: ModbusTCPSlaveEndpoi
    nt@52731fed[address=10.88.64.48,port=502]. Ignoring response.
    2017-02-17 12:52:44 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (first_ponet): Transaction id of the response (7287) does not match request net.wimpi.modbus.msg.WriteCoilRequest@15eae080.  Endpoint 7290. Connection: ModbusTCPSlaveEndpoi
    nt@399da10f[address=10.88.64.47,port=502]. Ignoring response.
    2017-02-17 12:55:21 WARN  o.o.b.m.internal.ModbusSlave[:530]- ModbusSlave (basement): Transaction id of the response (7629) does not match request net.wimpi.modbus.msg.ReadCoilsRequest@75bd731f id 7633.  Endpoint ModbusTCPSlaveEndpoint@3ffb8632[a
    ddress=10.88.64.46,port=502]. Connection: TCPMasterConnection@4c8e9d4[socket=Socket[addr=/10.88.64.46,port=502,localport=36085]]. Ignoring response.
    2017-02-17 12:58:58 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (second_ponet): Transaction id of the response (8107) does not match request net.wimpi.modbus.msg.WriteCoilRequest@69197e1e.  Endpoint 8112. Connection: ModbusTCPSlaveEndpo
    int@52731fed[address=10.88.64.48,port=502]. Ignoring response.
    2017-02-17 13:39:18 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (first_ponet): Transaction id of the response (13445) does not match request net.wimpi.modbus.msg.WriteCoilRequest@2071be98.  Endpoint 13448. Connection: ModbusTCPSlaveEndp
    oint@399da10f[address=10.88.64.47,port=502]. Ignoring response.
    2017-02-17 13:44:01 WARN  o.o.b.m.internal.ModbusSlave[:530]- ModbusSlave (first_ponet): Transaction id of the response (14074) does not match request net.wimpi.modbus.msg.ReadCoilsRequest@22315b5 id 14076.  Endpoint ModbusTCPSlaveEndpoint@399da1
    0f[address=10.88.64.47,port=502]. Connection: TCPMasterConnection@5af10956[socket=Socket[addr=/10.88.64.47,port=502,localport=41150]]. Ignoring response.
    2017-02-17 13:50:11 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (basement_ponet): Transaction id of the response (14890) does not match request net.wimpi.modbus.msg.WriteCoilRequest@76a15abf.  Endpoint 14895. Connection: ModbusTCPSlaveE
    ndpoint@39baf2f[address=10.88.64.46,port=502]. Ignoring response.
    2017-02-17 13:55:13 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (second_ponet): Transaction id of the response (15555) does not match request net.wimpi.modbus.msg.WriteCoilRequest@fcf21cb.  Endpoint 15561. Connection: ModbusTCPSlaveEndp
    oint@52731fed[address=10.88.64.48,port=502]. Ignoring response.
    2017-02-17 14:14:23 WARN  o.o.b.m.internal.ModbusSlave[:341]- ModbusSlave (second_ponet): Transaction id of the response (18105) does not match request net.wimpi.modbus.msg.WriteCoilRequest@38d896bf.  Endpoint 18109. Connection: ModbusTCPSlaveEnd
    point@52731fed[address=10.88.64.48,port=502]. Ignoring response.
    2017-02-17 14:39:37 WARN  o.o.b.m.internal.ModbusSlave[:530]- ModbusSlave (first_ponet): Transaction id of the response (21461) does not match request net.wimpi.modbus.msg.ReadCoilsRequest@7e15fd51 id 21467.  Endpoint ModbusTCPSlaveEndpoint@399da
    10f[address=10.88.64.47,port=502]. Connection: TCPMasterConnection@5af10956[socket=Socket[addr=/10.88.64.47,port=502,localport=51177]]. Ignoring response.
14

Thanks @sipvoip for testing the version.

Could you please test using the new version I just made:

https://github.com/openhab/openhab1-addons/files/784910/org.openhab.binding.modbus-1.10.0-SNAPSHOT-175604.zip

While testing, please enable verbose logs according to this guide.

This includes some logging fixes and I should be able to confirm better what is happening.

Best,
Sami

15

Sami, just for info - Nathan’s host server is unusually powerful for Openhab - should be good at showing up races, reentrancy etc.

1 Like
16

Still seeing delay of about 6 seconds between when I open a door and it shows up in openHAB.

http://share.robotics.net/modbus.log.gz

My config:

# Modbus
modbus:poll=250

modbus:tcp.water.connection=10.88.64.45
modbus:tcp.water.length=55
modbus:tcp.water.type=coil

modbus:tcp.basement.connection=10.88.64.46
modbus:tcp.basement.length=55
modbus:tcp.basement.type=coil

modbus:tcp.basement_shared.connection=10.88.64.46
modbus:tcp.basement_shared.start=200
modbus:tcp.basement_shared.length=2
modbus:tcp.basement_shared.type=coil

modbus:tcp.basement_ponet.connection=10.88.64.46
modbus:tcp.basement_ponet.start=2072
modbus:tcp.basement_ponet.length=8
modbus:tcp.basement_ponet.type=coil

modbus:tcp.first.connection=10.88.64.47
modbus:tcp.first.length=55
modbus:tcp.first.type=coil

modbus:tcp.first_ponet.connection=10.88.64.47
modbus:tcp.first_ponet.start=2072
modbus:tcp.first_ponet.length=8
modbus:tcp.first_ponet.type=coil

modbus:tcp.first_shared.connection=10.88.64.47
modbus:tcp.first_shared.start=200
modbus:tcp.first_shared.length=2
modbus:tcp.first_shared.type=coil

modbus:tcp.second.connection=10.88.64.48
modbus:tcp.second.length=55
modbus:tcp.second.type=coil

modbus:tcp.second_ponet.connection=10.88.64.48
modbus:tcp.second_ponet.start=2072
modbus:tcp.second_ponet.length=8
modbus:tcp.second_ponet.type=coil

modbus:tcp.shed.connection=10.88.64.49
modbus:tcp.shed.length=55
modbus:tcp.shed.type=coil
17

thanks, yes nothing was changed in the latest version except logging so it’s quite expected that the issues remain the same.

Will let you know what I find out from the logs

Best,
Sami

18

Hi,

it seems that net.wimpi.modbus logger messages are not there. Did you follow the guide I posted to configure the loggers?

Could you please try again?

Best,
Sami

19

Sorry about that, only had one logger. Also, just to make sure it was not my hardware I tested my inputs with modpoll. It only lets me poll every second, but I see the door state change with less then 1 second delay.

http://share.robotics.net/modbus.log.gz

20

Could you please check the link, I believe it’s not working - I get “not found” error.

Best
Sami

21

Sorry about that, try now.

1 Like
22

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

23

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.

24

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

25

@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

26

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.

27

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

28

Is it possible to run modbus binding more then once?

29

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.