Possible performance of bindings?

Add-ons Bindings
1

We are currently evaluating if it is possible to use openhab for automation of a building. I am not sure, if it is fast enough, because the following test did not succeed.

There are 240 items where always 2 items are connected to one modbus channel which makes 120 modbus channels. 120 Registers are polled once per second from a modbus tcp slave. Only one register counts monotonic (+ 1 once per second) on the modbus slave. Thus 2 items are notified about the change.

Independently if openhab runs on openhabian/Rasperry PI 2 or on a linux pc, the following happens:

  • openhab polls one time per second and get data from the modbus slave as it should be
  • when the first update message is logged, the updates are already far behind:

register content on the server: 13330

logging of openhab:

2018-06-28 16:51:01.976 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13289 to 13257
2018-06-28 16:51:01.993 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13289 to 13257
2018-06-28 16:51:02.501 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13257 to 13284
2018-06-28 16:51:02.504 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13257 to 13284
2018-06-28 16:51:03.837 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13284 to 13262
2018-06-28 16:51:03.880 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13284 to 13262
2018-06-28 16:51:03.995 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13262 to 13321
2018-06-28 16:51:04.042 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13262 to 13321
2018-06-28 16:51:04.048 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13321 to 13294
2018-06-28 16:51:04.053 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13321 to 13294
2018-06-28 16:51:04.366 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13294 to 13290
2018-06-28 16:51:04.370 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13294 to 13290
2018-06-28 16:51:04.376 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13290 to 13261
2018-06-28 16:51:04.390 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13290 to 13261
2018-06-28 16:51:05.897 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13261 to 13313
2018-06-28 16:51:05.898 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13261 to 13313
2018-06-28 16:51:06.382 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13313 to 13310
2018-06-28 16:51:06.402 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13313 to 13310
2018-06-28 16:51:06.414 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13310 to 13256
2018-06-28 16:51:06.416 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13310 to 13256
2018-06-28 16:51:06.439 [vent.ItemStateChangedEvent] - dItem_0057_0002 changed from 13256 to 13309
2018-06-28 16:51:06.476 [vent.ItemStateChangedEvent] - dItem_0057_0001 changed from 13256 to 13309

Note, on the rasperry it is much more behind and on the faster pc I have already seen a counter arriving after 1000 seconds!

Is this a general performance problem or an issue with the binding (we use modbus 2 binding alpha)?

Details:

The configuration of the items is like:

Number dItem_0001_0001 “dItem_0001_0001” (dGroup_1) {channel=“modbus:data:gasanalyse:pull:ee702c24:number”}
Number dItem_0002_0001 “dItem_0002_0001” (dGroup_1) {channel=“modbus:data:gasanalyse:pull:d8fb32c8:number”}
Number dItem_0003_0001 “dItem_0003_0001” (dGroup_1) {channel=“modbus:data:gasanalyse:pull:221179bc:number”}

The configuration of the things is like:

