Subscription expressions optimization

[uKL]

First of all, great job with 2.0 :) I've tested it due to lagging issues (I've described on loxforum)

Overall experience is great but the subscription filters are somehow still consuming some processing time, even if the result is set to be ignored. I've added some logs to see how long the sub received takes.

Here are some logs

20:52:47.037 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/linkquality: 55
20:52:47.038    zigbee2mqtt/0xccccccfffee2762f/linkquality (incoming value 55) skipped - Subscription Filter line 2
20:52:47.038 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffee2762f/linkquality, send to MS 1
20:52:47.040 <INFO> Sent to miniserver 2.35104560852051 msecs
20:52:47.040 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/battery: 47
20:52:47.041    zigbee2mqtt/0xccccccfffee2762f/battery is cached
20:52:47.042 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffee2762f/battery, send to MS 1
20:52:47.042   HTTP: Preparing input zigbee2mqtt_0xccccccfffee2762f_battery (using cache): 47
20:52:47.043 <INFO> Sent to miniserver 2.43997573852539 msecs
20:52:47.044 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/update_available: true
20:52:47.044    zigbee2mqtt/0xccccccfffee2762f/update_available (incoming value true) skipped - Subscription Filter line 3
20:52:47.045 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffee2762f/update_available, send to MS 1
20:52:47.046 <INFO> Sent to miniserver 2.22301483154297 msecs
20:52:47.047 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/click: on
20:52:47.048    zigbee2mqtt/0xccccccfffee2762f/click is cached
20:52:47.048 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffee2762f/click, send to MS 1
20:52:47.049   HTTP: Preparing input zigbee2mqtt_0xccccccfffee2762f_click (using cache): on
20:52:47.061 <INFO> Sent to miniserver 13.225793838501 msecs
20:52:47.265 <OK> UDP IN:  (192.168.3.254): zigbee2mqtt/0xccccccfffed45a82/set {"color_temp_startup": "250","color_temp": "250", "brightness": "254"}
20:52:47.266 Publishing: 'zigbee2mqtt/0xccccccfffed45a82/set'='{"color_temp_startup": "250","color_temp": "250", "brightness": "254"}'
20:52:47.269 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/set: {"color_temp_startup": "250","color_temp": "250", "brightness": "254"}
20:52:47.269   Expanding json message
20:52:47.271    zigbee2mqtt/0xccccccfffed45a82/set/color##_temp (incoming value 250) skipped - Subscription Filter line 1
20:52:47.271    zigbee2mqtt/0xccccccfffed45a82/set/brightness (incoming value 254) skipped - Subscription Filter line 1
20:52:47.272    zigbee2mqtt/0xccccccfffed45a82/set/color##_temp##_startup (incoming value 250) skipped - Subscription Filter line 1
20:52:47.272 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/set, send to MS 1
20:52:47.274 <INFO> Sent to miniserver 4.35900688171387 msecs
20:52:47.393 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: ON
20:52:47.393    zigbee2mqtt/0xccccccfffed45a82/state (incoming value ON) skipped - do not forward enabled
20:52:47.394 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/state, send to MS 1
20:52:47.395 <INFO> Sent to miniserver 1.7540454864502 msecs
20:52:47.396 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
20:52:47.396    zigbee2mqtt/0xccccccfffed45a82/linkquality (incoming value 60) skipped - Subscription Filter line 2
20:52:47.397 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/linkquality, send to MS 1
20:52:47.398 <INFO> Sent to miniserver 1.86705589294434 msecs
20:52:47.398 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
20:52:47.399    zigbee2mqtt/0xccccccfffed45a82/brightness is cached
20:52:47.399 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/brightness, send to MS 1
20:52:47.400   HTTP: Preparing input zigbee2mqtt_0xccccccfffed45a82_brightness (using cache): 254
20:52:47.401 <INFO> Sent to miniserver 2.18391418457031 msecs
20:52:47.401 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
20:52:47.402    zigbee2mqtt/0xccccccfffed45a82/color_temp is cached
20:52:47.402 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/color_temp, send to MS 1
20:52:47.403   HTTP: Preparing input zigbee2mqtt_0xccccccfffed45a82_color_temp (using cache): 250
20:52:47.404 <INFO> Sent to miniserver 2.13384628295898 msecs
20:52:47.404 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
20:52:47.405    zigbee2mqtt/0xccccccfffed45a82/update_available (incoming value true) skipped - Subscription Filter line 3
20:52:47.406 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/update_available, send to MS 1
20:52:47.407 <INFO> Sent to miniserver 1.97505950927734 msecs
20:52:47.482 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: ON
20:52:47.482    zigbee2mqtt/0xccccccfffed45a82/state (incoming value ON) skipped - do not forward enabled
20:52:47.483 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/state, send to MS 1
20:52:47.484 <INFO> Sent to miniserver 1.75905227661133 msecs
20:52:47.484 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
20:52:47.485    zigbee2mqtt/0xccccccfffed45a82/linkquality (incoming value 60) skipped - Subscription Filter line 2
20:52:47.486 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/linkquality, send to MS 1
20:52:47.487 <INFO> Sent to miniserver 2.4409294128418 msecs
20:52:47.488 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
20:52:47.489    zigbee2mqtt/0xccccccfffed45a82/brightness is cached
20:52:47.489 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/brightness, send to MS 1
20:52:47.490   HTTP: Preparing input zigbee2mqtt_0xccccccfffed45a82_brightness (using cache): 254
20:52:47.491 <INFO> Sent to miniserver 2.76803970336914 msecs
20:52:47.492 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
20:52:47.492    zigbee2mqtt/0xccccccfffed45a82/color_temp is cached
20:52:47.493 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/color_temp, send to MS 1
20:52:47.494   HTTP: Preparing input zigbee2mqtt_0xccccccfffed45a82_color_temp (using cache): 250
20:52:47.495 <INFO> Sent to miniserver 2.58302688598633 msecs
20:52:47.496 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
20:52:47.496    zigbee2mqtt/0xccccccfffed45a82/update_available (incoming value true) skipped - Subscription Filter line 3
20:52:47.497 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/update_available, send to MS 1
20:52:47.498 <INFO> Sent to miniserver 2.14099884033203 msecs

