I updated to OH 3.4 and took the opportunity to convert all my rules from using Nashhorn to JS Scripting. I’m running OH on an RPI3.
When using the JS Scripting version of the rules, OH is so much slower to start-up and get to the point that all my initialisation has completed. Its gone from ~3 minutes to ~8 minutes.
It looks to be using more CPU during start-up and the java process is using ~20% more memory.
Triggering a rule for the first time after start-up has delays of over 20 seconds. After about 10 minutes the UI stops working and OH is unusable.
The openhab log has a lot of these messages when starting up:
[ERROR] [ipt.internal.ScriptEngineManagerImpl] - ScriptEngine for language 'application/javascript;version=ECMAScript-2021' could not be found for identifier: 90826c44-30e5-4e92-badc-f3a1f8f56f6f
I’ve swapped back to using my Nashhorn version of the rules (by replacing the automation_rules.json file) and they seem fine on 3.4.
Is this expected or is there anything I can do to help debug?
I think this is a openHAB Core issue, where the rules try to load up before the JS Scripting add-on has started. @J-N-K Are you aware of this problem? IIRC @rlkoshak is experiencing the same issue with the Nashorn add-on on 4.0-SNAPSHOT.
This is not expected, the error message comes from a known problem in openHAB core, but I did not expect the UI rules to kill openHAB later. I’ve been using file-based JS Scripting rules on my Pi 3 for over a half year and never had any problems. I am wondering what’s the problem with the UI based rules: The startup problem due to core or is there another problem in JS Scripting??
Can you please provide me more logs, especially when openHAB stops working and is unusuable. Is anything logged then?
No, I’m not aware of any issues related to that. What exactly do I need to do to reproduce it? And can you please open an issue in openhab-core and provide STR there? Thanks.
No, I’m not seeing any performance changes. There’s an issue that the Nashorn rules load before Nashorn is available and therefore system level triggered rules don’t run, but the rules themselves run as fast as they ever have.
Though I’m running on a beefy machine so maybe I’m not noticing it.
All my rules are in the UI though. That could make a difference too perhaps?
And I’m getting a different error. It’s comlaining that application/javascript could not be found, not JS Scripting.
I related to the issue that the rules load before Nashorn is available, not the instabilities.
I am not sure if that would make a difference, but @MikeJMajor also seems to use UI rules (as he says he edited his automation_rules.json).
@rlkoshak Out of interest: What are you using for your UI rules? Graal or Nashorn? How many UI rules do you have, how stable are them and how much heap space do you have?
A mix. A bunch of my rule templates were written to work in both but still use the application/javascript MIME type. I plan on upgrading those to JS Scripting rather than Nashorn with @runtime imported but haven’t gotten around to it yet and need to figure out a proper upgrade path for end users.
I have 51 rules and 21 scripts. I have 15 script actions/conditions that are application/javascript and 64 script actions/conditions that are application/javascript;version=ECMAScript-2021 and a smattering of rules that are straight UI.
All rules are in the UI.
A few of my rules run at least once every few seconds. After the initial errors during startup they run smoothly and without error of delay.
For example, here are a few events.log entries for my humidifier_threshold rule which is pretty complex running in Nashorn.
configuration:
comparison: <
dnd_end: 07:00
limit: 4h
threshold: 35
script: humidity_alert
dnd_start: 22:00
group: MinIndoorHumidity
triggers:
- id: "1"
configuration:
itemName: MinIndoorHumidity
type: core.ItemStateChangeTrigger
conditions:
- inputs: {}
id: "2"
configuration:
itemName: MinIndoorHumidity
state: 25 %
operator: <
type: core.ItemStateCondition
actions:
- inputs: {}
id: "3"
configuration:
type: application/javascript
script: >
if(typeof(require) === "function") Object.assign(this,
require('@runtime'));
var logger = Java.type("org.slf4j.LoggerFactory").getLogger("org.openhab.model.script.Threshold MinIndoorHumidity");
var ZonedDateTime = Java.type("java.time.ZonedDateTime");
this.logger.debug("Processing initialization data");
var group = "MinIndoorHumidity";
var limit = "24h";
var alertScript = "humidity_alert";
var filterFunc = function(i) { return i.state.class !== UnDefType.class && i.state.floatValue() < 25.0; };
var dndStartStr = "22:00";
var dndStartStrs = dndStartStr.split(":");
var dndStart = ZonedDateTime.now()
.withHour(parseInt(dndStartStrs[0]))
.withMinute(parseInt(dndStartStrs[1]))
.withSecond(0)
.withNano(0);
var dndEndStr = "07:00";
var dndEndStrs = dndEndStr.split(":");
var dndEnd = ZonedDateTime.now()
.withHour(parseInt(dndEndStrs[0]))
.withMinute(parseInt(dndEndStrs[1]))
.withSecond(0)
.withNano(0);
this.logger.debug("Done, determining if it's time to call the script");
// TODO Move to library when able
/**
var OPENHAB_CONF = java.lang.System.getenv("OPENHAB_CONF");
load(OPENHAB_CONF+'/automation/lib/javascript/community/rateLimit.js');
load(OPENHAB_CONF+'/automation/lib/javascript/personal/alerting.js');
load(OPENHAB_CONF+'/automation/lib/javascript/personal/metadata.js');
*/
/**
* A class that will limit how often an event can occur. One calls run and pass
* a time_utils when to indicate how long before the call to run will run again.
* If run is called before that amount of time then the call is ignored.
*/
var RateLimit = function() {
'use strict';
// var OPENHAB_CONF = java.lang.System.getenv("OPENHAB_CONF");
this.ZonedDateTime = Java.type("java.time.ZonedDateTime");
this.log = Java.type("org.slf4j.LoggerFactory").getLogger("org.openhab.model.script.Rules.RateLimit");
this.log.debug("Building the RateLimit object.");
// load(OPENHAB_CONF+'/automation/lib/javascript/community/timeUtils.js');
this.until = this.ZonedDateTime.now().minusSeconds(1);
this.log.debug("RateLimit is ready to operate");
}
// reproduced from timeUtils, truncated to only parse duration strings
RateLimit.prototype.toDateTime = function(when) {
var Duration = Java.type("java.time.Duration");
var ZonedDateTime = Java.type("java.time.ZonedDateTime");
var dur = null;
var dt = null;
var regex = new RegExp(/[\d]+[d|h|m|s|z]/gi);
var numMatches = 0;
var part = null;
var params = { "d": 0, "h": 0, "m":0, "s":0, "z":0 };
while(null != (part=regex.exec(when))) {
this.log.debug("Match = " + part[0]);
numMatches++;
var scale = part[0].slice(-1).toLowerCase();
var value = Number(part[0].slice(0, part[0].length-1));
params[scale] = value;
}
if(numMatches === 0){
this.log.warn("Could not parse any time information from '" + timeStr +"'. Examples of valid string: '8h', '2d8h5s200z', '3d 7m'.");
}
else {
this.log.debug("Days = " + params["d"] + " hours = " + params["h"] + " minutes = " + params["m"] + " seconds = " + params["s"] + " msec = " + params["z"]);
dur = Duration.ofDays(params["d"]).plusHours(params["h"]).plusMinutes(params["m"]).plusSeconds(params["s"]).plusMillis(params["z"]);
}
if(dur !== null) {
dt = ZonedDateTime.now().plus(dur);
}
return dt;
},
/**
* Function called to attempt to run the passed in function. If enough time has
* passed since the last time run was called func is called. If not the call is
* ignored.
*
* @param {function} func called if it's been long enough since the last call to run
* @param {*} when any of the durations supported by time_utils.
*/
RateLimit.prototype.run = function(func, when){
ZonedDateTime = Java.type("java.time.ZonedDateTime");
var now = ZonedDateTime.now();
if(now.isAfter(this.until)) {
this.log.debug("It has been long enough, running the function");
this.until = this.toDateTime(when);
func();
}
else {
this.log.debug("It is still too soon, not running the function");
}
}
// END TODO
var alertGenerator = function(nullItems, nullItemLabels, threshItems, threshItemLabels, filterFunc){
return function(){
// Only call the rule if the Group still doens't meet the criteria.
// It's possible that the function is delayed some hours before it runs and the threshold may no longer be a problem.
if(filterFunc(ir.getItem(group))) {
// Get the RuleManager
var FrameworkUtil = Java.type("org.osgi.framework.FrameworkUtil");
var ScriptHandler = Java.type("org.openhab.core.automation.module.script.rulesupport.shared.ScriptedHandler");
var _bundle = FrameworkUtil.getBundle(ScriptHandler.class);
var bundle_context = _bundle.getBundleContext();
var classname = "org.openhab.core.automation.RuleManager";
var RuleManager_Ref = bundle_context.getServiceReference(classname);
var RuleManager = bundle_context.getService(RuleManager_Ref);
var map = new java.util.HashMap();
map.put("nullItems", nullItems);
map.put("nullItemLabels", nullItemLabels);
map.put("threshItems", threshItems);
map.put("threshItemLabels", threshItemLabels);
RuleManager.runNow(alertScript, true, map);
}
else {
this.logger.info("No longer violating threshold");
}
}
}
var getLabels = function(list) {
this.logger.debug("Getting the labels");
var Collectors = Java.type("java.util.stream.Collectors");
return list.stream()
.map(function(i) { return i.label; })
.collect(Collectors.joining(", "));
}
var getItems = function(group, filterFunc) {
this.logger.debug("Getting the Items");
var Collectors = Java.type("java.util.stream.Collectors");
return ir.getItem(group)
.members
.stream()
.filter(filterFunc)
.collect(Collectors.toList());
}
var callGenerator = function(group, filterFunc) {
this.logger.debug("Generating the script calling function");
return function() {
this.logger.debug("Calling the script");
// TODO Expand to handle non-numeric states
var nullItems = getItems(group,function(i) { return i.state.class == UnDefType.class; });
var nullItemLabels = getLabels(nullItems);
var threshItems = getItems(group, filterFunc);
var threshItemLabels = getLabels(threshItems);
this.rl.run(alertGenerator(nullItems, nullItemLabels, threshItems, threshItemLabels, filterFunc), limit);
this.timer = undefined;
}
}
this.rl = (this.rl === undefined) ? new RateLimit(): this.rl;
var now = ZonedDateTime.now();
// DND spans midnight, move end time to tomorrow if we are before midnight
if(dndEnd.isBefore(dndStart) && now.isAfter(dndStart)) {
// Move dndEnd to tomorrow
this.logger.debug("Moving end time to tomorrow");
var tomorrow = now.plusDays(1);
dndEnd = dndEnd.withYear(tomorrow.getYear())
.withMonth(tomorrow.getMonthValue())
.withDayOfMonth(tomorrow.getDayOfMonth())
.withZoneSameLocal(tomorrow.getOffset());
}
// if DND spans midnight, move the start time to yesterday if we are after midnight
else if(dndEnd.isBefore(dndStart) && now.isBefore(dndStart)) {
// Move dndStart to yesterday
this.logger.debug("Moving start time to yesterday");
var yesterday = now.minusDays(1);
dndStart = dndStart.withYear(yesterday.getYear())
.withMonth(yesterday.getMonthValue())
.withDayOfMonth(yesterday.getDayOfMonth())
.withZoneSameLocal(yesterday.getOffset());
}
this.logger.debug("Now: " + now + " Start DND Time: " + dndStart + " End DND Time: " + dndEnd);
var isDnd = now.isAfter(dndStart) && now.isBefore(dndEnd);
this.logger.debug("Is DND = " + isDnd);
// Immediately call when no delay is required
if(dndStartStr == dndEndStr || !isDnd) {
this.logger.debug("Not during a DND time, calling script immediately");
callGenerator(group, filterFunc)();
}
// Schedule a timer to run at the end of the dnd time
else if(this.timer === undefined){
var ScriptExecution = Java.type("org.openhab.core.model.script.actions.ScriptExecution");
this.logger.debug("Creating a timer to call the script after the DND time.");
this.timer = ScriptExecution.createTimer(dndEnd, callGenerator(group, filterFunc));
}
else {
this.logger.debug("Timer already exists to call the script.");
}
type: script.ScriptAction
configuration:
dndEnd: 08:00
reschedule: false
defaultTimeout: PT5m
invert: true
alertRuleUID: service_offline_proc
groupTriggers: ServiceStatuses
dndStart: 22:00
repeatPeriod: PT12h
timeoutMetadata: rem_time
alertState: OFF
triggers:
- id: "1"
configuration:
groupName: ServiceStatuses
type: core.GroupStateChangeTrigger
conditions: []
actions:
- inputs: {}
id: "2"
configuration:
type: application/javascript;version=ECMAScript-2021
script: >
var {loopingTimer, timeUtils} = require('openhab_rules_tools');
var logger = log('rules_tools.'+ruleUID);
// Rule Properties
var alertState = "OFF";
var defaultTimeout = "PT5m";
var timeoutMetadata = "rem_time";
var alertRuleUID = "service_offline_proc";
var repeatPeriod = "PT12h";
var reschedule = false;
var dndStart = "22:00";
var dndEnd = "08:00";
var noAlertPeriod = (dndStart == dndEnd);
var isAlertState = (curr) => { return (true) ? (curr == alertState) : (curr != alertState); };
var TIMERS_KEY = ruleUID+'_timers';
var TIMER_BUFFER = 600*1000000; // Nano seconds
// If you edit this rule, run it manually to clear out the cache or else
// errors will occur complaining about the context being closed.
//if(this.event === undefined) {
// logger.info('Resetting looping timers');
// cache.put(TIMERS_KEY, null);
//}
//else {
var timers = cache.private.get(TIMERS_KEY, () => new Map());
var item = event.itemName;
var state = event.itemState.toString();
// Temporary work around until PR to fix openhab-js gets merged
var isBetweenTimes = function (t, start, end) {
var startTime = time.toZDT(start).toLocalTime();
var endTime = time.toZDT(end).toLocalTime();
// const currTime = this.toLocalTime();
var currTime = time.toZDT(t).toLocalTime();
// time range spans midnight
if (endTime.isBefore(startTime)) {
return currTime.isAfter(startTime) || currTime.isBefore(endTime);
} else {
return currTime.isAfter(startTime) && currTime.isBefore(endTime);
}
};
// Looks at the currently scheduled timers and makes the time for a new one
// doesn't overlap.
// Loop through the timers and check the timeout time against the existing timers.
// If it's within half a second of one, move the timer forward 500 msec.
// If the timeout was moved at least once, loop through the timers again to make
// sure we didn't move it on top of an already checked timer.
var avoidOverlapping = (timeout) => {
let rval = time.toZDT(timeout);
let recheck = true;
while(recheck) {
recheck = false;
logger.debug('There are ' + timers.size + ' timers already scheduled');
timers.forEach((value, key) => {
if(!value.hasTerminated() &&
rval.isClose(time.toZDT(value.timer.getExecutionTime()), time.Duration.ofMillis(250))) {
logger.debug('Found timer ' + value.name + ' that has not terminated and is too close to timeout');
rval = rval.plusNanos(TIMER_BUFFER);
recheck = true;
}
});
}
return rval;
};
// Moves the alert time to the end of the DND period if the timeout is
// in the DND period. Then it makes sure it's at least TIMER_BUFFER nanosecs
// from any existing timer
var generateAlertTime = (timeout, dnds, dnde) => {
let rval = time.toZDT(timeout);
if(isBetweenTimes(rval, dnds, dnde)) { // temporary work around until PR gets merged to openhab-js
logger.debug('Timer is scheduled during DND, moving to end of DND');
rval = dndEnd;
if(time.toZDT(dndEnd).isBefore(time.toZDT())) {
rval = timeUtils.toTomorrow(dndEnd);
}
}
return avoidOverlapping(rval);
};
// This returns the function called by the LoopingTimer. LoopingTimer will
// reschedule the timer based on what the function passed to it returns. If
// a duration is returned it will be reschuled for that time into the future.
// If null is returned the looping stops.
var sendAlertGenerator = (alertItem, repeat, dnds, dnde) => {
return () => {
const currState = items.getItem(alertItem).state;
logger.debug('Timer expired for ' + alertItem + ' with dnd between ' + dnds + ' and ' + dnde);
// Calculate the next repeat time
let repeatTime = (repeat) ? generateAlertTime(repeat, dnds, dnde) : null;
// Send alert
if(isAlertState(currState)) {
logger.debug('Item is still in an alert state.')
rules.runRule(alertRuleUID, { 'alertItem': alertItem, 'currState': currState }, true);
}
// Cancel the repeats
else {
logger.debug('Item has returned to the non-alert state');
repeatTime = null;
}
// If there is no repeat delete the timer from the map
if(!repeatTime) {
logger.debug('No repeat time');
timers.delete(alertItem);
}
logger.debug('Rescheduling for ' + repeatTime);
return repeatTime;
};
};
logger.debug('Running door alert rule with: \n' +
' item: ' + item + '\n' +
' state: ' + state + '\n' +
' alertState: ' + alertState + '\n' +
' invert: ' + true + '\n' +
' defaultTimeout: ' + defaultTimeout + '\n' +
' repeatPeriod: ' + repeatPeriod + '\n' +
' dndStart: ' + dndStart + '\n' +
' dndEnd: ' + dndEnd + '\n' +
' noAlertPeriod: ' + noAlertPeriod + '\n' +
' alertRuleUID: ' + alertRuleUID);
// Returned to alertState and timer exists, cancel the looping timer
if(!isAlertState(state) && timers.has(item)) {
logger.debug(item + ' has returned to a non-alerting state of ' + state + ', canceling the timer if it exists.');
timers.get(item).cancel();
timers.delete(item);
}
// Item changed to a not alertState, create a looping timer if one doesn't already exist
else if(isAlertState(state)) {
logger.debug(item + ' is in the alert state of ' + state);
// There shouldn't be a Timer if the Item just changed to the alertState, log to show
// something went wrong.
if(timers.has(item)) {
logger.warn(item + ' state is now ' + state + ' but an alert timer already exists! This should not have happened!');
}
// Schedule a looping timer to start at the initial timeout (from metadata) and repeat
// on repeatPeriod
else {
const metadata = items.getItem(item).getMetadataValue(timeoutMetadata);
let timeout = generateAlertTime((metadata) ? metadata : defaultTimeout, dndStart, dndEnd);
timers.set(item, new loopingTimer.LoopingTimer()); // add name as argument when openhab_rules_tools is updated to support that
logger.debug('Starting timer for ' + item + ' with ' + timeout);
timers.get(item).loop(sendAlertGenerator(item, repeatPeriod, dndStart, dndEnd), timeout);
}
}
//}
type: script.ScriptAction
In both cases they pretty consistently take 1 msec to run even from the initial start of OH.
I’m not sure how to show the heap space in use by Java. I’ve never personally encountered a memory leak in OH so never learned. I run OH in Docker on an Ubuntu VM and it currently is sitting at 5883M VIRT, 2225M RES and 25576M SHR (according to htop). But the Docker container explodes the memory requirements. I’ve tried to ruin jsstat but get an illegal argument exception. I think the container isolation interferes with jsstat.
Wow, thanks for the very detailed answer.
Are you on openHAB 4?
You‘ve already migrated much code. I am missing a few Nashorn UI scripts as well, but most of my JS rules are file based JS Scripting.
That‘s my experience as well, but my openHAB is also on a more powerful system than a Raspberry Pi. When I started to work with JS Scripting, I was on a Pi 3, and yes, initial loading took a little bit longer as with Nashorn, but rule execution was much faster.
If you are logged in to MainUI as admin user, you can go to „Help & About“, „Technical Information“ and you‘ll see some stats that say something like „133/500 MB available memory“ (Sorry if those names aren‘t 100% percent correct, I can only translate them from my German UI).
Yes, once the zwave issues got resolved I’m able to hum along on OH 4 without problem. It’s been a week or so since I last upgraded though so maybe there’s something up in the snapshots since last Wednesday.
Awesome! I knew it tracked some system stats but didn’t know the heap was in there.
4 available processors - 546/1167MB available memory
I’ve not tracked that over time but the system overall RAM usage has been pretty stable over time.
I can’t go back any farther because I have Zabbix configured to throw out data older than two days. But this is inline with how my RAM usage looks every time I look at it.
Again, this is a VM running all my home automation services in Docker containers including Zabbix (though the PostgreSQL is running on a different VM on the same box). The system load is spiky but that’s expected from Zabbix.
Thanks for the stats, now all my worries about memory leaks and instabilities due to JS Scripting are gone. It is just a matter how many scripts/rules you have and how much memory: the more JS scripts, the more memory is required.
I’m not sure, on my Pi 3 all my file based JS rules were working fine, but I think that I increased the max heap limit. (I am now on a VM, but that has other reasons.)
If I recall correctly, openHABian sets the maximum heap to 320MB or something about this. Maybe you can check your /etc/default/openhab file and increase the heap limit to 500MB. IMO this still works with 1 GB of RAM.
Unfortunately, yes that seems right. All my heap dumps showed that there is no memory leak left (as long as the rules don’t contain errors), this is normal heap usage from GraalVM.
It might be possible to reduce heap usage and increase performance by sharing more resources, I can have a look into this but I can’t promise anything.
I don’t use openhabian, but I did have the minimum heap size set to 350mb. Increasing that to 500mb makes it more stable and prevents the “VM thread” using 100% CPU.
However, the garbage collection now does a lot more frequent large collections with noticeable pauses of several seconds.
I’ll need to get some better hardware before moving over to JS scripting.
Testing with the latest 4.0 snapshot has shown some good improvement on my RPI2 test system.
The start-up time is still twice as slow compared to Nashorn or Groovy, but the heap usage is now only about 90mb bigger. Also the actual heap usage is much better, filling up at a similar rate to Nashorn/Groovy and only triggering minor GCs. Previously it was constantly doing full GCs with noticeable pauses.