Bridge modbus:tcp:gasanalyse [ host =“192.168.0.49”, port=502, id=1 ] {
Bridge poller pull [ start=750, length=120, type=“holding”, refresh=1000 ] {
//created Things
Thing data ee702c24 “dummieThing_0001” [ readStart=“750”, readValueType=“int16” ]
Thing data d8fb32c8 “dummieThing_0002” [ readStart=“751”, readValueType=“int16” ]
Thing data 221179bc “dummieThing_0003” [ readStart=“752”, readValueType=“int16” ]
Thing data 476e856f “dummieThing_0004” [ readStart=“753”, readValueType=“int16” ]
Thing data cae6c01e “dummieThing_0005” [ readStart=“754”, readValueType=“int16” ]

There are 120 modbus registers transferred per second and each second 240 items have to be checked. It seems that the threads cannot catch up. If the polling time or the number is made smaller and if the threads can catch up, it is quite fast.

It appears as if there are many threads trying to write data to the item and that the threads are waiting and are selected randomly. Therefore it can happen, that a newer value is written first and a much older value overwrites the newer value.

2

There are people who run systems with many more Items and Things than this using other bindings so I don’t think the problem is with the core. But it’s it is, you can increase the number of the the thingHandler and safeCall thread pools.

Edit conf/services/runtime.cfg and add

org.eclipse.smarthome.threadpool:thingHandler=5
org.eclipse.smarthome.threadpool:discovery=5
org.eclipse.smarthome.threadpool:safeCall=10
org.eclipse.smarthome.threadpool:ruleEngine=5

Where conf on an installed OH is /etc/openhab2.

The numbers shown after the defaults.

If you are using rules already, you will probably need to up the ruleEngine threads as well.

This will consume more ram so don’t go too big with three numbers on the RPi.

If anything these do not address the problem, the problem is likely in the binding itself.

3

I think @sipvoip is the fellow with experience of large Modbus networks in OH2.

I note you are using Modbus-TCP, I seem to recall there are performance impacts associated with the choice of reconnect TCP connections each time, or keeping it open. The ‘best’ choice depends on the behaviour of your Modbus slaves.

That seems unlikely to change the processing order of data packets though.

I wonder, if you are able to set your two “test” slave counter registers to different values, if it might offer a clue.

I also note your poller length of 120 is getting close to maximum for Modbus. It ought to work! But again it might offer a clue if you try with two pollers of smaller chunks. Might make it worse - that’s still a clue.

(I have a network of 8 slaves, 100 Items, polling at 800mS intervals running well. But it’s still OH1 for now)

4

openHAB should not have any problem with that. I currently have 134 things over a bunch of devices sampled at 100 ms. Not sure if this helps, but this is my modbus.things

Bridge modbus:tcp:water [ host="10.88.64.45", reconnectAfterMillis=600000, connectTimeoutMillis=1200, id=1 ] {
  Bridge poller coils [ start=0, length=55, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
  }
}

Bridge modbus:tcp:basement [ host="10.88.64.46", reconnectAfterMillis=600000, connectTimeoutMillis=1200, id=2 ] {
  Bridge poller coils [ start=0, length=55, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]
    Thing data 08 [ readStart="8", readValueType="bit", writeStart="8", writeValueType="bit", writeType="coil" ]
    Thing data 09 [ readStart="9", readValueType="bit", writeStart="9", writeValueType="bit", writeType="coil" ]
    Thing data 10 [ readStart="10", readValueType="bit", writeStart="10", writeValueType="bit", writeType="coil" ]
    Thing data 11 [ readStart="11", readValueType="bit", writeStart="11", writeValueType="bit", writeType="coil" ]
    Thing data 12 [ readStart="12", readValueType="bit", writeStart="13", writeValueType="bit", writeType="coil" ]
    Thing data 13 [ readStart="13", readValueType="bit", writeStart="14", writeValueType="bit", writeType="coil" ]
    Thing data 14 [ readStart="14", readValueType="bit", writeStart="14", writeValueType="bit", writeType="coil" ]
    Thing data 15 [ readStart="15", readValueType="bit", writeStart="15", writeValueType="bit", writeType="coil" ]
    Thing data 16 [ readStart="16", readValueType="bit", writeStart="16", writeValueType="bit", writeType="coil" ]
    Thing data 17 [ readStart="17", readValueType="bit", writeStart="17", writeValueType="bit", writeType="coil" ]
    Thing data 18 [ readStart="18", readValueType="bit", writeStart="18", writeValueType="bit", writeType="coil" ]
    Thing data 29 [ readStart="19", readValueType="bit", writeStart="19", writeValueType="bit", writeType="coil" ]
    Thing data 20 [ readStart="20", readValueType="bit", writeStart="20", writeValueType="bit", writeType="coil" ]
    Thing data 21 [ readStart="21", readValueType="bit", writeStart="21", writeValueType="bit", writeType="coil" ]
    Thing data 49 [ readStart="49", readValueType="bit", writeStart="49", writeValueType="bit", writeType="coil" ]
    Thing data 50 [ readStart="50", readValueType="bit", writeStart="50", writeValueType="bit", writeType="coil" ]
    Thing data 51 [ readStart="51", readValueType="bit", writeStart="51", writeValueType="bit", writeType="coil" ]
    Thing data 52 [ readStart="52", readValueType="bit", writeStart="52", writeValueType="bit", writeType="coil" ]
    Thing data 53 [ readStart="53", readValueType="bit", writeStart="53", writeValueType="bit", writeType="coil" ]
  }
  Bridge poller ponet [ start=2072, length=8, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="2072", readValueType="bit", writeStart="2072", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="2073", readValueType="bit", writeStart="2073", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2074", readValueType="bit", writeStart="2074", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="2075", readValueType="bit", writeStart="2075", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="2076", readValueType="bit", writeStart="2076", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="2077", readValueType="bit", writeStart="2077", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="2078", readValueType="bit", writeStart="2078", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="2079", readValueType="bit", writeStart="2079", writeValueType="bit", writeType="coil" ]
  }
}

Bridge modbus:tcp:first [ host="10.88.64.47", reconnectAfterMillis=600000, connectTimeoutMillis=1200, id=3 ] {
  Bridge poller coils [ start=0, length=55, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]
    Thing data 08 [ readStart="8", readValueType="bit", writeStart="8", writeValueType="bit", writeType="coil" ]
    Thing data 09 [ readStart="9", readValueType="bit", writeStart="9", writeValueType="bit", writeType="coil" ]
    Thing data 10 [ readStart="10", readValueType="bit", writeStart="10", writeValueType="bit", writeType="coil" ]
    Thing data 11 [ readStart="11", readValueType="bit", writeStart="11", writeValueType="bit", writeType="coil" ]
    Thing data 12 [ readStart="12", readValueType="bit", writeStart="13", writeValueType="bit", writeType="coil" ]
    Thing data 13 [ readStart="13", readValueType="bit", writeStart="14", writeValueType="bit", writeType="coil" ]
    Thing data 14 [ readStart="14", readValueType="bit", writeStart="14", writeValueType="bit", writeType="coil" ]
    Thing data 15 [ readStart="15", readValueType="bit", writeStart="15", writeValueType="bit", writeType="coil" ]
    Thing data 16 [ readStart="16", readValueType="bit", writeStart="16", writeValueType="bit", writeType="coil" ]
    Thing data 17 [ readStart="17", readValueType="bit", writeStart="17", writeValueType="bit", writeType="coil" ]
    Thing data 18 [ readStart="18", readValueType="bit", writeStart="18", writeValueType="bit", writeType="coil" ]
    Thing data 29 [ readStart="19", readValueType="bit", writeStart="19", writeValueType="bit", writeType="coil" ]
    Thing data 20 [ readStart="20", readValueType="bit", writeStart="20", writeValueType="bit", writeType="coil" ]
    Thing data 21 [ readStart="21", readValueType="bit", writeStart="21", writeValueType="bit", writeType="coil" ]
    Thing data 22 [ readStart="22", readValueType="bit", writeStart="22", writeValueType="bit", writeType="coil" ]
    Thing data 23 [ readStart="23", readValueType="bit", writeStart="23", writeValueType="bit", writeType="coil" ]
    Thing data 24 [ readStart="24", readValueType="bit", writeStart="24", writeValueType="bit", writeType="coil" ]
    Thing data 25 [ readStart="25", readValueType="bit", writeStart="25", writeValueType="bit", writeType="coil" ]
    Thing data 26 [ readStart="26", readValueType="bit", writeStart="26", writeValueType="bit", writeType="coil" ]
  }
  Bridge poller ponet [ start=2072, length=8, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="2072", readValueType="bit", writeStart="2072", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="2073", readValueType="bit", writeStart="2073", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2074", readValueType="bit", writeStart="2074", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="2075", readValueType="bit", writeStart="2075", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="2076", readValueType="bit", writeStart="2076", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="2077", readValueType="bit", writeStart="2077", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="2078", readValueType="bit", writeStart="2078", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="2079", readValueType="bit", writeStart="2079", writeValueType="bit", writeType="coil" ]
  }
}