What you can see, that most of the topics are ignored due to regexp filtering but their processing is summing up to around 30 millis - and this is only a button press and a lamp turning on.

[christianTF]

20:52:47.269 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/set: {"color_temp_startup": "250","color_temp": "250", "brightness": "254"}
20:52:47.269   Expanding json message
20:52:47.271    zigbee2mqtt/0xccccccfffed45a82/set/color##_temp (incoming value 250) skipped - Subscription Filter line 1
20:52:47.271    zigbee2mqtt/0xccccccfffed45a82/set/brightness (incoming value 254) skipped - Subscription Filter line 1
20:52:47.272    zigbee2mqtt/0xccccccfffed45a82/set/color##_temp##_startup (incoming value 250) skipped - Subscription Filter line 1
20:52:47.272 zigbee2mqtt/# matches zigbee2mqtt/0xccccccfffed45a82/set, send to MS 1
20:52:47.274 <INFO> Sent to miniserver 4.35900688171387 msecs

It would be possible to stop processing earlier if everything was filtered, before of the # toMS: Evaluate what Miniservers to send to. May save 1 msec. Currently in an to late state before the Pre-Release (more important things to fix).

I'm just wondering about the "Sent to miniserver" line, as everything was filtered, and no element should arrive at the mshttp functions.

[uKL]

Here is where I've put the log

if( $miniservers{$cfg->{Main}{msno}} ) {
            foreach ( @toMS ) {
                # LOGDEB "  HTTP: Sending all values";
                my $httpresp;
                $httpresp = LoxBerry::MQTTGateway::IO::mshttp_send2($_,  %sendhash_noncached);
                validate_http_response( $_, \%sendhash_noncached, $httpresp ) if $httpresp;
                $httpresp = LoxBerry::MQTTGateway::IO::mshttp_send_mem2($_,  %sendhash_cached);
                validate_http_response( $_, \%sendhash_cached, $httpresp ) if $httpresp;

                if ( scalar keys %sendhash_resetaftersend > 0 ) {
                    LOGDEB "  HTTP: Sending reset-after-send values (delay ".$cfg->{Main}{resetaftersendms}." ms)";
                    Time::HiRes::sleep($cfg->{Main}{resetaftersendms}/1000);
                    $httpresp = LoxBerry::MQTTGateway::IO::mshttp_send2($_, %sendhash_resetaftersend);
                }
                LOGINF "Sent to miniserver " . (Time::HiRes::time() - $beforeSendingTime) * 1000 . " msecs";
            }
        } else {
            LOGERR "  HTTP: Cannot send: No Miniserver defined";
        }

BTW. Is there any neat way to reload loxberry or the plugin without rebooting the RPi? restarting of the loxberry serving doesn't seem to do that.

[christianTF]

In that short time scales also the logging itself needs to be taken into account.

As you are already in "debugging" mode, would you like to comment every LOGxxx line from after MQTT receivedup to Sent to miniserver and check, what the difference is. Logfile processing is checking the loglevel, open file, add line, close file, and the logfile is stored on a zram compressed ram disk.

Is there any neat way to reload loxberry or the plugin without rebooting the RPi?

I'm not sure what you are for. What do you mean by "reload"? The mqttgateway.pl process can be restarted directly by the webif, or pkill mqttgateway.pl and restarting it from shell.

[uKL]

I'm not sure what you are for. What do you mean by "reload"? The mqttgateway.pl process can be restarted directly by the webif, or pkill mqttgateway.pl and restarting it from shell.

That's exactly what I needed :) I'm newbie to PERL, I'm proficient with Java & Kotlin and programmed for a few years in PHP.

22:23:15.752 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/linkquality: 39
22:23:15.754 <INFO> Sent to miniserver 1.20210647583008 msecs
22:23:15.755 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/battery: 87
22:23:15.757 <INFO> Sent to miniserver 1.28793716430664 msecs
22:23:15.758 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/update_available: true
22:23:15.760 <INFO> Sent to miniserver 1.19209289550781 msecs
22:23:15.761 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/click: off
22:23:15.772 <INFO> Sent to miniserver 10.4401111602783 msecs
22:23:15.773 <OK> UDP IN:  (192.168.3.254): zigbee2mqtt/0xccccccfffed45a82/set {"color_temp_startup": "250","color_temp": "250", "brightness": "0"}
22:23:15.774 Publishing: 'zigbee2mqtt/0xccccccfffed45a82/set'='{"color_temp_startup": "250","color_temp": "250", "brightness": "0"}'
22:23:15.780 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/set: {"color_temp_startup": "250","color_temp": "250", "brightness": "0"}
22:23:15.782 <INFO> Sent to miniserver 1.60694122314453 msecs
22:23:15.887 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: OFF
22:23:15.889 <INFO> Sent to miniserver 0.905990600585938 msecs
22:23:15.890 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
22:23:15.891 <INFO> Sent to miniserver 0.924110412597656 msecs
22:23:15.892 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
22:23:15.894 <INFO> Sent to miniserver 1.00302696228027 msecs
22:23:15.894 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
22:23:15.896 <INFO> Sent to miniserver 0.993967056274414 msecs
22:23:15.897 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
22:23:15.898 <INFO> Sent to miniserver 0.929117202758789 msecs
22:23:15.980 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: OFF
22:23:15.981 <INFO> Sent to miniserver 0.975131988525391 msecs
22:23:15.982 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
22:23:15.983 <INFO> Sent to miniserver 0.905990600585938 msecs
22:23:15.984 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
22:23:15.986 <INFO> Sent to miniserver 0.974893569946289 msecs
22:23:15.986 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
22:23:15.988 <INFO> Sent to miniserver 0.976800918579102 msecs
22:23:15.989 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
22:23:15.991 <INFO> Sent to miniserver 1.67608261108398 msecs

Here are results. First response from the MS comes after 22ms! Entire process takes 239ms.

Another thing, I've dumped what goes to IO::mshttp

