Blockly rules after upgrade to OH 4.0.1 very slow on the first run

After upgrading to OH 4.0.1 i run into a time issue, so i tested a simple rule designed with blockly.
I did the test on a complete fresh install with just a view items and only one rule!

i deleted the blocksource to be more readable.

ECMAScript-5.1

configuration: {}
triggers:
  - id: "1"
    configuration:
      itemName: Hue_motion_sensor_3_Bewegung
      state: ON
    type: core.ItemStateChangeTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      type: application/javascript;version=ECMAScript-5.1
      script: >
        if (itemRegistry.getItem('Tasmota_Vorhaus_Vorhaus_1').getState() ==
        'OFF') {
          events.sendCommand('Tasmota_Vorhaus_Vorhaus_1', 'ON');
        }
    type: script.ScriptAction

That is the log after the motionsensor triggered.

2023-08-09 20:37:49.034 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Hue_motion_sensor_3_Bewegung' changed from OFF to ON
2023-08-09 20:37:49.232 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Tasmota_Vorhaus_Vorhaus_1' received command ON
2023-08-09 20:37:49.234 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Tasmota_Vorhaus_Vorhaus_1' predicted to become ON
2023-08-09 20:37:49.236 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Tasmota_Vorhaus_Vorhaus_1' changed from OFF to ON

from the time the motionsensor trigered to the change of the switch it is not even a quater of a second, as it was always before the upgrade.

application/javascript

configuration: {}
triggers:
  - id: "1"
    configuration:
      itemName: Hue_motion_sensor_3_Bewegung
      state: ON
    type: core.ItemStateChangeTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      type: application/javascript
      script: |
        if (items.getItem('Tasmota_Vorhaus_Vorhaus_1').state == 'OFF') {
          items.getItem('Tasmota_Vorhaus_Vorhaus_1').sendCommand('ON');
        }
    type: script.ScriptAction

and the log after the motionsensor triggered

2023-08-09 20:39:29.756 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Hue_motion_sensor_3_Bewegung' changed from OFF to ON
==> /var/log/openhab/openhab.log <==
2023-08-09 20:39:29.760 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2023-08-09 20:39:29.806 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2023-08-09 20:39:29.808 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2023-08-09 20:39:29.813 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
==> /var/log/openhab/events.log <==
2023-08-09 20:39:39.682 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Hue_motion_sensor_3_Bewegung' changed from ON to OFF
==> /var/log/openhab/openhab.log <==
2023-08-09 20:39:46.968 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Successfully initialized GraalJS script engine.
==> /var/log/openhab/events.log <==
2023-08-09 20:39:46.974 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Tasmota_Vorhaus_Vorhaus_1' received command ON
2023-08-09 20:39:46.980 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Tasmota_Vorhaus_Vorhaus_1' predicted to become ON
2023-08-09 20:39:46.982 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Tasmota_Vorhaus_Vorhaus_1' changed from OFF to ON

from the time the motionsensor triggered to the change of the switch it is now 17 second and that is a very long time.

has anyone a idea of what could be the problem?
thanks Roli

Is it slow the first time the rule runs after itā€™s loaded or every time?

From looking at the log this one at least is from the first load.

There was a problem with the caching of the library that was causing the rules to run slowly the first time they are triggered that I believe got fixed but not until after 4.0 release.

Yes, I can confirm that. I noticed it and it was fixed by Florian a week ago or so. It is very fast with the latest version now.

I checked, it is slow only on the first load, but iĀ“m on release 4.0.1 downloaded and installed last monday.
it also occures when i open the rule and just close it without saving.

Can anybody agree that this is also happens with manually running rules? I must wait 1 min or longer to check a rule after manually execution.

I just updated to the latest snapshot, openHAB 4.1.0 Build #3581
and it is still there on the first load of the rule.

@florian-h05 Can you look into this as it is perfectly fine on my side since you implemented the webpack patch lately?

My fix, which is working fine on my system and for @stefan.hoehn as well, is not backported to the 4.0.x branch, but there is no patch release that includes it yet.
You either have to wait for 4.0.2 or deploy the fixed bundle yourself, I will try to add a guide later.

Not all bug fixes get back ported to the existing release.

That might trigger a rule reload under some circumstances. You can watch the event stream in the developer sidebar or enable logging of rule events to events.log to verify.

It doesnā€™t matter how the rule is triggered.

thank you guys for your effort.
@florian-h05 i can live with that until 4.0.2 is released.

Thanks to all of you for your great work!!!

Iā€™m not sure but on my system the rules working and then after a while some rules stay in running mode and openhab crash.

It start with a false info and then all other bindings canā€™t connect and get timeoutsā€¦

2023-08-11 21:24:57.768 [INFO ] [tomation.script.ui.Schlafzimmerlicht] - false
2023-08-11 21:29:29.441 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber ā€˜org.openhab.core.thing.internal.CommunicationManager@1bb03eeā€™ takes more than 5000ms.
2023-08-11 21:29:29.442 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber ā€˜org.openhab.core.internal.items.ItemUpdater@be8e28ā€™ takes more than 5000ms.