Bridge modbus:tcp:second [ host="10.88.64.48", reconnectAfterMillis=600000, connectTimeoutMillis=1200, id=4 ] {
  Bridge poller coils [ start=0, length=55, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]
    Thing data 08 [ readStart="8", readValueType="bit", writeStart="8", writeValueType="bit", writeType="coil" ]
    Thing data 09 [ readStart="9", readValueType="bit", writeStart="9", writeValueType="bit", writeType="coil" ]
    Thing data 10 [ readStart="10", readValueType="bit", writeStart="10", writeValueType="bit", writeType="coil" ]
    Thing data 11 [ readStart="11", readValueType="bit", writeStart="11", writeValueType="bit", writeType="coil" ]
    Thing data 12 [ readStart="12", readValueType="bit", writeStart="13", writeValueType="bit", writeType="coil" ]
    Thing data 13 [ readStart="13", readValueType="bit", writeStart="14", writeValueType="bit", writeType="coil" ]
    Thing data 14 [ readStart="14", readValueType="bit", writeStart="14", writeValueType="bit", writeType="coil" ]
    Thing data 15 [ readStart="15", readValueType="bit", writeStart="15", writeValueType="bit", writeType="coil" ]
    Thing data 16 [ readStart="16", readValueType="bit", writeStart="16", writeValueType="bit", writeType="coil" ]
    Thing data 17 [ readStart="17", readValueType="bit", writeStart="17", writeValueType="bit", writeType="coil" ]
    Thing data 18 [ readStart="18", readValueType="bit", writeStart="18", writeValueType="bit", writeType="coil" ]
    Thing data 19 [ readStart="19", readValueType="bit", writeStart="19", writeValueType="bit", writeType="coil" ]
    Thing data 20 [ readStart="20", readValueType="bit", writeStart="20", writeValueType="bit", writeType="coil" ]
    Thing data 21 [ readStart="21", readValueType="bit", writeStart="21", writeValueType="bit", writeType="coil" ]
    Thing data 22 [ readStart="22", readValueType="bit", writeStart="22", writeValueType="bit", writeType="coil" ]
    Thing data 23 [ readStart="23", readValueType="bit", writeStart="23", writeValueType="bit", writeType="coil" ]
    Thing data 24 [ readStart="24", readValueType="bit", writeStart="24", writeValueType="bit", writeType="coil" ]
    Thing data 25 [ readStart="25", readValueType="bit", writeStart="25", writeValueType="bit", writeType="coil" ]
    Thing data 26 [ readStart="26", readValueType="bit", writeStart="26", writeValueType="bit", writeType="coil" ]
    Thing data 27 [ readStart="27", readValueType="bit", writeStart="27", writeValueType="bit", writeType="coil" ]
    Thing data 28 [ readStart="28", readValueType="bit", writeStart="28", writeValueType="bit", writeType="coil" ]
    Thing data 29 [ readStart="29", readValueType="bit", writeStart="29", writeValueType="bit", writeType="coil" ]
    Thing data 30 [ readStart="30", readValueType="bit", writeStart="30", writeValueType="bit", writeType="coil" ]
    Thing data 31 [ readStart="31", readValueType="bit", writeStart="31", writeValueType="bit", writeType="coil" ]
    Thing data 32 [ readStart="32", readValueType="bit", writeStart="32", writeValueType="bit", writeType="coil" ]
    Thing data 51 [ readStart="51", readValueType="bit", writeStart="51", writeValueType="bit", writeType="coil" ]
    Thing data 52 [ readStart="52", readValueType="bit", writeStart="52", writeValueType="bit", writeType="coil" ]
  }
  Bridge poller ponet [ start=2072, length=8, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="2072", readValueType="bit", writeStart="2072", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="2073", readValueType="bit", writeStart="2073", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2074", readValueType="bit", writeStart="2074", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="2075", readValueType="bit", writeStart="2075", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="2076", readValueType="bit", writeStart="2076", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="2077", readValueType="bit", writeStart="2077", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="2078", readValueType="bit", writeStart="2078", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="2079", readValueType="bit", writeStart="2079", writeValueType="bit", writeType="coil" ]
  }
}