22:27:13.119 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/linkquality: 44
22:27:13.120   HTTP: Will send to MS: $VAR1 = {};

22:27:13.121 <INFO> Sent to miniserver 1.91998481750488 msecs
22:27:13.122 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/battery: 87
22:27:13.123   HTTP: Will send to MS: $VAR1 = {
          'zigbee2mqtt_0xccccccfffee2762f_battery' => '87'
        };

22:27:13.124 <INFO> Sent to miniserver 1.89900398254395 msecs
22:27:13.125 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/update_available: true
22:27:13.126   HTTP: Will send to MS: $VAR1 = {};

22:27:13.127 <INFO> Sent to miniserver 1.80888175964355 msecs
22:27:13.128 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/click: on
22:27:13.139   HTTP: Will send to MS: $VAR1 = {};

22:27:13.140 <INFO> Sent to miniserver 12.1700763702393 msecs
22:27:13.343 <INFO> Executing DNS reverse lookup
22:27:13.343 <OK> UDP IN:  (192.168.3.254): zigbee2mqtt/0xccccccfffed45a82/set {"color_temp_startup": "250","color_temp": "250", "brightness": "254"}
22:27:13.344 Publishing: 'zigbee2mqtt/0xccccccfffed45a82/set'='{"color_temp_startup": "250","color_temp": "250", "brightness": "254"}'
22:27:13.347 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/set: {"color_temp_startup": "250","color_temp": "250", "brightness": "254"}
22:27:13.349   HTTP: Will send to MS: $VAR1 = {};

22:27:13.350 <INFO> Sent to miniserver 2.76684761047363 msecs
22:27:13.448 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: ON
22:27:13.449   HTTP: Will send to MS: $VAR1 = {};

22:27:13.450 <INFO> Sent to miniserver 1.5261173248291 msecs
22:27:13.452 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
22:27:13.453   HTTP: Will send to MS: $VAR1 = {};

22:27:13.454 <INFO> Sent to miniserver 1.5568733215332 msecs
22:27:13.455 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
22:27:13.456   HTTP: Will send to MS: $VAR1 = {
          'zigbee2mqtt_0xccccccfffed45a82_brightness' => '254'
        };

22:27:13.457 <INFO> Sent to miniserver 1.70588493347168 msecs
22:27:13.457 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
22:27:13.459   HTTP: Will send to MS: $VAR1 = {
          'zigbee2mqtt_0xccccccfffed45a82_color_temp' => '250'
        };

22:27:13.459 <INFO> Sent to miniserver 1.66487693786621 msecs
22:27:13.460 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
22:27:13.461   HTTP: Will send to MS: $VAR1 = {};

22:27:13.462 <INFO> Sent to miniserver 1.79815292358398 msecs
22:27:13.539 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: ON
22:27:13.539   HTTP: Will send to MS: $VAR1 = {};

22:27:13.540 <INFO> Sent to miniserver 1.13010406494141 msecs
22:27:13.540 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
22:27:13.541   HTTP: Will send to MS: $VAR1 = {};

22:27:13.542 <INFO> Sent to miniserver 1.1441707611084 msecs
22:27:13.542 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
22:27:13.543   HTTP: Will send to MS: $VAR1 = {
          'zigbee2mqtt_0xccccccfffed45a82_brightness' => '254'
        };

22:27:13.544 <INFO> Sent to miniserver 1.21808052062988 msecs
22:27:13.544 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
22:27:13.545   HTTP: Will send to MS: $VAR1 = {
          'zigbee2mqtt_0xccccccfffed45a82_color_temp' => '250'
        };

22:27:13.545 <INFO> Sent to miniserver 1.19400024414062 msecs
22:27:13.546 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
22:27:13.547   HTTP: Will send to MS: $VAR1 = {};

22:27:13.547 <INFO> Sent to miniserver 1.12295150756836 msecs

As you can see, even if the hash is empty, it goes to the output pipe. I've introduced a following condition:

if (%sendhash_noncached) {
                    #LOGDEB "  HTTP: Will send non-cached to MS: ".Dumper(\%sendhash_noncached);
                    $httpresp = LoxBerry::MQTTGateway::IO::mshttp_send2($_,  %sendhash_noncached);
                    validate_http_response( $_, \%sendhash_noncached, $httpresp ) if $httpresp;
                }
                if (%sendhash_cached) {
                    #LOGDEB "  HTTP: Will send cached to MS: ".Dumper(\%sendhash_cached);
                    $httpresp = LoxBerry::MQTTGateway::IO::mshttp_send_mem2($_,  %sendhash_cached);
                    validate_http_response( $_, \%sendhash_cached, $httpresp ) if $httpresp;
                }

Which resulted in total processing time of ~211ms (part of that is the zigbee communication itself)

22:36:21.694 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/linkquality: 55
22:36:21.695 <INFO> Sent to miniserver 0.580072402954102 msecs
22:36:21.696 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/battery: 87
22:36:21.698 <INFO> Sent to miniserver 1.29294395446777 msecs
22:36:21.699 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/update_available: true
22:36:21.700 <INFO> Sent to miniserver 0.570058822631836 msecs
22:36:21.701 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/click: off
22:36:21.713 <INFO> Sent to miniserver 11.7189884185791 msecs
22:36:21.714 <OK> UDP IN:  (192.168.3.254): zigbee2mqtt/0xccccccfffed45a82/set {"color_temp_startup": "250","color_temp": "250", "brightness": "0"}
22:36:21.714 Publishing: 'zigbee2mqtt/0xccccccfffed45a82/set'='{"color_temp_startup": "250","color_temp": "250", "brightness": "0"}'
22:36:21.718 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/set: {"color_temp_startup": "250","color_temp": "250", "brightness": "0"}
22:36:21.720 <INFO> Sent to miniserver 1.11103057861328 msecs
22:36:21.815 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: OFF
22:36:21.816 <INFO> Sent to miniserver 0.411033630371094 msecs
22:36:21.816 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
22:36:21.817 <INFO> Sent to miniserver 0.40888786315918 msecs
22:36:21.818 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
22:36:21.819 <INFO> Sent to miniserver 1.04093551635742 msecs
22:36:21.820 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
22:36:21.821 <INFO> Sent to miniserver 1.06287002563477 msecs
22:36:21.822 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
22:36:21.823 <INFO> Sent to miniserver 0.462055206298828 msecs
22:36:21.896 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: OFF
22:36:21.896 <INFO> Sent to miniserver 0.396966934204102 msecs
22:36:21.898 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
22:36:21.899 <INFO> Sent to miniserver 0.473976135253906 msecs
22:36:21.900 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
22:36:21.901 <INFO> Sent to miniserver 1.1448860168457 msecs
22:36:21.902 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
22:36:21.904 <INFO> Sent to miniserver 1.16682052612305 msecs
22:36:21.904 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
22:36:21.905 <INFO> Sent to miniserver 0.505924224853516 msecs

It's not at a level that is satisfying but further optimizations are possible:

1. No need to expand JSON if not forwarding
2. Do not prepare data for incoming tab (this needed only when configuring)
3. Maybe multithreading to prepare messages? RPI4 has 4 cores...

[christianTF]

To "if" the sendhash variables before calling mshttp doesn't really make the request cheaper, as the if is already in mshttp, and in 99% of cases, somethings needs to be sent (and if filtered, who cares that doing nothing took half a msec longer as needed).

json expansion is needed as all filters work on expanded data.

Preparing data for incoming overview is copying pointers in memory. I want to have the state in memory.

Multithreading is really something I'm thinking of, but only for the Transformer handling. Perl has not very good Multithreading support (it's used in Squeezelite Plugin), and Thread handling will take up the double of the 1 msec that can be eliminated out of 4.

Currently, I only see further performance needs in the UI with additional filters, because data increases. The processing delay is required as otherwise it will freeze our Miniserver Gen. 1.

[christianTF]

Would you test this easy change that quits message processing early, if nothing is left after the filters?

[uKL]

(and if filtered, who cares that doing nothing took half a msec longer as needed).

