About all I can recommend is gather what information you can and file an issue. No one else is reporting this specific problem so :shrug.
OK, thanks.
And what you assumed was right. I tried the UI-based approach and it didn’t have any significant delay with respect to Python. So must have to do something with file-based in general or JSRule approach.
It’s really funny: I have now four rules doing this one log entry when the phone status changes to status DIALING. This is the output:
2023-08-01 18:23:06.518 [INFO ] [jsr223.jython.Jython Telefon-Anruf ] - Python rule triggered: DIALING
2023-08-01 18:23:06.524 [INFO ] [nhab.automation.script.ui.dae3a200ac] - UI-Rule triggered: DIALING
2023-08-01 18:23:06.528 [INFO ] [nhab.automation.script.file.anruf.js] - JS(RuleBuilder) rule triggered: DIALING
2023-08-01 18:23:10.528 [INFO ] [nhab.automation.script.file.anruf.js] - JS(JSrule) rule triggered: ACTIVE
So every approach except for the JSRule one is working fast, some delay occurs for the JSRule rule. JSRule is so slow that the status in the meanwhile has changed to ACTIVE. 
Definitely file an issue. What’s really odd is behind the scenes rule builder uses JSrule so it’s definitely odd.
Should I file it in GitHub? If so, where exactly?
1 Like
Ok, did the bug report on GitHub:
1 Like
Nevertheless, I started porting very simple Jython rules to JS with the rule builder. So far nothing I am missing. I will have to dig more deeply into how to use libraries and so on.
I believe there is a section in the docs. The tl;dr is you’ll have to create an npm module (it’s not hard) and put it as a folder under $OH_CONF/automation/js/node-modules. Then you use require to bring it into your rule.
For third party libraries, they can be installed by npm.
I seem to have some serious performance issues. Maybe I need help to check what is wrong with my system.
I am on the path of porting rules from Python to JS. Works fine so far, but most of the rules don’t have any relevance regarding performance.
But some of them really have. Now I have ported one script that reads PV forecast data (just 72 lines via HTTP) and then calculates some values and writes them into the influxdb database.
With the Python version that took 5s (most of that being response times from the PV API and influxdb), with JS script it took more than 30s. Then I simplified a little bit and compared those two scripts:
Python
test_PV_forecast.log.info("Start Python Rule PV-Vorhersage")
for fieldNo in range(0, 5000):
milliDate = ZonedDateTime.now().toInstant().toEpochMilli()
test_PV_forecast.log.info("Completed penalty code.")
JSScript
console.log("Error retrieving PV forecast");
for (fieldNo=0;fieldNo<5000;fieldNo++)
{
milliDate = time.ZonedDateTime.now().toInstant().toEpochMilli();
}
console.log("Completed penalty code.");
Result is: Python takes 0.4s, JSScript 49s.
JSScript does also not improve after a couple of calls.
Rich, do you have an idea what checks I can do (assuming that this is not a normal behavior, other users should have noted that)?
Thanks a lot!
I do know that the one thing in general that takes the longest in some languages is date time operations.
And personally, any time I see toEpochMilli it’s a code smell. You should almost never be working with epoch.
I ran the above code and it takes about a second (give or take a couple hundred msec).
The JS ZonedDateTime is a completely separate implementation from the Java ZonedDateTime (which is what your Jython code is using).
2023-08-07 15:08:50.757 [INFO ] [nhab.automation.script.ui.scratchpad] - Error retrieving PV forecast
2023-08-07 15:08:51.844 [INFO ] [nhab.automation.script.ui.scratchpad] - Completed penalty code.
...
2023-08-07 15:09:03.252 [INFO ] [nhab.automation.script.ui.scratchpad] - Error retrieving PV forecast
2023-08-07 15:09:04.555 [INFO ] [nhab.automation.script.ui.scratchpad] - Completed penalty code.
Not super but not 49 seconds either.
It’s not clear what you are doing with that epoch but I wouldn’t be surprised if keeping it a ZonedDateTime were more performant. It does seem to shave about 200 msec from my runs which should shave around 8 seconds from your runtime.
I just took randomly a line of code and repeated that 5000 times. In my code, I used that one to write to influxdb (but only 144 times). Certainly, there is a better way to do that, but that is not my question. I can live with a few hundred ms. But the difference between Python and JS Script is my problem, and obviously also the difference between your system and mine. Something seems to be wrong with mine.
I have one solar EV charging optimization algorithm that takes about 90s to 180s in Python. I cannot afford a runtime 5-10 times more.
I couldn’t say. My machine isn’t an RPi but it’s nothing special. I wouldn’t expect these long runtimes for rules on anything but a really underpowered machine like an RPi 2b or RPi 0w. I’ve not seen any reports of exceptionally long runtimes from any other users on this forum outside of the initial run of the rule. And even for that there is a PR open (I think it hasn’t been merged yet) to fix a bug in the caching which will improve that.
I wouldn’t begin to guess where to look for why these rules are taking so much longer for you. You can try jRuby or Groovy and see if they are more performant.
My system is a RPi 4 with 2 GB.
JRuby takes 300ms for the same code example. Something is wrong with my JS Script, would be happy to somehow find the root cause, but I have no clue where to look at. Does it make sense to increase log level?
Possibly. I’m not sure what that would show. The problem isn’t waiting for the rule to start, it’s after the rule is already running. So there wouldn’t be anything from OH or the add-on being logged at that point. Those parts of OH will be waiting for your rule to complete.
It might just be, on an RPi at least, heavily looping code like that just isn’t performant in GraalVM JS. That is kind of an edge case for OH rules so it’s not surprising the problem hasn’t been seen before.
@florian-h05 Any idea from your side about this performance issue? Maybe this is connected with the strange finding I reported as a bug where JS rule and rule builder were very different in performance. Maybe it’s just my system that is somehow weird, and I would really appreciate to get some hints how to track this down.
Sorry, Rich, but I am not really convinced.
Why should just JavaScript be orders of magnitude more slowly?
Any suggestions for other code I could test for performance, that is not heavily looping?
BTW: The InfluxDB HTTP API I am using to write future values of PV forecast into the database (yes, you can use time values in the future there) does only accept epoch seconds, milliseconds or nanoseconds, as far as I know. Of course I could use something else to store the next 72h of forecast. But writing it into the Persistence database is convenient as it remains persisted for evaluating afterwards how good the forecast really was.
The other languages (Python, JRuby) could do thousands of toEpoch conversions within less than a second… I think I rather have a general JS scripting performance problem.
Is it possible that for some reason no Javascript caching works at all on my system?
I see no improvement from the first to the subsequent runs.
What logging option could be suitable to track this?
I increased log level of the JS scripting add on to TRACE, but could not see anything strange. This is shown in the log when I save the script file:
2023-08-08 10:45:31.150 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2023-08-08 10:45:31.183 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2023-08-08 10:45:31.186 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2023-08-08 10:45:31.193 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
2023-08-08 10:46:03.776 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Successfully initialized GraalJS script engine.
After that, no more log output from the scripting add-on could be seen.
As you are the only one reporting this problem to date, at this point you are the expert on what does and does not take a long time to run.
There is a PR open that didn’t make it into OH 4 to allow publishing future values to persistence through the persistence API so this sort of work around should not be required in the future.
No doubt but you are also the only one who can generate this extreme difference in runtimes. As you saw, while my machine ran the rule more slowly than I would have expected, it’s certainly not so slow as to be a problem. I am running on a VM on an Intel processor but all things considered, it’s not 50 times the processing power of an RPi 4.
I don’t know what other loggers you could enable. But I do know that while the rule is running, the add-on and rule engine is blocked waiting for the rule to complete. I wouldn’t expect there to be any logging taking place after the rule is triggered so I’m not sure how much can be learned in this case from the logs.