Bridge modbus:tcp:shed [ host="10.88.64.49", reconnectAfterMillis=600000, connectTimeoutMillis=1200, id=5 ] {
  Bridge poller coils [ start=0, length=55, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="0", readValueType="bit", writeStart="0", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="1", readValueType="bit", writeStart="1", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2", readValueType="bit", writeStart="2", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="3", readValueType="bit", writeStart="3", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="4", readValueType="bit", writeStart="4", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="5", readValueType="bit", writeStart="5", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="6", readValueType="bit", writeStart="6", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="7", readValueType="bit", writeStart="7", writeValueType="bit", writeType="coil" ]
    Thing data 08 [ readStart="8", readValueType="bit", writeStart="8", writeValueType="bit", writeType="coil" ]
    Thing data 09 [ readStart="9", readValueType="bit", writeStart="9", writeValueType="bit", writeType="coil" ]
    Thing data 10 [ readStart="10", readValueType="bit", writeStart="10", writeValueType="bit", writeType="coil" ]
  }
  Bridge poller ponet [ start=2072, length=8, refresh=100, type="coil" ] {
    Thing data 00 [ readStart="2072", readValueType="bit", writeStart="2072", writeValueType="bit", writeType="coil" ]
    Thing data 01 [ readStart="2073", readValueType="bit", writeStart="2073", writeValueType="bit", writeType="coil" ]
    Thing data 02 [ readStart="2074", readValueType="bit", writeStart="2074", writeValueType="bit", writeType="coil" ]
    Thing data 03 [ readStart="2075", readValueType="bit", writeStart="2075", writeValueType="bit", writeType="coil" ]
    Thing data 04 [ readStart="2076", readValueType="bit", writeStart="2076", writeValueType="bit", writeType="coil" ]
    Thing data 05 [ readStart="2077", readValueType="bit", writeStart="2077", writeValueType="bit", writeType="coil" ]
    Thing data 06 [ readStart="2078", readValueType="bit", writeStart="2078", writeValueType="bit", writeType="coil" ]
    Thing data 07 [ readStart="2079", readValueType="bit", writeStart="2079", writeValueType="bit", writeType="coil" ]
  }
}
5

