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

@jpg0
after a while when testing new JSscripting rules, OH is running out of memory and CPU load for openhab goes up to 100%
Error messages:

2021-12-29 22:12:59.868 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /rest/rules/SystemReadLog
java.lang.OutOfMemoryError: Java heap space

2021-12-29 22:14:35.128 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@16f740b' takes more than 5000ms.

2021-12-29 22:19:26.790 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.OutOfMemoryError: Java heap space

Is this something you are already aware of?

Possibly related?

thanks for pointing this out. I link my post to that topic and once it is clear it is the same problem, I’ll delete me post

For me too.
i have a stable system.
But when i try new functions in jss and run rules several times with errors in it, i get heap errors.

1 Like

me too: when I test my new scripts, I always have (lots of) errors in it :slight_smile:

I noticed this as well when trying to convert my text based DSL rules to text based js scripting. I updated and saved the same file multiple times. It appears that there might be some sort of memory leak

2 Likes

Hi together,

I also updated to OpenHAB 3.2 from stable 3.1 (on openhabian) just before christmas. Everthing worked smoothly.

But in the last days I noticed that scripting slows down dramatically.
Yesterday evening I watched in the logs and saw also:

java.lang.OutOfMemoryError: Java heap space

Every few seconds and CPU load arround 200% without any special activity triggered.

I made a system restart at arround 10pm yesterday. Now everything seams to work OK again.
Any sugestion why I should also check and provide is welcome!

Nobody knows if this problem gets attention and will be fixed. It is not wanted to post these problems in the openhab 3.2 release discussion thread where it could get attention.
You might also open a ticket on github, but I made the experience unless requested by a developer to do so, the ticket does not very often get attention either

@Oliver2
May be you should add some more info about your environment? (Openhabian, OpenHAB version,…)
Same environment like mine or different?

I think without more details to get down to the root cause, can not expect any answer…

My message was split from the official 3.2 release thread. And when talking about new JS scripting it is clear, that it HAS to be OH3.2 version.
But yes I could provide details that I have the latest openhabian version and run Zulu11-32 (latest version) - I always do an update before posting issues with OH.

In contrary to your problem, my OH is stable, no increase of CPU performance.
Only if I modify and test JSscripting scripts which causes errors due to wrong syntax after a short while my CPU load goes up to 100% and stays there until a restart.
I also made the experience that sometimes even a reboot does not help - I had to physically switch off my Pi

This is what is happening to me as well. I have 3.2 running on a banana pi with Armbian (Debian) bullseye and Zulu Java.

@Oliver2
May be true that out problems have different root cause.
I don’t use the new script engine until now, even if would like to try the python one :slight_smile:
I also use the Java version which comes with openhabian.

I played more arround with my system and noticed that I can bring my OpenHAB easy in a crash during startup when I do thinks on the GUI or changing sitmap files in parallel.

Example error:

2022-01-03 15:51:26.250 [WARN ] [p.internal.http.HttpResponseListener] - Requesting 'http://feinstaubsensor-14255834/data.json' (method='GET', content='null') failed: null

2022-01-03 15:51:42.535 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

Than nealy 6minutes nothing (CPU load 388%!!) and:

2022-01-03 15:57:16.052 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.io.monitor.internal.EventLogger@d3c059' takes more than 5000ms.

2022-01-03 15:57:16.064 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /chart

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.071 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.078 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.085 [INFO ] [org.eclipse.jetty.io.ManagedSelector] - Caught select() failure, trying to recover: java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.088 [ERROR] [se.californium.elements.UDPConnector] - Exception in network stage thread [UDP-Receiver-0.0.0.0/0.0.0.0:5683[0]]:

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.088 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.093 [WARN ] [work.deduplication.SweepDeduplicator] - Exception in Mark-and-Sweep algorithm

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.107 [ERROR] [org.apache.felix.fileinstall        ] - In main loop, we have serious trouble

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.107 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.107 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.110 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.112 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.107 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.110 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.114 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.114 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

2022-01-03 15:57:16.199 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 543a2bc1-9ff9-4d70-a726-c4181728adfc, base URL = http://localhost:8080)

2022-01-03 15:57:16.057 [ERROR] [org.knowm.yank.Yank                 ] - Error in SQL query!!!

