Basic Delay

  • Platform information:
    • Hardware: PI 4B x86
    • OS: openhabian 32Bit
    • Java Runtime Environment: OOTB 17
    • openHAB version: 4.0.1
  • Issue of the topic: delay

Hi,
i came across first time as I (re)tested my EchoControl Binding in OH4 (as far as I remember it was quite faster in OH3)
But testing further more the delay is not created by the Binding, more or less it is created by the Script itself.

I have created a Rule which is executed every Second:

configuration: {}
triggers:
  - id: "1"
    configuration:
      cronExpression: 0/1 * * * * ? *
    type: timer.GenericCronTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      blockSource: <xml xmlns="https://developers.google.com/blockly/xml"><block
        type="oh_log" id="#E]@1@MH*LMA{KFGL+Rf" x="362" y="167"><field
        name="severity">info</field><value name="message"><shadow type="text"
        id="zVWqkh%L@g`hZvNhovYy"><field name="TEXT">abc</field></shadow><block
        type="text" id="d}7VU9qffFU0hr8p$OOk"><field name="TEXT">This is anoterh
        Second...</field></block></value></block></xml>
      type: application/javascript
      script: |
        console.info('This is anoterh Second...');
    type: script.ScriptAction

==> /var/log/openhab/openhab.log <==
2023-11-28 13:26:53.234 [INFO ] [openhab.event.RuleUpdatedEvent ] - Rule ‘46869ac3a2’ has been updated.

2023-11-28 13:27:17.142 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.146 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.148 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.151 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.153 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.156 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.158 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.161 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.164 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.166 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.168 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.171 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:17.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:18.471 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:19.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:20.471 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:21.471 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:22.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:23.473 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:24.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:25.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:26.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:27.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:28.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:29.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:30.473 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:31.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:32.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:33.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…
2023-11-28 13:27:34.472 [INFO ] [nhab.automation.script.ui.46869ac3a2] - This is anoterh Second…

As you might see it takes some initial time untill the script is executed at the (nearly) “correct” timestamp.

My two questions:

  1. What are the reasons why it takes so long (initially)?
  2. How can I optimize these 472ms?

We know for sure there is an issue with the first run of a script on 32-bit ARM architecture machines (e.g. RPis). Given that RAM is rarely as limited of a resource on x86 I suspect most users run 64-bit there. So maybe this problem also exists on 32-bit across the board, not just ARM.

Anyway, the problem is the injection of the JS Scripting helper library into the script happens on that first run and it can take quite some time for that to happen.

There is preliminary evidence that running on 64-bit Java or the GraalVM JRE (which only comes in 64-bit) provides an increase of 10x for that first run. That takes what some are seeing on RPis of 20 seconds for that first run of the script down to a manageable 2 seconds. I’ve always run 64-bit and I see no noticeable delay in the execution of my scripts.

This delay only occurs the first run after a reload of the rule. So you could manually trigger the rule to get that first run over with. After that the rule should only take milliseconds to run.

Note that Blockly “compiles” into JS Scripting so all the above applies to Blockly too.

The best I can suggest is to run with 64-bit or try a different rules language like jRuby in cases where this matters.

If you mean how to make it more precise I don’t think you can. Quartz cron does not guarantee millisecond accuracy, only accuracy to the nearest second. If you need millisecond accuracy you need to use a Timer instead of a cron expression.

But it does appear that the scheduler will do it’s best to make sure as close to a second passes between runs of the rule.

Looking at the logs the first time that the rule ran it took 24 seconds to run. In that time, the rule was triggered by the cron 11 more times for a total of 12 triggers. Once that first instance finished loading and running the remaining 11 queued triggers worked off spending one to two milliseconds per run until 13:27:17.472.

After that each run of the rule is within on millisecond of each other.

Thanks for your quick Reply!

So you mean the delta is done during triggering allready? If so I can live with :slight_smile:

I only used 32Bit openhabian Image, course it mentioned in the recommendations (regarding RAM) :thinking:

The initial delay in script execution may stem from system load or openHAB configuration. To optimize the 472ms delay, check system resources, review JVM settings, and streamline the JavaScript code for efficiency.