Sorry for the Off-Topic question in this thread but what exactly is the meaning of these parameters? Is there any documentation? Thank you!

6

Here:

1 Like
7

Hmm, we have seen more than 100 threads, there seems to be one thread for each of the 120 things (channels). Above, I read …threadpool::thingHandler=5. Is this number the number of threads which are started at the beginning or can the maximum number of threads be higher? Or are the seen threads independent from thingHandler?

8

Your config seems similar but we are just using registers (words) instead of coils (bits) for testing purposes.

Later, there would be 60 wago io couplers, the total number of digital inputs would be several thousands. This is quite a huge number. But the number of events is of course much lower. We made some tests with rules and there the performance looked good.

If the modbus performance is not good enough, it would also be possible to write a binding which reads bits from shared memory on the same computer instead. I could also run 60 seperate processes where each reads from one wago bus coupler and writes the data into the shared memory.

I think the most speed critical would be, how long it takes until openhab can scan for example 5000 digital inputs. As it is expected that only few will change at a certain time, the following steps seem not to be as critical.

We made also some speed tests with modbus/tcp and mqtt/json, see next reply.

9

I think this should not have been the problem, because there was only 1 request per second at the modbus tcp slave. At the same time I could make another 40 modbus requests by the use of 2 other modbus masters.

We have also tested where one modbus register was transferred to an item 1, a rule set the value of item 2 which was transferred to mqtt (json formate), an item 3 got the mqtt value again and a rule set the value of item 4, where the value was transferred via modbus, the value came back via modbus to item 5 and so on until 12 items (6 modbus and 6 mqtt connetions). Openhab was on rasperry pi and the modbus slave (self programmed) and the mqtt broker (mosquitto) where running on an ARM Cortex A9 (which has similar performance like a rasperry pi 1). This all togehter took 0.2 seconds, including the network.

10

Has anybody an idea if there is already a binding which is very fast and which could be used in order to test?

We could test with mqtt, but normally I would expect that mqtt is much slower than modbus/tcp. Fastest would be shared memory or just a dummy binding wich returns a constant. Is there one?

11

Hum, I do not think the Modbus implementation works like that here. In keeping with Modbus’ history (originating as a shared serial bus) it waits for each poll query/response to complete (or fail) before executing the next one.

If considering some multimaster setup, you should bear in mind that some Modbus-TCP slaves only support one TCP connection at a time. This may lead into TCP disconnect/reconnect overheads I’ve already hinted at.

I think truly, we’re trying to say that what you propose should work. It’d be worth doing some more diagnostic work before adding complexity to try and get around it.
At the very least, simplify to find out what works. Shorter lengths? Reduced poll rate?

