Modbus lag

I am using several Pokeys 57E boards with modbus, most of my inputs are doors and windows so states are not that quick. However 6 of my inputs are doorbells and they only work if you hold the doorbell down for 1 - 2 seconds. I have tried to change the modbus:poll from 300, 200, 50, and all the way down to 10, but it does not change how long I have to hold down the doorbell to get OpenHab to see it.

Sounds like the bottle neck is not the MODBUS TCP connection but rather the processing of updates or rules…

Can you have the doorbell set a MB register in the Pokeys board and once OH sees it a rule can clear it? That also can help to de-bounce the button as well :slight_smile:

Tom

I thought it may be that, but when I look at the logs I am not seeing updates in the logs, so I don’t think when it is not working it is even getting to the rules. I hacked the solution by building a small PobBocks program on the PoKeys board that on a state change holds a shared line that modbus reads low for 8 seconds.

Can you explain more what you mean by setting a register and clearing it?

What version of modbus binding? You might want to try out with 1.9.0-SNAPSHOT which logs out any possible IO errors and has much improved performance.

Best,
Sami

1 Like

I was thinking you might be able to have the input Latch on until you reset it.

The Pokeys board may not be able to do that…

tom

Make sure all your Modbus devices are valid and working i.e. no non-existant slaves or non-responding registers. Modbus binding may be bogging down in retries and timeouts between polling the working parts. As ssalonen says, use latest binding with error reporting

Thanks for the all comments! I am using a recent 1.9.0-SNAPSHOT (6/19/16), and there are no errors and only a few warnings every now and then, nothing to make me think that a device is down or not working. Not sure what qualifies as a lot of registers, but my config consists of:

# Modbus
modbus:poll=250

modbus:tcp.shed.connection=10.71.129.8
modbus:tcp.shed.length=12
modbus:tcp.shed.type=coil

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

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

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

modbus:tcp.basement_ponet.type=coil
modbus:tcp.basement_ponet.connection=10.71.129.36
modbus:tcp.basement_ponet.start=2071
modbus:tcp.basement_ponet.length=8
modbus:tcp.basement_ponet.type=coil

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

modbus:tcp.first_ponet.connection=10.71.129.37
modbus:tcp.first_ponet.start=2071
modbus:tcp.first_ponet.length=8
modbus:tcp.first_ponet.type=coil

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

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

modbus:tcp.second_ponet.connection=10.71.129.38
modbus:tcp.second_ponet.start=2071
modbus:tcp.second_ponet.length=8
modbus:tcp.second_ponet.type=coil

P.S. I thank you so much for “updateunchangeditems”, I no longer need to use my own binding that did the same thing!

If you get warnings, it might require more time to poll all the slaves (slaves being “shed”, “water”, “basement”, etc.). Could you paste snippet of your logs to show what kind of errors you get?

Best,
Sami

I was not really worried about the warnings because it does not happen often and does not matter if I update every 50 ms or 500 ms.

2016-06-26 14:13:08 WARN  o.o.b.m.internal.ModbusSlave[:475]- ModbusSlave (first): Transaction id of the response does not match request net.wimpi.modbus.msg.ReadCoilsRequest@36a2709b.  Endpoint ModbusTCPSlaveEndpoint@5e620524[address=10.71.129.37,port=502]. Connection: TCPMasterConnection@340daf83[socket=Socket[addr=/10.71.129.37,port=502,localport=42038]]. Ignoring response.
2016-06-26 14:14:33 WARN  o.o.b.m.internal.ModbusSlave[:475]- ModbusSlave (water): Transaction id of the response does not match request net.wimpi.modbus.msg.ReadCoilsRequest@26c31494.  Endpoint ModbusTCPSlaveEndpoint@3409e7f[address=10.71.129.35,port=502]. Connection: TCPMasterConnection@6f0abb4e[socket=Socket[addr=/10.71.129.35,port=502,localport=47713]]. Ignoring response.
2016-06-26 14:14:36 WARN  o.o.b.m.internal.ModbusSlave[:475]- ModbusSlave (basement): Transaction id of the response does not match request net.wimpi.modbus.msg.ReadCoilsRequest@195c1886.  Endpoint ModbusTCPSlaveEndpoint@2705d88d[address=10.71.129.36,port=502]. Connection: TCPMasterConnection@3b3a1228[socket=Socket[addr=/10.71.129.36,port=502,localport=39240]]. Ignoring response.
2016-06-26 14:16:53 WARN  o.o.b.m.internal.ModbusSlave[:475]- ModbusSlave (first_shared): Transaction id of the response does not match request net.wimpi.modbus.msg.ReadCoilsRequest@42960834.  Endpoint ModbusTCPSlaveEndpoint@3b77a0c8[address=10.71.129.37,port=502]. Connection: TCPMasterConnection@340daf83[socket=Socket[addr=/10.71.129.37,port=502,localport=42612]]. Ignoring response.

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

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

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

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.

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

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

1 Like

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

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

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

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

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

Best
Sami