JavaScript memory/stability issues

Setup, Configuration and Use Scripts & Rules
,
#1

Hi,

I’m taking the first baby steps towards migrating my DSL rules to JavaScript. Unfortunately I’m starting to see a pattern: Every time I edit and trigger a rule a few times, my system becomes very unstable and runs out of Java heap space. I’m running openHABian:

openhabian@openHABianPi:/etc/openhab $ uname -a
Linux openHABianPi 4.19.66-v7+ #1253 SMP Thu Aug 15 11:49:46 BST 2019 armv7l GNU/Linux

on a Raspberry Pi 3 with openHAB 3.2.

So far I have only one rule:

/etc/openhab/automation/js/test.js:

rules.JSRule({
  name: "Danfoss boost new",
  description: "Push notification when boost is triggered on Danfoss Air",
  triggers: [triggers.ItemStateChangeTrigger('Test', 'OFF', 'ON')],
  execute: data => {

    var item = items.getItem("DanfossHRV_Humidity");
    var danfossRecentHumidity = item.history.historicState(time.ZonedDateTime.now().minusMinutes(22));

    var body = "Boost er aktiveret. Luftfugtighed: ${danfossRecentHumidity} %";
    console.log(body);
  }
});

After editing and triggering this rule just a few times, this happened:

2021-12-29 14:28:55.620 [INFO ] [rulesupport.loader.ScriptFileWatcher] - Loading script '/etc/openhab/automation/js/test.js'
2021-12-29 14:29:09.251 [INFO ] [org.openhab.automation.script.rules ] - Adding rule: Danfoss boost new
2021-12-29 14:29:14.840 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Test' received command ON
2021-12-29 14:29:17.319 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Test' changed from OFF to ON
2021-12-29 14:29:33.986 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Test' received command ON
2021-12-29 14:29:34.110 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Test' changed from OFF to ON
2021-12-29 14:29:56.353 [INFO ] [rulesupport.loader.ScriptFileWatcher] - Loading script '/etc/openhab/automation/js/test.js'
2021-12-29 14:30:10.029 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@bbd51' takes more than 5000ms.
2021-12-29 14:30:26.992 [INFO ] [org.openhab.automation.script.rules ] - Adding rule: Danfoss boost new
2021-12-29 14:30:40.732 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Test' received command ON
2021-12-29 14:30:48.887 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@bbd51' takes more than 5000ms.
2021-12-29 14:30:59.423 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@bbd51' takes more than 5000ms.
2021-12-29 14:31:12.796 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Test' changed from OFF to ON
2021-12-29 14:31:23.870 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@bbd51' takes more than 5000ms.
2021-12-29 14:31:31.673 [INFO ] [org.openhab.automation.script       ] - Boost er aktiveret. Luftfugtighed: ${danfossRecentHumidity} %
2021-12-29 14:31:48.312 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading, caused by su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
2021-12-29 14:31:48.322 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2021-12-29 14:31:51.079 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while sending 'PING', caused by java.net.SocketException: Broken pipe (Write failed)
2021-12-29 14:31:45.748 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
	at java.util.Arrays.copyOf(Arrays.java:3745) ~[?:?]
	at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:172) ~[?:?]
	at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:538) ~[?:?]
	at java.lang.StringBuffer.append(StringBuffer.java:312) ~[?:?]
	at java.io.StringWriter.write(StringWriter.java:106) ~[?:?]
	at com.google.gson.stream.JsonWriter.string(JsonWriter.java:586) ~[?:?]
	at com.google.gson.stream.JsonWriter.value(JsonWriter.java:418) ~[?:?]
	at com.google.gson.internal.bind.TypeAdapters$16.write(TypeAdapters.java:406) ~[?:?]
	at com.google.gson.internal.bind.TypeAdapters$16.write(TypeAdapters.java:390) ~[?:?]
	at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.write(TypeAdapterRuntimeTypeWrapper.java:69) ~[?:?]
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.write(ReflectiveTypeAdapterFactory.java:127) ~[?:?]
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.write(ReflectiveTypeAdapterFactory.java:245) ~[?:?]
	at com.google.gson.Gson.toJson(Gson.java:704) ~[?:?]
	at com.google.gson.Gson.toJson(Gson.java:683) ~[?:?]
	at com.google.gson.Gson.toJson(Gson.java:638) ~[?:?]
	at com.google.gson.Gson.toJson(Gson.java:618) ~[?:?]
	at org.openhab.core.events.AbstractEventFactory.serializePayload(AbstractEventFactory.java:88) ~[?:?]
	at org.openhab.core.items.events.ItemEventFactory.createStateEvent(ItemEventFactory.java:255) ~[?:?]
	at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.sendUpdate(ProfileCallbackImpl.java:125) ~[?:?]
	at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onStateUpdateFromHandler(SystemDefaultProfile.java:53) ~[?:?]
	at org.openhab.core.thing.internal.CommunicationManager.lambda$11(CommunicationManager.java:534) ~[?:?]
	at org.openhab.core.thing.internal.CommunicationManager$$Lambda$1095/0x5dfec628.accept(Unknown Source) ~[?:?]
	at org.openhab.core.thing.internal.CommunicationManager.lambda$13(CommunicationManager.java:554) ~[?:?]
	at org.openhab.core.thing.internal.CommunicationManager$$Lambda$1096/0x5df74e28.accept(Unknown Source) ~[?:?]
	at java.lang.Iterable.forEach(Iterable.java:75) ~[?:?]
	at org.openhab.core.thing.internal.CommunicationManager.handleCallFromHandler(CommunicationManager.java:550) ~[?:?]
	at org.openhab.core.thing.internal.CommunicationManager.stateUpdated(CommunicationManager.java:532) ~[?:?]
	at org.openhab.core.thing.internal.ThingManagerImpl$1.stateUpdated(ThingManagerImpl.java:176) ~[?:?]
	at org.openhab.core.thing.binding.BaseThingHandler.updateState(BaseThingHandler.java:231) ~[?:?]
	at org.openhab.binding.synologysurveillancestation.handler.SynoCameraHandler.updateState(SynoCameraHandler.java:365) ~[?:?]
	at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThreadSnapshot.refresh(SynoApiThreadSnapshot.java:56) ~[?:?]
	at org.openhab.binding.synologysurveillancestation.internal.thread.SynoApiThread.runOnce(SynoApiThread.java:135) ~[?:?]
