Modbus performance and logging improvements #4304

ssalonen · 2018-12-02T17:49:05Z

Some small performance improvements identified using JProfiler:

avoid calling isLinked(String) and prefer isLinked(ChannelUID)
avoid creating ChanneUID, now reusing same instances
some diagnostic (e.g. last read success) channels were updated even though they were not linked. Turns out DateTimeType unnecessary construction shows up profiler

Furthermore, logging improved to give clear outline of bottle necks (from raspberry pi 3B):

Modbus operation ended, timing info: {total: 476 ms, connection: 15, transaction=4, callback=412} [operation ID 2379c461-b4bc-473f-96f0-0c23987f3250]

(currently most of the time is spent in the binding.modbus when data has been already received from the slave)

Signed-off-by: Sami Salonen <ssalonen@gmail.com>

This was introduced to get high-level split down for each operation Example log statement: Modbus operation ended, timing info: {total: 476 ms, connection: 15, transaction=4, callback=412} [operation ID 2379c461-b4bc-473f-96f0-0c23987f3250] Signed-off-by: Sami Salonen <ssalonen@gmail.com>

Signed-off-by: Sami Salonen <ssalonen@gmail.com>

ssalonen · 2018-12-02T18:00:39Z

...ansport.modbus/src/main/java/org/openhab/io/transport/modbus/internal/ModbusManagerImpl.java

                    }
                }
            }
            Exception exception = lastError.get();
            if (exception != null) {
                // All retries failed with some error
                if (callback != null) {
-                    callbackThreadPool.execute(() -> {


We want to run in some thread right away, similar to other callbacks. Thus, removing call to ExecutorService.execute and invoking the callback directly.

Should have spotted this already in https://github.com/openhab/openhab2-addons/pull/4158

ssalonen · 2018-12-02T18:00:56Z

...ansport.modbus/src/main/java/org/openhab/io/transport/modbus/internal/ModbusManagerImpl.java

            return Optional.empty();
        }
        if (!connection.isPresent()) {
            logger.warn("Could not connect to endpoint {} -- aborting request {} [operation ID {}]", endpoint, request,
                    operationId);
            if (callback != null) {
-                callbackPool.execute(() -> {


We want to run in some thread right away, similar to other callbacks. Thus, removing call to ExecutorService.execute and invoking the callback directly.

Should have spotted this already in https://github.com/openhab/openhab2-addons/pull/4158

martinvw · 2018-12-07T19:29:29Z

...modbus/src/main/java/org/openhab/binding/modbus/internal/handler/ModbusDataThingHandler.java

-        DateTimeType now = new DateTimeType();
-        updateStatus(ThingStatus.ONLINE);
-        updateState(ModbusBindingConstantsInternal.CHANNEL_LAST_WRITE_SUCCESS, now);
+        if (getThing().getStatus() != ThingStatus.ONLINE) {


@kaikreuzer do we want to optimize such things as this one and line 765

Or should the framework be optimized better, @ssalonen how expensive was this?

It's expensive enough to show up in my profiling studies... Modbus is a tough case since some users have very high poll rates..

Haven't looked into the framework if there is any obvious optimizations

The general suggestion is to throttle it in the binding this way if there are status updates every few seconds. I guess that's the case for modbus, so this optimisation is fine. We could also think about moving something like that to the framework, but having it transparent in the binding is imho not bad.

Great thanks 👍

The LIFX binding had a similar issue which was addressed with eclipse-archived/smarthome#3816. It sends the same update at most once a second. That way it can still be used for the "last seen online" feature that will be there some day. 😉

Nice find @wborn. I adapted the code to follow the convention set by LIFX:
f75be1a

Now throttling all state updates in data thing with the same logic as in LIFX.

martinvw · 2018-12-07T19:31:32Z

Results :
Failed tests: 
  ModbusDataHandlerTest.testOnRegistersRealTransformationNoLinks:781->assertSingleStateUpdate:426 
Expected: is is not null
     but: was null

ssalonen · 2018-12-09T14:49:42Z

@martinvw fixed the tests in 0e4e05a

Signed-off-by: Sami Salonen <ssalonen@gmail.com>

Even "last successful read" will not get an update if it is not linked Signed-off-by: Sami Salonen <ssalonen@gmail.com>

wborn

Thanks!

openhab-bot · 2018-12-10T19:20:42Z

This pull request has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/many-100-modbus-pollers-is-it-slowing-down-the-binding/53496/22

* Cache ChannelUID creation for no reason * Timing information for modbus operations This was introduced to get high-level split down for each operation Example log statement: Modbus operation ended, timing info: {total: 476 ms, connection: 15, transaction=4, callback=412} [operation ID 2379c461-b4bc-473f-96f0-0c23987f3250] * Avoid creating DateTimeType for no reason * Throttle ONLINE updates to 1 second Signed-off-by: Sami Salonen <ssalonen@gmail.com>

openhab-bot · 2018-12-24T09:36:10Z

This pull request has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/modbus-binding-with-wago-controller/60642/21

Regression introduced in PR openhab#4304: the thing status description is not passed to thing status updates. Signed-off-by: Sami Salonen <ssalonen@gmail.com>

* [modbus] data thing: update thing status including description Regression introduced in PR #4304: the thing status description is not passed to thing status updates. Signed-off-by: Sami Salonen <ssalonen@gmail.com>

* Cache ChannelUID creation for no reason * Timing information for modbus operations This was introduced to get high-level split down for each operation Example log statement: Modbus operation ended, timing info: {total: 476 ms, connection: 15, transaction=4, callback=412} [operation ID 2379c461-b4bc-473f-96f0-0c23987f3250] * Avoid creating DateTimeType for no reason * Throttle ONLINE updates to 1 second Signed-off-by: Sami Salonen <ssalonen@gmail.com> Signed-off-by: Pascal Larin <plarin@gmail.com>

* [modbus] data thing: update thing status including description Regression introduced in PR openhab#4304: the thing status description is not passed to thing status updates. Signed-off-by: Sami Salonen <ssalonen@gmail.com> Signed-off-by: Pascal Larin <plarin@gmail.com>

* Cache ChannelUID creation for no reason * Timing information for modbus operations This was introduced to get high-level split down for each operation Example log statement: Modbus operation ended, timing info: {total: 476 ms, connection: 15, transaction=4, callback=412} [operation ID 2379c461-b4bc-473f-96f0-0c23987f3250] * Avoid creating DateTimeType for no reason * Throttle ONLINE updates to 1 second Signed-off-by: Sami Salonen <ssalonen@gmail.com> Signed-off-by: Maximilian Hess <mail@ne0h.de>

* [modbus] data thing: update thing status including description Regression introduced in PR openhab#4304: the thing status description is not passed to thing status updates. Signed-off-by: Sami Salonen <ssalonen@gmail.com> Signed-off-by: Maximilian Hess <mail@ne0h.de>

ssalonen added 4 commits December 2, 2018 19:20

[modbus] cache ChannelUID creation for no reason

2014566

Signed-off-by: Sami Salonen <ssalonen@gmail.com>

[modbus] simplification

85834cf

Signed-off-by: Sami Salonen <ssalonen@gmail.com>

[modbus] avoid creating DateTimeType for no reason

e0678ed

Signed-off-by: Sami Salonen <ssalonen@gmail.com>

ssalonen force-pushed the modbus-improved-logging branch from ac511e9 to e0678ed Compare December 2, 2018 17:57

ssalonen commented Dec 2, 2018

View reviewed changes

martinvw reviewed Dec 7, 2018

View reviewed changes

ssalonen added 2 commits December 9, 2018 17:28

[modbus] throttle ONLINE updates to 1 second

f75be1a

Signed-off-by: Sami Salonen <ssalonen@gmail.com>

[modbus] fixed tests

5bd5883

Even "last successful read" will not get an update if it is not linked Signed-off-by: Sami Salonen <ssalonen@gmail.com>

ssalonen force-pushed the modbus-improved-logging branch from 0e4e05a to 5bd5883 Compare December 9, 2018 15:28

wborn approved these changes Dec 9, 2018

View reviewed changes

wborn merged commit 6e9f7d8 into openhab:master Dec 9, 2018

ssalonen mentioned this pull request Dec 27, 2018

[modbus] CONFIGURATION_ERROR status has no status description #4459

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Modbus performance and logging improvements #4304

Modbus performance and logging improvements #4304

ssalonen commented Dec 2, 2018 •

edited

ssalonen Dec 2, 2018 •

edited

ssalonen Dec 2, 2018 •

edited

martinvw Dec 7, 2018

martinvw Dec 7, 2018

ssalonen Dec 7, 2018

kaikreuzer Dec 7, 2018

martinvw Dec 8, 2018

wborn Dec 9, 2018

ssalonen Dec 9, 2018 •

edited

martinvw commented Dec 7, 2018

ssalonen commented Dec 9, 2018

wborn left a comment

openhab-bot commented Dec 10, 2018

openhab-bot commented Dec 24, 2018

Modbus performance and logging improvements #4304

Modbus performance and logging improvements #4304

Conversation

ssalonen commented Dec 2, 2018 • edited

ssalonen Dec 2, 2018 • edited

Choose a reason for hiding this comment

ssalonen Dec 2, 2018 • edited

Choose a reason for hiding this comment

martinvw Dec 7, 2018

Choose a reason for hiding this comment

martinvw Dec 7, 2018

Choose a reason for hiding this comment

ssalonen Dec 7, 2018

Choose a reason for hiding this comment

kaikreuzer Dec 7, 2018

Choose a reason for hiding this comment

martinvw Dec 8, 2018

Choose a reason for hiding this comment

wborn Dec 9, 2018

Choose a reason for hiding this comment

ssalonen Dec 9, 2018 • edited

Choose a reason for hiding this comment

martinvw commented Dec 7, 2018

ssalonen commented Dec 9, 2018

wborn left a comment

Choose a reason for hiding this comment

openhab-bot commented Dec 10, 2018

openhab-bot commented Dec 24, 2018

ssalonen commented Dec 2, 2018 •

edited

ssalonen Dec 2, 2018 •

edited

ssalonen Dec 2, 2018 •

edited

ssalonen Dec 9, 2018 •

edited