I would at least try with all polling extended to 100 or 200mS, give your write command a chance to get in the modbus queue.
EDIT - muddled up messages, but this advice should still be sensible for @Rado1
1 Like
@Pe_Man could you please adjust the logging as described in the docs: https://www.openhab.org/addons/bindings/modbus/#enable-verbose-logging
I think we are missing the transport level logging.
Sami
Thanks @Rado1, now the logging is correctly configured.
I can see that one round of polling takes around 120 ms:
$ grep timing /tmp/rado1logs
2018-12-26 19:34:00.114 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 131 ms, connection: 103, transaction=12, callback=6} [operation ID 5075f19c-8d93-4406-9767-83bc88486505]
2018-12-26 19:34:00.178 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 117 ms, connection: 88, transaction=11, callback=7} [operation ID 9cfe136d-64f2-492a-9016-0591fd2a6139]
2018-12-26 19:34:00.242 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 115 ms, connection: 88, transaction=12, callback=7} [operation ID 676c6ec8-8e5a-4d53-96c4-381d9408b088]
2018-12-26 19:34:00.306 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 115 ms, connection: 86, transaction=12, callback=9} [operation ID b03de9ba-0686-46d6-aa11-aabdc9d1d364]
2018-12-26 19:34:00.369 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 114 ms, connection: 88, transaction=10, callback=7} [operation ID 1e2e50d0-0adc-4956-8b1b-4cea8293452e]
2018-12-26 19:34:00.431 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 112 ms, connection: 85, transaction=13, callback=6} [operation ID 67bbd000-4bf9-461b-bf0a-d3bf8763a4e6]
2018-12-26 19:34:00.496 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 114 ms, connection: 87, transaction=13, callback=5} [operation ID 50747201-db03-45ef-888d-95d6bce5e313]
Most of the time goes to connection related things (see above). One reason might be that poll period is 10 ms but default period between transactions is 35 ms. We can see that binding is artificially waiting between polls to ensure the silent period.
$ grep Waited /tmp/rado1logs
2018-12-26 19:34:00.143 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 32ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.208 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.272 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.337 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.400 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.462 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@462ebe57[portName=/dev/ttyUSB0], to ensure delay between transactions.
2018-12-26 19:34:00.527 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 33ms (interTransactionDelayMillis 35ms) before giving returning connection SerialConnection@7c7a5c98[portName=/dev/ttyUSB0,port=/dev/ttyUSB0] for endpoint ModbusSerialSlaveEndpoint@6fcec663[portName=/dev/ttyUSB0], to ensure delay between transactions.
It’s quite interesting that you see high CPU consumption… After all, you just have two pollers (that are automatically refreshed), not 100+ as discussed this thread.
UPDATE: please note that the logging increases CPU usage quite heavily. Tune down the logging to increase performance.
Would you please share the modbus1 configuration you had? Also, could you repeat the log collection for a longer time span, say 30 seconds – I would then see the queue statistics.
Best,
Sami
I use 1000ms for read/write registers and 10000ms for read only. You probably meant to quote Rado1?
ok, sorry for the inconvenience.
Same test today, but with loggings correctly set.
2018-12-27 11:06:32.854 [ome.event.ItemCommandEvent] - Item 'Sovrum_4__Kontor__Ljusfunktion_Tak_Status' received command ON
2018-12-27 11:06:32.869 [nt.ItemStatePredictedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status predicted to become ON
2018-12-27 11:06:32.874 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON
2018-12-27 11:06:34.486 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from ON to OFF
2018-12-27 11:06:48.110 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON
I put the extract of the openhab.log here: https://www.dropbox.com/s/j307w03z9fp7y6e/openhab.log%20(modbus-debug)?dl=0
It was to large for pastebin…
Thanks @Pe_Man
I can see that majority of the time goes to connections:
$ grep timing peman.log
2018-12-27 11:06:32.802 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 555 ms, connection: 480, transaction=7, callback=21} [operation ID 1954a600-2a42-44fd-b42a-797da1ec58c8]
2018-12-27 11:06:32.914 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 546 ms, connection: 492, transaction=13, callback=14} [operation ID 6c2d7d70-585b-430e-aae6-60928ae29458]
2018-12-27 11:06:33.019 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 560 ms, connection: 512, transaction=20, callback=11} [operation ID 8e3b10f0-634b-4044-9aba-6c4caf1a98fc]
2018-12-27 11:06:33.107 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 531 ms, connection: 502, transaction=7, callback=10} [operation ID 4e931edf-fad8-4d63-9311-cf91358ceb94]
2018-12-27 11:06:33.209 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 531 ms, connection: 493, transaction=18, callback=9} [operation ID e0d5cdff-314e-4d31-b9f8-63b1cd00f54d]
2018-12-27 11:06:33.336 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 528 ms, connection: 465, transaction=34, callback=10} [operation ID d45e3e18-e915-4290-b854-96fbe1f95bb1]
(for reference, explanation of the different categories:
- connection: time spent waiting for the turn to get the connection (has to wait other requests to complete), establishing the connection, disconnecting connection
- transaction: actual modbus protocol level I/O
- callback: time spent “processing” the received data and updating channels and items
)
I think this might be because there are so many pollers competing for time with the slave. Anyways, it might be a good idea to keep the connection open (see reconnectAfterMillis parameter).
You can also see from above that it takes ~550 ms to complete one transaction, which translates to 73 seconds to poll all the 133 slaves!
There 133 pollers which shows up in queue size (130 requests queued). In other words, the queue is full of poll tasks. (queue size used to increase without limit in cases like this before – now it’s contained which is good)
# Sorting queue by poll start
$ grep 'POLL MONITOR:' peman.log|sort --general-numeric-sort --key=14|cut -d' ' -f12-14
READ_MULTIPLE_REGISTERS, start 0,
READ_MULTIPLE_REGISTERS, start 38,
READ_MULTIPLE_REGISTERS, start 76,
READ_MULTIPLE_REGISTERS, start 114,
READ_MULTIPLE_REGISTERS, start 141,
READ_INPUT_REGISTERS, start 162,
READ_MULTIPLE_REGISTERS, start 176,
READ_MULTIPLE_REGISTERS, start 272,
READ_MULTIPLE_REGISTERS, start 349,
READ_MULTIPLE_REGISTERS, start 487,
READ_MULTIPLE_REGISTERS, start 525,
READ_MULTIPLE_REGISTERS, start 587,
READ_MULTIPLE_REGISTERS, start 625,
READ_MULTIPLE_REGISTERS, start 663,
READ_MULTIPLE_REGISTERS, start 701,
READ_MULTIPLE_REGISTERS, start 739,
READ_MULTIPLE_REGISTERS, start 777,
READ_INPUT_REGISTERS, start 808,
READ_MULTIPLE_REGISTERS, start 842,
READ_MULTIPLE_REGISTERS, start 880,
READ_MULTIPLE_REGISTERS, start 918,
READ_MULTIPLE_REGISTERS, start 983,
READ_MULTIPLE_REGISTERS, start 1079,
READ_MULTIPLE_REGISTERS, start 1209,
READ_MULTIPLE_REGISTERS, start 1247,
READ_MULTIPLE_REGISTERS, start 1285,
READ_MULTIPLE_REGISTERS, start 1323,
READ_MULTIPLE_REGISTERS, start 1361,
READ_MULTIPLE_REGISTERS, start 1399,
READ_MULTIPLE_REGISTERS, start 1437,
READ_MULTIPLE_REGISTERS, start 1475,
READ_MULTIPLE_REGISTERS, start 1552,
READ_MULTIPLE_REGISTERS, start 1590,
READ_MULTIPLE_REGISTERS, start 1628,
READ_MULTIPLE_REGISTERS, start 1666,
READ_MULTIPLE_REGISTERS, start 1704,
READ_MULTIPLE_REGISTERS, start 1742,
READ_MULTIPLE_REGISTERS, start 1780,
READ_MULTIPLE_REGISTERS, start 1818,
READ_MULTIPLE_REGISTERS, start 1856,
READ_MULTIPLE_REGISTERS, start 1894,
READ_MULTIPLE_REGISTERS, start 1932,
READ_MULTIPLE_REGISTERS, start 1970,
READ_MULTIPLE_REGISTERS, start 2042,
READ_INPUT_REGISTERS, start 2089,
READ_MULTIPLE_REGISTERS, start 2135,
READ_INPUT_REGISTERS, start 2169,
READ_INPUT_REGISTERS, start 2249,
READ_MULTIPLE_REGISTERS, start 2254,
READ_INPUT_REGISTERS, start 2329,
READ_MULTIPLE_REGISTERS, start 2567,
READ_MULTIPLE_REGISTERS, start 2663,
READ_INPUT_REGISTERS, start 2702,
READ_MULTIPLE_REGISTERS, start 2759,
READ_MULTIPLE_REGISTERS, start 2855,
READ_MULTIPLE_REGISTERS, start 2975,
READ_MULTIPLE_REGISTERS, start 3052,
READ_MULTIPLE_REGISTERS, start 3129,
READ_MULTIPLE_REGISTERS, start 3291,
READ_MULTIPLE_REGISTERS, start 3318,
READ_MULTIPLE_REGISTERS, start 3356,
READ_INPUT_REGISTERS, start 3356,
READ_INPUT_REGISTERS, start 3436,
READ_MULTIPLE_REGISTERS, start 3466,
READ_MULTIPLE_REGISTERS, start 3504,
READ_INPUT_REGISTERS, start 3950,
READ_MULTIPLE_REGISTERS, start 4005,
READ_MULTIPLE_REGISTERS, start 4043,
READ_MULTIPLE_REGISTERS, start 4097,
READ_MULTIPLE_REGISTERS, start 4234,
READ_MULTIPLE_REGISTERS, start 4330,
READ_INPUT_REGISTERS, start 4850,
READ_INPUT_REGISTERS, start 4955,
READ_MULTIPLE_REGISTERS, start 5088,
READ_MULTIPLE_REGISTERS, start 5285,
READ_MULTIPLE_REGISTERS, start 5362,
READ_MULTIPLE_REGISTERS, start 5439,
READ_MULTIPLE_REGISTERS, start 5516,
READ_MULTIPLE_REGISTERS, start 5593,
READ_MULTIPLE_REGISTERS, start 5757,
READ_MULTIPLE_REGISTERS, start 5898,
READ_MULTIPLE_REGISTERS, start 5936,
READ_MULTIPLE_REGISTERS, start 5974,
READ_MULTIPLE_REGISTERS, start 6012,
READ_MULTIPLE_REGISTERS, start 6131,
READ_MULTIPLE_REGISTERS, start 6208,
READ_MULTIPLE_REGISTERS, start 6246,
READ_MULTIPLE_REGISTERS, start 6307,
READ_MULTIPLE_REGISTERS, start 6345,
READ_MULTIPLE_REGISTERS, start 6468,
READ_INPUT_REGISTERS, start 7427,
READ_MULTIPLE_REGISTERS, start 10202,
READ_MULTIPLE_REGISTERS, start 10387,
READ_MULTIPLE_REGISTERS, start 10478,
READ_MULTIPLE_REGISTERS, start 11223,
READ_MULTIPLE_REGISTERS, start 11301,
READ_MULTIPLE_REGISTERS, start 11339,
READ_MULTIPLE_REGISTERS, start 11377,
READ_MULTIPLE_REGISTERS, start 11415,
READ_MULTIPLE_REGISTERS, start 11453,
READ_MULTIPLE_REGISTERS, start 11491,
READ_MULTIPLE_REGISTERS, start 11572,
READ_MULTIPLE_REGISTERS, start 11649,
READ_MULTIPLE_REGISTERS, start 11687,
READ_MULTIPLE_REGISTERS, start 11725,
READ_MULTIPLE_REGISTERS, start 11763,
READ_MULTIPLE_REGISTERS, start 12013,
READ_MULTIPLE_REGISTERS, start 12051,
READ_MULTIPLE_REGISTERS, start 12089,
READ_MULTIPLE_REGISTERS, start 12127,
READ_INPUT_REGISTERS, start 12536,
READ_MULTIPLE_REGISTERS, start 13024,
READ_MULTIPLE_REGISTERS, start 13088,
READ_MULTIPLE_REGISTERS, start 13188,
READ_MULTIPLE_REGISTERS, start 13270,
READ_MULTIPLE_REGISTERS, start 13332,
READ_MULTIPLE_REGISTERS, start 13358,
READ_MULTIPLE_REGISTERS, start 13384,
READ_MULTIPLE_REGISTERS, start 13410,
READ_MULTIPLE_REGISTERS, start 13436,
READ_MULTIPLE_REGISTERS, start 13462,
READ_MULTIPLE_REGISTERS, start 13514,
READ_MULTIPLE_REGISTERS, start 13540,
READ_MULTIPLE_REGISTERS, start 13566,
READ_MULTIPLE_REGISTERS, start 13638,
READ_MULTIPLE_REGISTERS, start 13754,
READ_MULTIPLE_REGISTERS, start 13780,
READ_MULTIPLE_REGISTERS, start 13806,
READ_MULTIPLE_REGISTERS, start 13832,
READ_MULTIPLE_REGISTERS, start 13858,
READ_MULTIPLE_REGISTERS, start 13884,
READ_MULTIPLE_REGISTERS, start 13910,
READ_MULTIPLE_REGISTERS, start 13936,
We can also evaluate how long the tasks are in the queue
$ grep 'POLL MONITOR:' peman.log|grep -o -E 'delay: -?[[:digit:]]+'|sort --general-numeric-sort --key 2
delay: -12510
delay: -12268
delay: -12213
delay: -12211
delay: -12135
delay: -11986
delay: -11919
delay: -11723
delay: -11650
delay: -11444
delay: -11375
delay: -11250
delay: -11182
delay: -11115
delay: -11096
delay: -10765
delay: -10688
delay: -10676
delay: -10565
delay: -10425
delay: -10339
delay: -10139
delay: -10018
delay: -9980
delay: -9938
delay: -9879
delay: -9719
delay: -9558
delay: -9461
delay: -9372
delay: -9193
delay: -9103
delay: -8929
delay: -8903
delay: -8895
delay: -8504
delay: -8436
delay: -8244
delay: -8242
delay: -8188
delay: -8076
delay: -8001
delay: -7829
delay: -7779
delay: -7737
delay: -7650
delay: -7536
delay: -7498
delay: -7180
delay: -7179
delay: -7129
delay: -7060
delay: -6919
delay: -6720
delay: -6689
delay: -6633
delay: -6562
delay: -6562
delay: -6293
delay: -6176
delay: -6164
delay: -6141
delay: -6063
delay: -5939
delay: -5727
delay: -5688
delay: -5673
delay: -5536
delay: -5496
delay: -5473
delay: -4726
delay: -4395
delay: -4195
delay: -3979
delay: -3884
delay: -3811
delay: -3702
delay: -3619
delay: -3509
delay: -3297
delay: -3174
delay: -2967
delay: -2960
delay: -2714
delay: -2697
delay: -2561
delay: -2476
delay: -2472
delay: -2396
delay: -2070
delay: -1963
delay: -1950
delay: -1756
delay: -1660
delay: -1555
delay: -1305
delay: -1157
delay: -1114
delay: -973
delay: -755
delay: -734
delay: -591
delay: -585
delay: -446
delay: -329
delay: -233
delay: -74
delay: -74
delay: 124
delay: 295
delay: 336
delay: 375
delay: 613
delay: 719
delay: 848
delay: 936
delay: 974
delay: 1575
delay: 2006
delay: 2778
delay: 3303
delay: 4844
delay: 5295
delay: 5382
delay: 5768
delay: 6183
delay: 6328
delay: 6761
delay: 7356
delay: 7734
delay: 8673
delay: 9130
delay: 9539
Negative values mean that the poll task has missed it’s scheduled poll time (e.g. 10 s) by that many milliseconds. Positive values mean that scheduled poll time is still in the future. We can see many regular poll tasks are lagging behind the set poll rate.
The amount queued tasks probably explain why you are seeing a lag to when issuing commands to the slave (problem described in OP) – it takes a while before the corresponding data is refreshed from the modbus. I could not confirm this from the logs – there was no writes in the logs.
It is the writing I’d like to have higher pririty on, reading is not so critical.
Could you please adjust reconnectAfterMillis parameter of the tcp thing to 60000 (that is, 1 minute), and please report back.
Quite right, I muddled up there.
ok, changed the thing to 60000 like this
Bridge modbus:tcp:SH2WEB [ host="192.168.1.198", port=502, id=1 , reconnectAfterMillis=60000] {
I don’t see any change in responsetime after this.
replaced log-file: https://www.dropbox.com/s/j307w03z9fp7y6e/openhab.log%20(modbus-debug)?dl=0
2018-12-27 13:15:53.242 [ome.event.ItemCommandEvent] - Item 'Sovrum_4__Kontor__Ljusfunktion_Tak_Status' received command ON
2018-12-27 13:15:53.262 [nt.ItemStatePredictedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status predicted to become ON
2018-12-27 13:15:53.281 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON
2018-12-27 13:15:54.526 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from ON to OFF
2018-12-27 13:15:56.188 [hingStatusInfoChangedEvent] - 'sonos:PLAY3:RINCON_000E587E872A01400' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_000E587E872A01400 is not available in local network.
2018-12-27 13:15:56.304 [hingStatusInfoChangedEvent] - 'sonos:zoneplayer:RINCON_000E587E872A01400' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): The Sonos player RINCON_000E587E872A01400 is not available in local network.
2018-12-27 13:15:59.383 [vent.ItemStateChangedEvent] - Sovrum_1__Leo__Temperatur_Temperatur_rum changed from 22.5 to 22.6
2018-12-27 13:16:02.050 [vent.ItemStateChangedEvent] - K_k_Dimbart_ljus_K_kssk_p_Status changed from 0 to 25
2018-12-27 13:16:07.857 [vent.ItemStateChangedEvent] - Sovrum_4__Kontor__Ljusfunktion_Tak_Status changed from OFF to ON
I know it is fast but with the old binding i was polling 6 pollers at 1mS without any problem’s.If i pol slower i can not catch every puls the input gets.
With the old binding i was polling at 1mS for 6 pollers because i could not disabel the 4 coil pollers and i had no increase of cpu use.
This is my old config.
poll=1
modbus:serial.slave1.connection=/dev/ttyUSB0:38400:8:none:1:rtu:1
modbus:serial.slave1.id=1
modbus:serial.slave1.type=coil
modbus:serial.slave1.start=0
modbus:serial.slave1.length=8
modbus:serial.slave2.connection=/dev/ttyUSB0:38400:8:none:1:rtu:1
modbus:serial.slave2.id=2
modbus:serial.slave2.type=coil
modbus:serial.slave2.start=0
modbus:serial.slave2.length=8
modbus:serial.slave3.connection=/dev/ttyUSB0:38400:8:none:1:rtu:1
modbus:serial.slave3.id=3
modbus:serial.slave3.type=coil
modbus:serial.slave3.start=0
modbus:serial.slave3.length=8
modbus:serial.slave4.connection=/dev/ttyUSB0:38400:8:none:1:rtu:1
modbus:serial.slave4.id=4
modbus:serial.slave4.type=coil
modbus:serial.slave4.start=0
modbus:serial.slave4.length=8
modbus:serial.slave10.connection=/dev/ttyUSB2:38400:8:none:1:rtu:1
modbus:serial.slave10.id=10
modbus:serial.slave10.type=discrete
modbus:serial.slave10.start=0
modbus:serial.slave10.length=16
modbus:serial.slave11.connection=/dev/ttyUSB2:38400:8:none:1:rtu:1
modbus:serial.slave11.id=11
modbus:serial.slave11.type=discrete
modbus:serial.slave11.start=0
modbus:serial.slave11.length=16
Here is my item’s config
Group Verlichting <verlichting>
Switch keuken1 "keuken1" ["Lighting"] {modbus="slave1:0"}
Switch keuken2 "keuken2" ["Lighting"] {modbus="slave1:1"}
Switch keuken3 "keuken3" ["Lighting"] {modbus="slave1:2"}
Switch living1 "living1" ["Lighting"] {modbus="slave1:3"}
Switch living2 "living2" ["Lighting"] {modbus="slave1:4"}
Switch eetkamer1 "eetkamer1" ["Lighting"] {modbus="slave1:5"}
Switch eetkamer2 "eetkamer2" ["Lighting"] {modbus="slave1:6"}
Switch livingwand "livingwand" ["Lighting"] {modbus="slave1:7"}
Switch bureau "bureau" ["Lighting"] {modbus="slave2:0"}
Switch inkomhal "inkomhal" ["Lighting"] {modbus="slave3:6"}
Switch wasplaats "wasplaats" ["Lighting"] {modbus="slave2:2"}
Switch voordeur "voordeur" ["Lighting"] {modbus="slave2:3"}
Switch garage "garage" ["Lighting"] {modbus="slave2:4"}
Switch douche "douche" ["Lighting"] {modbus="slave2:5"}
Switch kelder "kelder" ["Lighting"] {modbus="slave2:6"}
Switch voor "voor" ["Lighting"] {modbus="slave2:7"}
Switch zijkant "zijkant" ["Lighting"] {modbus="slave3:0"}
Switch achter "achter" ["Lighting"] {modbus="slave3:1"}
Switch hal "hal" ["Lighting"]{modbus="slave3:2"}
Switch orientatie "orientatie" ["Lighting"] {modbus="slave3:3"}
Switch masterbedroom "masterbedroom" ["Lighting"] {modbus="slave3:4"}
Switch badkamer "badkamer" ["Lighting"] {modbus="slave3:5"}
Switch open1 "open1" {modbus="slave3:6"}
Switch open2 "open2" {modbus="slave3:7"}
Switch open3 "open3" {modbus="slave4:0"}
Switch open4 "open4" {modbus="slave4:1"}
Switch open5 "open5" {modbus="slave4:2"}
Switch open6 "open6" {modbus="slave4:3"}
Switch open7 "open7" {modbus="slave4:4"}
Switch open8 "open8" {modbus="slave4:5"}
Switch open9 "open9" {modbus="slave4:6"}
Switch open10 "open10" {modbus="slave4:7"}
Group Verlichtinginputs <verlichting>
Contact verlichting1 "verlichting1[MAP(en.map):%s]" {modbus="slave10:0"}
Contact verlichting2 "verlichting2[MAP(en.map):%s]" {modbus="slave10:1"}
Contact verlichting3 "verlichting3[MAP(en.map):%s]" {modbus="slave10:2"}
Contact verlichting4 "verlichting4[MAP(en.map):%s]" {modbus="slave10:3"}
Contact verlichting5 "verlichting5[MAP(en.map):%s]" {modbus="slave10:4"}
Contact verlichting6 "verlichting6[MAP(en.map):%s]" {modbus="slave10:7"}
Contact verlichting7 "verlichting7[MAP(en.map):%s]" {modbus="slave10:5"}
Contact verlichting8 "verlichting8[MAP(en.map):%s]" {modbus="slave10:6"}
Contact verlichting9 "verlichting9[MAP(en.map):%s]" {modbus="slave10:8"}
Contact verlichting10 "verlichting10[MAP(en.map):%s]" {modbus="slave10:9"}
Contact verlichting11 "verlichting11[MAP(en.map):%s]" {modbus="slave10:10"}
Contact verlichting12 "verlichting12[MAP(en.map):%s]" {modbus="slave10:11"}
Contact verlichting13 "verlichting13[MAP(en.map):%s]" {modbus="slave10:12"}
Contact verlichting14 "verlichting14[MAP(en.map):%s]" {modbus="slave10:13"}
Contact verlichting15 "verlichting15[MAP(en.map):%s]" {modbus="slave10:14"}
Contact verlichting16 "verlichting16[MAP(en.map):%s]" {modbus="slave10:15"}
Contact verlichting17 "verlichting17[MAP(en.map):%s]" {modbus="slave11:0"}
Contact verlichting18 "verlichting18[MAP(en.map):%s]" {modbus="slave11:1"}
Contact verlichting19 "verlichting19[MAP(en.map):%s]" {modbus="slave11:2"}
Contact verlichting20 "verlichting20[MAP(en.map):%s]" {modbus="slave11:3"}
Contact verlichting21 "verlichting21[MAP(en.map):%s]" {modbus="slave11:4"}
Contact verlichting22 "verlichting22[MAP(en.map):%s]" {modbus="slave11:5"}
Contact verlichting23 "verlichting23[MAP(en.map):%s]" {modbus="slave11:6"}
Contact verlichting24 "verlichting24[MAP(en.map):%s]" {modbus="slave11:7"}
Contact verlichting25 "verlichting25[MAP(en.map):%s]" {modbus="slave11:8"}
Contact verlichting26 "verlichting26[MAP(en.map):%s]" {modbus="slave11:9"}
Contact verlichting27 "verlichting27[MAP(en.map):%s]" {modbus="slave11:10"}
Contact verlichting28 "verlichting28[MAP(en.map):%s]" {modbus="slave11:11"}
Contact verlichting29 "verlichting29[MAP(en.map):%s]" {modbus="slave11:12"}
Contact verlichting30 "verlichting30[MAP(en.map):%s]" {modbus="slave11:13"}
Contact verlichting31 "verlichting31[MAP(en.map):%s]" {modbus="slave11:14"}
Contact verlichting32 "verlichting32[MAP(en.map):%s]" {modbus="slave11:15"}
Switch verlichting1dummy "[%s]"
Switch verlichting2dummy "[%s]"
Switch verlichting3dummy "[%s]"
Switch verlichting4dummy "[%s]"
Switch verlichting5dummy "[%s]"
Switch verlichting6dummy "[%s]"
Switch verlichting7dummy "[%s]"
Switch verlichting8dummy "[%s]"
Switch verlichting9dummy "[%s]"
Switch verlichting10dummy "[%s]"
Switch verlichting11dummy "[%s]"
Switch verlichting12dummy "[%s]"
Switch verlichting13dummy "[%s]"
Switch verlichting14dummy "[%s]"
Switch verlichting15dummy "[%s]"
Switch verlichting16dummy "[%s]"
Switch verlichting17dummy "[%s]"
Switch verlichting18dummy "[%s]"
Switch verlichting19dummy "[%s]"
Switch verlichting20dummy "[%s]"
Switch verlichting21dummy "[%s]"
Switch verlichting22dummy "[%s]"
Switch verlichting23dummy "[%s]"
Switch verlichting24dummy "[%s]"
Switch verlichting25dummy "[%s]"
Switch verlichting26dummy "[%s]"
Switch verlichting27dummy "[%s]"
Switch verlichting28dummy "[%s]"
Switch verlichting29dummy "[%s]"
Switch verlichting30dummy "[%s]"
Switch verlichting31dummy "[%s]"
Switch verlichting32dummy "[%s]"
I created a dropbox acount here is the link https://www.dropbox.com/s/cur1xfblf8wqm0q/Modbus%20logs.txt?dl=0
Do you have some other file sharing service?
Btw, having poll=1 with the old binding does not mean it is polling with that high frequency. In practice it is polling as fast as possible. Not saying that there isn’t room to improve in the new binding
@Pe_Man, the logs say that reconnectAfterMillis is 10000 not 60000? I guess that works too… Are you sure you changed the config and recorded correct logs?
After thinking this for a while, I think the “scheduling logic” of the polling needs improvement… Writing down my notes here.
Currently, a fixed size thread pool (5 threads) is used for all polling. However, all but one of this threads are waiting since in your configuration everything polls the same slave. We have limited to have at most one connection to the slave at a time.
This means that processing of commands gets delayed. Furthermore, poll tasks with high poll frequency do not get fair share of time.
I will try to replicate this with my own setup and see if there’s a quick workaround for you.
That’s not unreasonable, given the Modbus underlying philosophy or model of everything queuing for one serial bus.
I think you have already implemented the queue shortening idea of discarding new polls where already one in the queue? i.e. only one request per poller thing. Wouldn’t make anything work faster, just reduce queue length.
Looking at your earlier time analysis, I note that post-comms callback processing is not insignificant. What we can’t see is what workload we are throwing on to the rest of the system e.g. putting updates on the OH event bus.
I wonder if we may yet revisit the OH1 option of not updating if no change. I know this is not general policy, but fast polling is not something OH will ever handle well.
@Pe_Man, reanalyzing your logs, (see this post)
You can see that modbus transactions are completed every 100 ms. Note that by default the binding waits timeBetweenTransactionsMillis, 60 ms for tcp things. Since actual modbus I/O takes ~20 ms, and callback handling takes ~15 ms, it’s basically working all the time!
Please also note that the poll period of 1 second is infeasible considering the default timeBetweenTransactionsMillis – 100 pollers would take at least 6 seconds to complete just due to wait time between transactions.
As adviced in tcp thing configuration docs, you do have option to reduce timeBetweenReconnectMillis to lower value. For example, with your config and timeBetweenTransactionsMillis=0 reconnectAfterMillis=60000 I can reach ~92 transactions/second against a local modbus slave (diagslave).
I advice to lower timeBetweenTransactionsMillis as low as possible (provided you are not getting any errors), and report back.
@Rado1 I’m not sure I have solid advice regarding CPU usage. It might be because of the new binding doing more work (updating at every poll). Alternatively the new binding has to go through longer code path with channels and things etc. that were not present with old binding.
To work on this hypothesis: If you have the energy, would appreciate if you can compare CPU load with these two setups
- openHAB 2.4.0 release with modbus1 binding. Use your old configuration but set
updateunchangeditemstotruefor all “slaves”. Old docs: Modbus Binding · openhab/openhab1-addons Wiki · GitHub - openHAB 2.4.0 release with modbus2 binding. Configure
interTransactionDelayMillis=1to all tcp things to match the old configuration better.
Provide verbose logs from each setup.
You can record CPU usage of openHAB with this one-liner in bash (I am assuming you are on linux):
FILENAME=ps.log ; echo > $FILENAME; while true; do (echo "%CPU %MEM ARGS $(date)" && ps -o pcpu,pmem,args -p `pgrep -f openhab` | cut -d" " -f1- ) | tee -a $FILENAME; sleep 0.5; done
I think you have already implemented the queue shortening idea of discarding new polls where already one in the queue? i.e. only one request per poller thing. Wouldn’t make anything work faster, just reduce queue length.
Yeah queue is not accumulating anymore and there is at most one item in the queue per poller. Actually previously there were two queue and if the polling was fast (faster than updating channels), the other one would grow without limit…
Looking at your earlier time analysis, I note that post-comms callback processing is not insignificant. What we can’t see is what workload we are throwing on to the rest of the system e.g. putting updates on the OH event bus.
I wonder if we may yet revisit the OH1 option of not updating if no change. I know this is not general policy, but fast polling is not something OH will ever handle well.
This is certainly true. I am seeing a lot more time spent with low-end PCs such as Raspberry Pi 3 B (400 ms!). Tried to profile where the time goes but it really looks like it just does so much work serializing/deserializing the updates to internal event bus openHAB uses.
There might be a point what you are saying. In case we would introduce “update-channels-only-on-value-change” I would like to tune it such that it would be “update-channels-only-on-value-change-or-every-X-ms” to support cases where you would like to have “heartbeat” updates (e.g. with expire binding).
Need to try this out when I have the time.
UPDATE: @Rado1 Try with this version. It updates channels “lazily” (every x seconds) unless the value changes. org.openhab.binding.modbus-2.5.0-lazy-updates-SNAPSHOT.jar.pdf (61.9 KB) . Rename the pdf as jar.
Best,
Sami
1 Like
Yes, i changed to 10000 afterwards to see if there was a difference(but it was not).
I probably captured the logs with the latter settings.
Med vänlig hälsning,
Per
I will try this when I’m back home in a couple of days.
Meanwhile, just throwing an idea out here while I’m thinking about it.
Is it possible to prioritise the polls depending on usage, like things used in rules or items on a current homepage etc need faster response time. While things not used by any process could wait?
I don’t know if it is possible , but I think an HMI driver works like this, just poll the items on the current page making modbus requests quite fast.
Med vänlig hälsning,
Per
Is it possible to prioritise the polls depending on usage, like things used in rules or items on a current homepage etc need faster response time. While things not used by any process could wait?
No I don’t think that is possible.
The SNAPSHOT binding does not show up in the binding inbox?I named it like this “org.openhab.binding.modbus-2.5.0-lazy-updates-SNAPSHOT.jar” and put it in the openhab2-addons file.And i uninstalled the 2.4 modbus binding restart openhab and nothing show’s up?Am i doing something wrong?I am using the jablotron SNAPSHOT binding the same way and that one is showing up in the binding inbox?
Hmm, I haven’t used PaperUI for this so I’m not sure how it works out
bundle:list|grep -i modbus list all modbus bundles.
bundle:update XX where XX is the ID of the modbus binding as listed by bundle:list. Updates the binding from addons folder.
What do you mean by openhab2-addons file?