There is a very long running thread by @ssalonen which includes how-to get extra debugging info

12

Wait … do you mean you are hitting the slaves from other Masters at the same time as OpenHAB?

13

Yes and no - it makes no difference. The modbus slave opens a new thread for each new socket communication.
%

14

My collegue Felix is doing most of the tests and he is also reading here but might not be registered yet. I will not be available until monday.

15

Sounds like you might be suffering from the issue explained in this post

What do you think? Do you get warnings logged because of large queue size?

Best,
Sami

16

Yes, I think this could be the problem. My collegue will provide more details later. On the raspberry there were errors logged about lost events or so and a size of 560 queue size, events or threads, I cannot remember exactly. Sometimes the system can catch up.and from this time on there is no delay anymore at least on the faster pc.
It seems that there are no counter values lost but the values arrive randomly at the item.

17

Please try out with the new version, for more details, see this post: Modbus openHAB2 binding available for alpha testing

Sami

18

Hey, so I can now provide some additional information.

The following applies to the RaspberryPi setup.
I did upgrade to the newest version of the binding (2.4.0.201806291551 that is, I hope).
I reduced the number of items to 1 per thing, just for now.
Started the Server with 120 things and items, letting it run for about 30 min.
Here is the logfile for these 30 min: openhab.log (json, google drive)

The first 20 items did get initialized, but the 100 others didn’t. The amount of tasks in the callbackThreadPool was at 2200.

CPU usage is at about 10-15%, Memory at about 20%
So that’s very different from what we experienced before, where the CPU usage would always go up to 350% to 400% but the callbackThreadPool would consist of 500-600 tasks, after 30 min.

I will do additional testing with the tips @rlkoshak provided and keep you updated.
Also there is gonna be testing on the number of items per poll affecting the behaviour.

Felix

19

@awiflx, I can confirm that you are using the latest binding.

The caching is mostly applied since the REFRESH commands come more than 50ms (the default) apart:

$ grep 'received refresh() but the cache is not applicable. Polling new data' ~/Downloads/openhab.txt|wc -l
201
$ grep 'cache was recent enough (age at most 50 ms). Reusing old response' ~/Downloads/openhab.txt|wc -l
37

Also, the overall number of REFRESH does not explain the large queue – only 201 poll tasks are queued this way

$ grep 'Scheduling one-off poll' ~/Downloads/openhab.txt|wc -l
201

So it must be something else :thinking:

I don’t see any log messages from the binding, are you sure you have configured the logging as explained in the logs: Enable verbose logging?

Please

  • ensure log configuratoin
  • also enable org.eclipse.smarthome.core.common.QueueingThreadPoolExecutor
  • share item and thing definitions (I can try to reproduce)

Best,
Sami

20

@ssalonen, allright i will try and go through that step by step.
First off, thank you for taking the time and being so patient about this.

I got the logging configured like this in the org.ops4j.pax.logging.cfg
(i did this through karaf with: log:set TRACE org.openhab.binding.modbus - all others according to this)

#Modbus logger
log4j2.logger.org_openhab_binding_modbus.level = TRACE
log4j2.logger.org_openhab_binding_modbus.name = org.openhab.binding.modbus
log4j2.logger.org_openhab_io_transport_modbus.level = TRACE
log4j2.logger.org_openhab_io_transport_modbus.name = org.openhab.io.transport.modbus
log4j2.logger.net_wimpi_modbus.level = TRACE
log4j2.logger.net_wimpi_modbus.name = net.wimpi.modbus
log4j2.logger.org_eclipse_smarthome_core_common_queueingthreadpoolexecutor.level = TRACE
log4j2.logger.org_eclipse_smarthome_core_common_queueingthreadpoolexecutor.name = org.eclipse.smarthome.core.common.QueueingThreadPoolExecutor

The definitions are like this:
dThing.json (10.0 KB)
dItem.json (14.1 KB)
and are created through a bash-script

I will now run the test again and post you the log file received.
Guess 10 to 15 min should be enough time?

Felix

Edit:
Tasks at ~900
CPU at 10-15%, Mem at 15-20%, Active threads at 5
Here is the log
openhab.log
And that’s what it looked like in PaperUIs Control

paperui_control
paperui_control.png1409×931 66 KB