Open a new thread so this situation can be analyzed in detail. This behavior has nothing to do with Blockly. Something is running amok on your machine consuming resources and forcing OH to have to wait.

1 Like

@florian-h05 i just want to inform you that after the update to OH4.0.2-1, the delay is still there.
To make it sure i restarted OH twice and also uninstalled and installed the JS addon.

as i said already, i can live with that, because i ported all my rules already and i know that itā€™s just on the first run.

Fully disagree. Try to develop a new rule.
My Wife told me that rules they must be fired before are slow after a while. That happens with 4.0.1. If 4.0.2 didnā€™t fix it then that will not be satisfied for me.

As discussed above, there are 2 problems. Slow execution which happens the first time a rule is run and what you are seeing. Thatā€™s why I asked you to open a separate thread.

Itā€™s open Openhab 4.0.1 unstable - #21 by Wikibear

Is the delay time the same? Whatā€™s your platform?

The delay is exactly the same as before, around 12 to 17 seconds, only on the first run.

Log on first run

==> /var/log/openhab/openhab.log <==
2023-08-19 12:38:26.347 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2023-08-19 12:38:26.375 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2023-08-19 12:38:26.377 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2023-08-19 12:38:26.380 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...

==> /var/log/openhab/openhab.log <==
2023-08-19 12:38:41.084 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Successfully initialized GraalJS script engine.
2023-08-19 12:38:41.104 [INFO ] [org.openhab.automation.script.ui.AA ] - ASSUMPTION_DAY
2023-08-19 12:38:41.107 [INFO ] [org.openhab.automation.script.ui.AA ] - NATIONAL_DAY
2023-08-19 12:38:41.110 [INFO ] [org.openhab.automation.script.ui.AA ] - 128
2023-08-19 12:38:41.112 [INFO ] [org.openhab.automation.script.ui.AA ] - NATIONAL_DAY

Log on second run with a time trigger at 12:41

2023-08-19 12:41:00.367 [INFO ] [org.openhab.automation.script.ui.AA ] - ASSUMPTION_DAY
2023-08-19 12:41:00.373 [INFO ] [org.openhab.automation.script.ui.AA ] - NATIONAL_DAY
2023-08-19 12:41:00.379 [INFO ] [org.openhab.automation.script.ui.AA ] - 128
2023-08-19 12:41:00.383 [INFO ] [org.openhab.automation.script.ui.AA ] - NATIONAL_DAY

Release = Raspbian GNU/Linux 11 (bullseye)
Kernel = Linux 6.1.21-v8+
Platform = Raspberry Pi 4 Model B Rev 1.2
openHAB = 4.0.2 - Release Build

System runs absolutely stable!!

Same situation as you, I can confirm that with 4.0.2 the delay issue is still there.

It also happens every time you open a Blockly rule without saving it

2 Likes

I can confirm, that now after 4.0.2-1 upgrade, rules run very slow.
Normal it takes to send a mail and a WhatApp a couple of secounds.
Now it takes 55 sec. (55 sec the rule itself shows the icon ā€œrunningā€)

Itā€™s not important for me if I get the notification that rain started or something else
happend, like power off from a charger, but compared to 3.4.4 it seems a problem.
This only happens on my testsystem with this configuration:

Release = Raspbian GNU/Linux 11 (bullseye)
##    Kernel = Linux 6.1.21-v7+
##  Platform = Raspberry Pi 3 Model B Plus Rev 1.3
##    Uptime = 17 day(s). 14:44:0
## CPU Usage = 2.01% avg over 4 cpu(s) (4 core(s) x 1 socket(s))
##  CPU Load = 1m: 2.14, 5m: 2.36, 15m: 1.75
##    Memory = Free: 0.00GB (1%), Used: 0.93GB (99%), Total: 0.94GB
##      Swap = Free: 2.33GB (78%), Used: 0.66GB (22%), Total: 2.99GB
##      Root = Free: 20.09GB (72%), Used: 7.67GB (28%), Total: 28.98GB
##   Updates = 0 apt updates available.
##  Sessions = 1 session(s)
## Processes = 125 running processes of 32768 maximum processes

The production System, works very well with:

 Release = Raspbian GNU/Linux 11 (bullseye)
##    Kernel = Linux 6.1.21-v8+
##  Platform = Raspberry Pi 4 Model B Rev 1.1
##    Uptime = 14 day(s). 5:11:40
## CPU Usage = 22.44% avg over 4 cpu(s) (4 core(s) x 1 socket(s))
##  CPU Load = 1m: 0.35, 5m: 0.45, 15m: 0.43
##    Memory = Free: 0.80GB (21%), Used: 2.94GB (79%), Total: 3.75GB
##      Swap = Free: 2.99GB (100%), Used: 0.00GB (0%), Total: 2.99GB
##      Root = Free: 20.21GB (72%), Used: 7.55GB (28%), Total: 28.98GB
##   Updates = 1 apt updates available.
##  Sessions = 1 session(s)
## Processes = 132 running processes of 32768 maximum processes