2021-12-29 14:32:07.072 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@bbd51' takes more than 5000ms.
2021-12-29 14:32:14.899 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@bbd51' takes more than 5000ms.
2021-12-29 14:32:25.799 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@bbd51' takes more than 5000ms.
2021-12-29 14:32:49.133 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while handling, caused by java.net.SocketException: Broken pipe (Write failed)
2021-12-29 14:32:49.136 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading, caused by su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
2021-12-29 14:32:49.138 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message

Of course JavaScript engine may not be to blame, but for sure on my system triggering some memory issues I don’t normally see.

What would be next steps for analyzing this further? How can I check how much memory is used by different add-ons?

Best regards,
Jacob Laursen

JSscripting: Error message "Java.lang.OutOfMemoryError: Java heap space"
openHAB 3.2 Release discussion
#2

Do you see a lot of these chromecast exceptions? Or any other exceptions? That would be a good hint.

#3

No, I don’t usually see them. I included them as they indicate start of instability/random issues. I’ll try to find out if the problem starts when rule is triggered or when rule is loaded, as I actually didn’t think about that previously.

#4

I doubt it’s a general JS issue. Very often OOMs were related to connection issues in a bindings where old connections were not properly closed before new connections were opened. Was this the first time you encountered an OOM?

#5

Let me try to look closer into the logs of previous incidents, and also try to reproduce the problem in a more systematic way. My system is usually very stable (and without OOM), but I agree that I need to verify which symptom is actually the first to start giving problems for others. JS might just have been the top of the iceberg if something else has already been misbehaving prior to that. Previously when I didn’t use JS at all, obviously I didn’t need memory for that, so some problems could have been hidden.

#6

I have the same problem (“Java.lang.OutOfMemoryError: Java heap space”) which is described here.
Problem is not related to chromecast.

#7

Thanks for the link, @Oliver2. From that other thread, @Giga522 provided an important clue about errors. A few hours ago I was not able to reproduce the problem, while it happened multiple times yesterday when I was working with the rules. Indeed the problem is very reproducible when having errors in the JS. I was able to get 100% CPU load just by introducing an error in the rule, and memory heap problems following that. I should be able to write a script or just a few reproduction steps tomorrow. I believe it’s now confirmed to be a problem with JS. When evidence is gathered, I’ll create an issue.

1 Like
#8

I too was hit by this during my first JSS attempt 2 days ago. (Ubuntu x64, 3.2.0 release)
Since this was my first JS rule, I had many ‘saves’ which resulted in errors.
My rule has a cron trigger every 1s with a today= new Date as the first line, which I thought was to blame, and after adding a delete today after I was forced to restart OH memory usage stabilized.
Guess the delete is not needed. :slight_smile:

What is the best way to recover? A full OH restart or is it sufficient to restart the JSS add-on in Karaf?

1 Like
Total energy consumed in kWh day/week/mont/year
#9

Seeing the same thing here, OH3.2 on Openhabian on Raspberry 4 4GB.
Experimenting with moving DSL rules to (file-based) JSScript and hence frequent saving of the rule, which at some point starts to freeze the systems, binding ceasing to function, etc. Restarting OH service from command line required to get system back to working again.

#10

Wait… everybody who is reporting this issue is using file based scripts???
cause this sounds an awful lot like an issue that cropped up right after OH3 came out with using file based DSL rules

Right, that is exactly what Mark figured out, purposefully introducing an error caused the cpu to pin in a file based DSL rule
read more here in this thread and linked git issue that resulted in a fix but never really got to the root of issue

3 Likes
#11

Hi Andrew,
I can reproduce this problem by testing rules which create an error during execution. However, my JS scripts are created in MainUI. I described this in this thread. I addressed this to the developer 5 days ago but did not get any feedback (no blaming, just providing some information)

#12

do you mean you created an issue on github? If so please post a link to your issue so we can follow along. If not, if you mean you posted something on this forum then some of the developers don’t frequent the forum and creating an issue on github is the best way to make sure it gets in front of the right people.
Don’t worry… if it is a bug then others will have the same problem and eventually the problem will come to light

#13

see here
And I re-posted it on the oh3.2 release discussion thread

no feedback until now

1 Like
#14

Good job Oliver, thanks for git link, will keep an eye on this as there seems to be one or two other recent threads seem similar

JSscripting: Error message "Java.lang.OutOfMemoryError: Java heap space"
#16

@laursen Can we mark this as solved now? ([jsscripting] Fix memory leak that crashes openHAB by florian-h05 · Pull Request #13824 · openhab/openhab-addons · GitHub)