JSRule takes >4s to trigger on item state change

[schup011]

Expected Behavior

The different rule approaches (Python script as reference, then for JS UI-based with script, file-based with JSRule, file-based with RuleBuilder) should show similar performance when being triggered by a simple item state change.

Current Behavior

JSRule takes more than 4s longer to put out the log message than the other three approaches:

2023-08-01 18:41:17.211 [INFO ] [jsr223.jython.Jython Telefon-Anruf  ] - Python rule triggered: DIALING
2023-08-01 18:41:17.213 [INFO ] [nhab.automation.script.ui.dae3a200ac] - UI-Rule triggered:  DIALING
2023-08-01 18:41:17.218 [INFO ] [nhab.automation.script.file.anruf.js] - JS(RuleBuilder) rule triggered:  DIALING
2023-08-01 18:41:21.719 [INFO ] [nhab.automation.script.file.anruf.js] - JS(JSrule) rule triggered:  ACTIVE

Possible Solution

Sorry, no idea.

Steps to Reproduce (for Bugs)

Added four rules:

1. Python JSR223 rule
2. UI-based rule, with Run Script/ECMAScript 262 Edition 11/: Added just one line:
3. JSRule rule
4. RuleBuilder rule.

Here is the Python rule:

@rule("Jython Telefon-Anruf", description="Pausiere Wohnzimmer-Player bei Telefon-Anruf", tags=["Telefon", "Squeeze"])# [description and tags are optional]
@when("Item telefonStatus changed to RINGING")
@when("Item telefonStatus changed to DIALING")
def telefon_anruf(event):
    telefon_anruf.log.info("Python rule triggered: " + str(ir.getItem("telefonStatus").state))

Here is the script line for the UI-based rule: console.log("UI-Rule triggered: ", items.telefonStatus.state);

Here is the JSRule:

rules.JSRule({
  name: "Telefon-Anruf",
  description: "Pausiere Wohnzimmer-Player bei Telefon-Anruf",
  triggers: [triggers.ItemStateChangeTrigger('telefonStatus', 'RINGING'),triggers.ItemStateChangeTrigger('telefonStatus', 'DIALING')],
  execute: (event) => {

    console.log("JS(JSrule) rule triggered: ", items.getItem("telefonStatus").state)    

  },
  tags: ["Telefon", "Squeeze"],
  id: "Telefon-Anruf"
});

Here is the RuleBuilder rule:

rules.when().item("telefonStatus").changed().to("DIALING").or().item("telefonStatus").changed().to("RINGING").then(event => {
  console.log("JS(RuleBuilder) rule triggered: ", items.getItem("telefonStatus").state)
 }).build("Telefon-Anruf-Builder", "Pausiere Wohnzimmer-Player bei Telefon-Anruf");

Context

I was recommended to transfer my existing Jython rules to something else as Jython Helper Libraries are not maintained any more. So I started with a very simple rule, took the JSRule approach, and was wondering why it took so long...

Your Environment

openHAB 4.0.0 JS Scripting 4.0.0 Raspberry Pi 4, 2GB, openhabian, Raspbian GNU/Linux 11 (bullseye)

[florian-h05]

Does it always take that long or is it faster the second, the third time etc..?

[schup011]

I did it now for 5-6 times, was always the same, except for the first time, which I did not count because I knew there would be delays. But if you think it could improve with more tries, I can do 10-15 runs, if you want.

[florian-h05]

I cannot reproduce this on any of my systems (1x production (Debian VM) and 2x dev). Even rules that use extensive loops react right now.

I don’t think this is a general issue of the JS Scripting add-on, but rather with your system. What are your Java heap settings?

[schup011]

Sorry, what is Java heap and how can I get the settings? (I am capable of SSH and simple shell commands).

10.08.2023 00:35:24 Florian Hotze @.***>:

I cannot reproduce this on any of my systems (1x production (Debian VM) and 2x dev). Even rules that use extensive loops react right now.

I don’t think this is a general issue of the JS Scripting add-on, but rather with your system. What are your Java heap settings?

— Reply to this email directly, view it on GitHub[https://github.com/openhab/openhab-js/issues/285#issuecomment-1672267427], or unsubscribe[https://github.com/notifications/unsubscribe-auth/AON5TCZEXZQLDJQGTUALN3DXUQGCXANCNFSM6AAAAAA3AB22J4]. You are receiving this because you authored the thread.[Verfolgungsbild][https://github.com/notifications/beacon/AON5TC3TQ3EPHYZXKORPQ7TXUQGCXA5CNFSM6AAAAAA3AB22J6WGG33NNVSW45C7OR4XAZNMJFZXG5LFINXW23LFNZ2KUY3PNVWWK3TUL5UWJTTDVTDKG.gif]

[schup011]

OK, here you are:

openhabian@openhabian:~ $ java -XX:+PrintFlagsFinal -version | grep MaxHeapSize
   size_t MaxHeapSize                              = 268435456                                 {product} {ergonomic}
   size_t SoftMaxHeapSize                          = 268435456                              {manageable} {ergonomic}
openjdk version "17.0.7" 2023-04-18
OpenJDK Runtime Environment (build 17.0.7+7-Raspbian-1deb11u1rpt1)
OpenJDK Client VM (build 17.0.7+7-Raspbian-1deb11u1rpt1, mixed mode, emulated-client)

[schup011]

Are these settings special?

[florian-h05]

Can you please check "Help & About" > "Technological Information" > the bar: How much free heap do you have?

[schup011]

That is what it says:

4 Verfügbare Prozessoren - 97/743MB Verfügbarer Arbeitsspeicher

[florian-h05]

What is using that much heap? However not sure if this is related.

I can only say that I cannot reproduce your peformance issues, as long as there are no similar reports, I think there is no general issue.

[schup011]

Except for openHAB, Influxdb, Grafana and Mosquitto, I have nothing running there. There is one Jython rule that possibly could use quite some memory because it handles large matrices. It runs every 30 min, but it does not (or should not) keep those in memory. I could try unloading (temporarily removing) it, and then check again. But will take some time, I have no access to my production system until 24th August.

[schup011]

System has been set up new, and the delay in triggering could not be reproduced. The scripting with JS appears really slow to me compared to Jython, but that is not an issue to be handled here.

[florian-h05]

System has been set up new, and the delay in triggering could not be reproduced.

Great 👍

The scripting with JS appears really slow to me compared to Jython, but that is not an issue to be handled here.

You mean the first execution of a script, right?

[schup011]

You mean the first execution of a script, right?

No... sorry.

I implemented an optimization algorithm handling "large" matrices (150 x 2500) of numbers. After porting it to JS, I had an execution time increase by factor of 8-10.

It's not doing complicated matrix operations, just filling these matrices step by step, just a few add and mult operations per number, and then reducing them again. I also tested whether the allocation of the whole matrix beforehand vs. dynamically changing the size of the matrix did matter. It doesn't. It is just executing slow. No heavy and special Openhab-specific stuff inside. I started some time profiling but gave up at a certain point. I couldn't really find something that specificly delayed all the rest. js-joda is really slow, but I do not have it inside the loops.

I installed HABApp on a separate Pi (but only PiZeroW), and it's now running on this one, slower by ~factor of 2, but still factor of 5 faster than on my production system (Pi4) with JS.

[florian-h05]

You have also written https://community.openhab.org/t/error-with-openhab-py-script-100-directorytrigger-py-after-update-to-4-0-1/148199/59, right?

I implemented an optimization algorithm handling "large" matrices (150 x 2500) of numbers. After porting it to JS, I had an execution time increase by factor of 8-10.

That sounds like a pretty heavy task compared to what the average rule is doing …

I installed HABApp on a separate Pi (but only PiZeroW), and it's now running on this one, slower by ~factor of 2, but still factor of 5 faster than on my production system (Pi4) with JS.

Glad you found a solution!! That’s the great thing about openHAB, there is not only ONE way to do something, there usually are multiple different ways, so you should usually find one that is suitable for you.

Have you considered putting the logic into a Python script and calling it on command line with the exec action?

[schup011]

Thank you for the hints. Yes, could be an interesting option to completely separate the openhab stuff and the "heavy calculation" things. Today, it is still a little bit "mixed" in the code. That is why I gave HABApp a try, it was easy to set up. I really like the JS Scripting, it is amazingly convenient to use, and I ported all my rules to it (except for that one :-). ), even very old DSL rules which I had not touched before since 3 years.

[schup011]

BTW: I never had significant execution time increases at the first run of a JS script. It just starts with a delay of ~10-20 seconds.

[florian-h05]

Yes, could be an interesting option to completely separate the openhab stuff and the "heavy calculation" things.

FYI: I have a Python script that creates a drawing with my house, sun & moon position, shadow of the house etc., which I run using actions.Exec.executeCommandLine from a rule builder rule. Works fine.

I really like the JS Scripting, it is amazingly convenient to use, and I ported all my rules to it (except for that one :-). ), even very old DSL rules which I had not touched before since 3 years.

Great to hear!

[schup011]

Yes, could be an interesting option to completely separate the openhab stuff and the "heavy calculation" things.

FYI: I have a Python script that creates a drawing with my house, sun & moon position, shadow of the house etc., which I run using actions.Exec.executeCommandLine from a rule builder rule. Works fine.

I really like the JS Scripting, it is amazingly convenient to use, and I ported all my rules to it (except for that one :-). ), even very old DSL rules which I had not touched before since 3 years.

Great to hear!

Thanks again for the tipp to run a separate Python script. I have realized it with the Exec binding. Great thing is that it can run asychronously. One JS rule triggers the start, another rule analyzes the results. It was quite an effort to separate everything to a "calculation-only" function within Python, and even more, to manage the handling of arguments (time series of PV forecasts, lists of planned next regular EV drives). But now it works, and it does it amazingly fast, even approximately factor 10 faster than the old Jython rule. Seems that I learned a lot about efficient code during this port :-) . I think quite an improvement is doing only one query to the Influx persistence database for getting the forecast, instead of querying ~40-100 single points separately. Thus, I only depend on an OpenHAB installation with working JS scripting automation, and a working Python installation on the same machine. Nothing special.

[florian-h05]

It was quite an effort to separate everything to a "calculation-only" function within Python, and even more, to manage the handling of arguments (time series of PV forecasts, lists of planned next regular EV drives).

FYI you probably don't need to pass everything, you can request it right from your Python script. For example my Python script is doing API requests to openHAB and to InfluxDB, see https://github.com/florian-h05/openhab-conf/blob/main/scripts/shaddow.py.

But now it works, and it does it amazingly fast, even approximately factor 10 faster than the old Jython rule.

That sounds absolutely insane!

[schup011]

I really wanted to separate it in order not to have any cross-dependencies. So the interface is just parameters in json format and there are only very basic requires like datetime in Python. I just spent too much time in the past because of not-any-more-maintained libraries outside of openhab. And I also found it a good idea to have something like a "heavy-maths" core and all the high-level java / jvascript stuff around it.

[florian-h05]

That's a really good argument to minimize dependencies on external libs.

Reminds me of the Jython helper library, whose maintainer disappeared and unfortunately it was not part of the openHAB project.

[schup011]

Yes, before the move to Javascript I was totally relying on Jython...