Well, actually, the processing is not concurrent. Basically, if my zigbee device reports 15 topics (and unfortunately the last one is /click), that means I've wasted 15 millis (at least, if each takes 1ms) before I knew about the click.

The change you've added in f693e65 works fine. Good job!

08:36:16.492 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/linkquality: 57
08:36:16.493 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/battery: 34
08:36:16.495 <INFO> Sent to miniserver 1.36017799377441 msecs
08:36:16.496 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/update_available: true
08:36:16.497 <INFO> MQTT received: zigbee2mqtt/0xccccccfffee2762f/click: off
08:36:16.509 <INFO> Sent to miniserver 12.4340057373047 msecs
08:36:16.510 <OK> UDP IN:  (192.168.3.254): zigbee2mqtt/0xccccccfffed45a82/set {"color_temp_startup": "250","color_temp": "250", "brightness": "0"}
08:36:16.514 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/set: {"color_temp_startup": "250","color_temp": "250", "brightness": "0"}
08:36:16.610 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: OFF
08:36:16.610 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
08:36:16.611 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
08:36:16.612 <INFO> Sent to miniserver 1.11103057861328 msecs
08:36:16.613 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
08:36:16.614 <INFO> Sent to miniserver 1.11103057861328 msecs
08:36:16.615 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true
08:36:16.696 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/state: OFF
08:36:16.696 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/linkquality: 60
08:36:16.698 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/brightness: 254
08:36:16.700 <INFO> Sent to miniserver 1.14297866821289 msecs
08:36:16.700 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/color_temp: 250
08:36:16.701 <INFO> Sent to miniserver 1.11508369445801 msecs
08:36:16.702 <INFO> MQTT received: zigbee2mqtt/0xccccccfffed45a82/update_available: true

The processing delay is required as otherwise it will freeze our Miniserver Gen. 1.

I'm not aware of issues with Gen 1, I'm just starting with Loxone :) I was comparing to my previous setup with OpenHAB which had almost no delay (stronger machine, direct MQTT connection).

[christianTF]

Try this: https://github.com/christianTF/LoxBerry-Plugin-MQTT-Gateway/commit/69d683cea757e16bb548f25ae72725647b9e78fe

What is your LoxWiki account name?

[uKL]

What is your LoxWiki account name?

https://www.loxforum.com/member/14020-pawel-urban

[uKL]

Try this: 69d683c

I haven't noticed any significant performance changes. Might be better with more significant load but not in my case.

[christianTF]

What is your performance setting at the Settings tab (I suppose it is "Very fast" or "No limits"). In that case, the Pid controller in the Gateway may have reduced to delay to nearly 0, so the "Fast Response Mode" cannot do any further improvements. This mode skips the loop delay in case that data were processed in the last round.

Perl (or PHP) is not a callback language. Using e. g. Node.js wouldn't require to have fetching loops. But the MQTT and UDP link in the Gateway ARE open connections! Fetching is not done from the broker, but from the socket buffer.

[christianTF]

What is your LoxWiki account name?

https://www.loxforum.com/member/14020-pawel-urban

This is not LoxWiki, this is Loxforum.

[uKL]

I somehow thought they share one account & it turned out I didn't have any. Here it is pawel.urban.

in fact, I was on default setting (Fast). Whenever I try changing that I see "Error saving" error message.

[christianTF]

Check https://www.loxwiki.eu/display/LOXBERRY/MQTT+Gateway+2.0+What%27s+New https://www.loxwiki.eu/display/LOXBERRY/MQTT+Gateway+-+Transformers

If you thing the saving error is an issue (and not happened of your changes to the Gateway), please open an issue with screenshot of the error (and if possible F12 Dev Tools Error message, if one exists).

[uKL]

Thanks, good job! :) I think we can close this issue for now.

[uKL]

If fact, the issue I was seeing with the config was related to the config file access rights. It has been altered when I ran the mqttgateway from the console (as root sadly). Now all good. Will check how this affects performance later.

[christianTF]

I'll close the issue. For still more performance, we need more MHz at Raspberry and Miniserver ;-)