java.sql.SQLTransientConnectionException: yank-default - Connection is not available, request timed out after 374453ms.

	at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:555) ~[?:?]

	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:188) ~[?:?]

	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:147) ~[?:?]

	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:83) ~[?:?]

	at org.apache.commons.dbutils.AbstractQueryRunner.prepareConnection(AbstractQueryRunner.java:204) ~[?:?]

	at org.apache.commons.dbutils.QueryRunner.query(QueryRunner.java:287) ~[?:?]

	at org.knowm.yank.Yank.queryObjectArrays(Yank.java:578) ~[?:?]

	at org.knowm.yank.Yank.queryObjectArrays(Yank.java:560) ~[?:?]

	at org.openhab.persistence.jdbc.db.JdbcBaseDAO.doGetHistItemFilterQuery(JdbcBaseDAO.java:344) ~[?:?]

	at org.openhab.persistence.jdbc.internal.JdbcMapper.getHistItemFilterQuery(JdbcMapper.java:169) ~[?:?]

	at org.openhab.persistence.jdbc.internal.JdbcPersistenceService.query(JdbcPersistenceService.java:205) ~[?:?]

	at org.openhab.core.ui.internal.chart.defaultchartprovider.DefaultChartProvider.addItem(DefaultChartProvider.java:328) ~[bundleFile:?]

	at org.openhab.core.ui.internal.chart.defaultchartprovider.DefaultChartProvider.createChart(DefaultChartProvider.java:209) ~[bundleFile:?]

	at org.openhab.core.ui.internal.chart.ChartServlet.doGet(ChartServlet.java:320) ~[bundleFile:?]

	at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) ~[bundleFile:3.1.0]

	at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[bundleFile:3.1.0]

	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550) ~[bundleFile:9.4.43.v20210629]

	at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[bundleFile:?]

	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) ~[bundleFile:9.4.43.v20210629]

	at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[bundleFile:?]

	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.43.v20210629]

	at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[bundleFile:?]

	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:555) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:410) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:164) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:386) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.43.v20210629]

	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.43.v20210629]

	at java.lang.Thread.run(Thread.java:829) [?:?]

2022-01-03 15:57:16.335 [WARN ] [e.io.http.servlet.BaseOpenHABServlet] - Chart generation failed: null

==> /var/log/openhab/events.log <==

2022-01-03 15:57:16.365 [INFO ] [openhab.event.InboxRemovedEvent     ] - Discovery Result with UID 'shelly:shellyrgbw2-white:49e6bd' has been removed.

2022-01-03 15:57:17.827 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Sensor_CPUTemp' changed from 65.7 to 65.2

2022-01-03 15:57:17.835 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ReceiverOnline' changed from ON to OFF

2022-01-03 15:57:17.846 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'N_FS_VINDRIKTNING_RSSI' changed from 82 to 80

==> /var/log/openhab/openhab.log <==

2022-01-03 15:57:19.404 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 543a2bc1-9ff9-4d70-a726-c4181728adfc, base URL = http://localhost:8080)

After that my log look normal but the GUI was dead.

As a first step I increased my JAVA memory with the JAVA options.
In the past I had the experience that the default values are to low for my installation.
I hope no memory leak somewhere!!

With OpenHAB 3.2 I added also the Shelly binding, the Network binding and the Python scripting (which I did not try yet). May be its also connetected to that…

My installation is stable after I increased JAVA heap.

Could you please post the command incl. parameters you issued?

you find the EXTRA_JAVA_OPTS in file:

/etc/default/openhab

I have a 4GB PI4. So I don’t see why I should limit the memory so much as it is by default.
My values look now like this:

EXTRA_JAVA_OPTS="-Xms512m -Xmx800m -Dlog4j2.formatMsgNoLookups=true"

I made Xms and Xms just much bigger. I think default is “-Xms192m -Xmx320m”!?
System its much more responsive and stable now.

I increased them also in the past but with each (or some) updates the values are reset to default.

Excellent. Will try this, too.
Thank you very much

Good point I will try it by myself but do you think that the problem just delays or is OpenHab also cleaning the used memory?

I suppose each of you could try to find out.
Useful background info in this thread -

Good point I will try it by myself but do you think that the problem just delays or is OpenHab also cleaning the used memory?

Not OpenHAB it cleaning unused memory. The JAVA garbage collector is doing it. Just try it. I don’t want to say that it solves also your problem.

It will not solve the symptoms nor is it the root cause of the problem.
I‘d say it pushes the symptoms of the problem to a later point of time (which is to me a kind of solution):grinning: