OH4 runs out of memory

markus7017 · August 14, 2023, 9:11pm

Platform information:

Hardware: Raspberry Pi 4 / 4GB ram / 64GB SD
OS: latest openHABian
Java Runtime Environment: openJDK 17 - latest, as installed by openHABian
openHAB version: 4.0.1 - latest, as installed by openHABian

As part of the migration I created a complete fresh setup with OH 4.0.1
Everything seemed to work fine, but then I run out of memory after 20-30min, sometimes up to 2h
I removed most of the bindings and rules, but problem is the same
I increased heap size, but still the same

EXTRA_JAVA_OPTS="-Xms256m -Xmx768m -XX:+ExitOnOutOfMemoryError"

shell:info shows

 Current heap size           165,872 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         267,500 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
Error executing command: unable to create native thread: possibly out of memory or process/resource limits reached

I ran shell:info shows multiple times before and it looked good (in fact heap size was reduced since startup). And 10min later I get this error.

I had 2 UI instances running for a while working on things and items.

Are there any know issues with regards to general memory leaks with the 4.0.1 release?

Logfile shows ** Stopped without executing or closing null**

2023-08-14 21:01:21.837 [INFO ] [y.internal.handler.ShellyBaseHandler] - shelly1pm-8caab505fcf4: INFO: Neue Firmware verfügbar: aktuelle Version: 20221108-153925/v1.12.1-1PM-fix-g2821131, neue Version: 20230503-101420/v1.13.0-g9aed950
2023-08-14 21:01:26.201 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 21:01:27.277 [INFO ] [g.sony.internal.AbstractThingHandler] - Starting state polling every 30 seconds
2023-08-14 21:10:02.953 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 21:15:21.621 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 21:24:47.749 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Invalid URI host: null (authority: 192.1686.7:8080)
	at org.eclipse.jetty.client.HttpClient.checkHost(HttpClient.java:541) ~[?:?]
	at org.eclipse.jetty.client.HttpClient.newHttpRequest(HttpClient.java:526) ~[?:?]
	at org.eclipse.jetty.client.HttpClient.newRequest(HttpClient.java:484) ~[?:?]
	at org.eclipse.jetty.client.HttpClient.newRequest(HttpClient.java:473) ~[?:?]
	at org.openhab.binding.remoteopenhab.internal.rest.RemoteopenhabRestClient.executeUrl(RemoteopenhabRestClient.java:565) ~[?:?]
	at org.openhab.binding.remoteopenhab.internal.rest.RemoteopenhabRestClient.executeGetUrl(RemoteopenhabRestClient.java:559) ~[?:?]
	at org.openhab.binding.remoteopenhab.internal.rest.RemoteopenhabRestClient.tryApi(RemoteopenhabRestClient.java:162) ~[?:?]
	at org.openhab.binding.remoteopenhab.internal.handler.RemoteopenhabBridgeHandler.checkConnection(RemoteopenhabBridgeHandler.java:376) ~[?:?]
	at org.openhab.binding.remoteopenhab.internal.handler.RemoteopenhabBridgeHandler.lambda$0(RemoteopenhabBridgeHandler.java:182) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[?:?]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]
2023-08-14 21:26:02.867 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 21:26:39.441 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'remoteopenhab:server:192_168_6_7' to inbox.
2023-08-14 21:40:03.113 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 21:44:41.511 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 21:52:16.765 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 21:59:03.106 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 22:01:09.651 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'shelly:shellybulbduo:d0cb5a' to inbox.
2023-08-14 22:04:20.374 [INFO ] [org.openhab.core.model.script.keyfob] - Keyfob event: 255.0
2023-08-14 22:04:44.268 [INFO ] [y.internal.handler.ShellyBaseHandler] - shellygas-50029178b4ac: INFO: Neue Firmware verfügbar: aktuelle Version: 20221027-111245/v1.12.1-ga9117d3, neue Version: 20230503-102300/v1.13.0-g9aed950
2023-08-14 22:14:37.740 [INFO ] [nhab.core.model.script.Shutter_Erker] - Open shutters Erker
2023-08-14 22:14:37.749 [INFO ] [nhab.core.model.script.Shutter_Erker] - Open shutters Erker
2023-08-14 22:17:01.466 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 22:21:02.975 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 22:24:41.605 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 22:25:01.510 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 22:28:21.536 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null
2023-08-14 22:43:52.708 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@14b3f35' takes more than 5000ms.
2023-08-14 22:44:21.364 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached
	at java.lang.Thread.start0(Native Method) ~[?:?]
	at java.lang.Thread.start(Thread.java:802) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:945) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.ensurePrestart(ThreadPoolExecutor.java:1593) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor.delayedExecute(ScheduledThreadPoolExecutor.java:346) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:562) ~[?:?]
	at org.eclipse.jetty.util.thread.ScheduledExecutorScheduler.schedule(ScheduledExecutorScheduler.java:125) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.SocketAddressResolver$Async.lambda$resolve$1(SocketAddressResolver.java:157) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[bundleFile:9.4.50.v20221201]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[bundleFile:9.4.50.v20221201]
	at java.lang.Thread.run(Thread.java:833) ~[?:?]

I’m wondering, because the Sony binding is not marked as installed under Settings->Bindings, but shows up in the log. I installed it before, removed it to narrow potential candidates, but still shows up in the log.
bundle:list indicates the binding as installed, but not active

236 │ Active    │  80 │ 4.0.1                  │ openHAB Add-ons :: Bundles :: Automation :: JavaScript Scripting
237 │ Active    │  80 │ 4.0.1                  │ openHAB Add-ons :: Bundles :: Amazon Dash Button Binding
238 │ Active    │  80 │ 4.0.1                  │ openHAB Add-ons :: Bundles :: Astro Binding
244 │ Active    │  80 │ 4.0.1                  │ openHAB UI :: Bundles :: HABPanel UI
245 │ Active    │  80 │ 4.0.1                  │ openHAB Add-ons :: Bundles :: Automation :: JavaScript Scripting (Nashorn)
248 │ Active    │  75 │ 4.0.1                  │ openHAB Add-ons :: Bundles :: Transformation Service :: Map
254 │ Active    │  75 │ 4.0.1                  │ openHAB Add-ons :: Bundles :: Transformation Service :: XPath
255 │ Active    │  80 │ 0.3.0.v20220506-1020   │ EdDSA-Java
256 │ Active    │  80 │ 2.7.4                  │ Californium (Cf) Core
257 │ Active    │  80 │ 2.7.4                  │ Californium (Cf) Element Connector
258 │ Active    │  80 │ 2.7.4                  │ Californium (Cf) OSGi
259 │ Active    │  80 │ 2.7.4                  │ Scandium (Sc) Core
275 │ Active    │  80 │ 4.1.0.202308122207     │ openHAB Add-ons :: Bundles :: Shelly Binding Gen1+2
281 │ Installed │  80 │ 4.0.0.202305291652     │ openHAB Add-ons :: Bundles :: Sony Binding
282 │ Active    │  80 │ 4.0.1                  │ openHAB Add-ons :: Bundles :: Remote openHAB Binding

The addons folder is empty, but there is openhab-addons-4.0.1.kar - is that correct?

I noticed when I do a “feature:install openhab-transport-coap” that OH crashes/restarts. Even the console is ended. After starting the console again, I’m able to activate the Shelly binding. This happens each time when I clean the cache and need to re-install the coap transport.

See what happens when I run shell:info command every 3sec:
heap grows rapidly to about 220MB and then drops to 170, grows again…

openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           169,590 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           186,391 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           192,006 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           194,293 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           197,851 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           199,981 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           203,248 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           204,398 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           208,816 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                         Current heap size           173,544 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           177,355 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes
openhab> shell:info | grep heap                                                                                                                                                       
  Current heap size           182,034 kbytes
  Maximum heap size           760,320 kbytes
  Committed heap size         253,952 kbytes

When I shutdown OH I see

2023-08-14 23:26:27.757 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Stopped HABPanel
2023-08-14 23:26:28.246 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler ShellyRelayHandler tried updating the thing status although the handler was already disposed.
2023-08-14 23:26:40.171 [WARN ] [service.spi.util.WebContainerManager] - Can't get a WebContainer service from {org.osgi.service.http.HttpService, org.ops4j.pax.web.service.WebContainer}={org.ops4j.pax.web.log.ncsa.extended=true, org.ops4j.pax.web.ssl.keystore.password=********, service.scope=bundle, org.ops4j.pax.web.ssl.key.password=********, org.ops4j.pax.web.session.cookie.name=JSESSIONID, org.osgi.service.http.connector.name=default, org.ops4j.pax.web.enc.iterationcount=1000, org.ops4j.pax.web.log.ncsa.file=yyyy_mm_dd.request.log, org.ops4j.pax.web.server.eventDispatcherThreadCount=1, org.osgi.service.http.checkForwardedHeaders=false, org.ops4j.pax.web.enc.suffix=), org.ops4j.pax.web.digestAuth.maxNonceAge=60000, org.ops4j.pax.web.ssl.ciphersuites.included=, org.ops4j.pax.web.session.url=jsessionid, org.ops4j.pax.web.formAuth.errorRedirect=false, org.ops4j.pax.web.ssl.ciphersuites.excluded=^.*_(MD5|SHA|SHA1)$,^TLS_RSA_.*$,^SSL_.*$,^.*_NULL_.*$,^.*_anon_.*, org.ops4j.pax.web.enc.prefix=ENC(, org.ops4j.pax.web.server.maxThreads=50, org.ops4j.pax.web.validatePeerCerts=false, service.id=125, org.ops4j.pax.web.session.cookie.maxAge=-1, org.ops4j.pax.web.ssl.truststore.password=********, org.ops4j.pax.web.ssl.session.cacheSize=-1, org.ops4j.pax.web.ssl.truststore.type=JKS, org.ops4j.pax.web.ssl.keystore.type=JKS, org.ops4j.pax.web.ssl.session.enabled=true, org.ops4j.pax.web.ssl.protocol=TLSv1.3, org.osgi.service.http.port=8080, org.ops4j.pax.web.log.ncsa.file.date.format=yyyy-MM-dd, org.ops4j.pax.web.ssl.renegotiationLimit=-1, org.osgi.service.http.secure.enabled=true, org.osgi.service.http.enabled=true, org.ops4j.pax.web.server.idleTimeout=300000, org.ops4j.pax.web.log.ncsa.retaindays=90, org.ops4j.pax.web.log.ncsa.logtimezone=GMT, org.ops4j.pax.web.enc.algorithm=PBEWithHmacSHA256AndAES_128, org.ops4j.pax.web.validateCerts=false, org.ops4j.pax.web.config.files=/usr/share/openhab/runtime/etc/jetty.xml, org.ops4j.pax.web.ssl.renegotiationAllowed=true, org.ops4j.pax.web.digestAuth.maxNonceCount=1024, org.ops4j.pax.web.enableOCSP=false, org.ops4j.pax.web.ssl.clientauth.needed=false, org.ops4j.pax.web.enc.enabled=false, org.osgi.service.http.port.secure=8443, javax.servlet.context.tempdir=/var/lib/openhab/tmp, org.ops4j.pax.web.enableCRLDP=false, org.ops4j.pax.web.server.connector.idleTimeout=30000, org.ops4j.pax.web.session.timeout=10, org.ops4j.pax.web.ssl.clientauth.wanted=false, org.ops4j.pax.web.ssl.protocols.excluded=SSL,SSLv2,SSLv2Hello,SSLv3, service.bundleid=222, org.ops4j.pax.web.server.minThreads=2, org.ops4j.pax.web.session.cookie.secure=false, org.ops4j.pax.web.enc.masterpassword=********, org.ops4j.pax.web.log.ncsa.append=true, org.osgi.service.http.secure.connector.name=secureDefault, org.ops4j.pax.web.ssl.session.timeout=-1, org.ops4j.pax.web.listening.addresses=0.0.0.0, org.ops4j.pax.web.log.ncsa.buffered=true, org.ops4j.pax.web.session.cookie.sameSite=unset, org.ops4j.pax.web.log.ncsa.enabled=false, org.ops4j.pax.web.ssl.protocols.included=, org.ops4j.pax.web.session.cookie.httpOnly=true, org.ops4j.pax.web.server.showStacks=false}

mstormi · August 14, 2023, 10:04pm

That’s actually not an increase if on a 4GB box. Try omitting or even 2g. Increase Xms, too, eventually.

markus7017 · August 15, 2023, 5:01am

changed to 2048 and removed another rules file, let’s see

What do you think about “2023-08-15 06:50:18.440 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - Stopped without executing or closing null” messages?
I found this:

seime · August 15, 2023, 5:12am

192.1686.7 is not a valid ip address, dot missing.

Arne

markus7017 · August 15, 2023, 12:04pm

hmm, I See that in the log above, but find it in the whole json db
I uninstalled the remote openHAB binding, so far looks look
I’m cleaning up the remote system, maybe it is related to a ton of old entries (I use this Pi in between only as a Z-Wave hub, but there was still a lot configured).

markus7017 · August 22, 2023, 6:28am

I had it running, mostly it was remotes to the remote server addon with a lot of auto-discovered items. Then I stripped down the remote installation by 75%, recreated the thing (no importing the OH3 config) and everything worked fine. Now I re-added the missing bindings (which link to existing things) and problem is back.

Is there a way to find out, which addon is consuming what amount of memory/heap? Or do I need to go the „strip down and re-add bindings/things one by one“, which is a hazzle…

wborn · August 22, 2023, 6:45am

The best approach is to create a memory heap dump when it is almost full and then analyze it with a tool like:

The leak can be anywhere not just in the add-on. It could also be in OH Core or some third party library the add-on code uses.

cmachtel · October 1, 2023, 12:13pm

Hello @markus7017 ,
Have you finally solved the issue?
I experience a similar issue and while testing thing it could maybe be caused by the shelly binding. I am currently not 100% shure but it seems to have a link. Any similar thing with your setup?

sjcliffe · October 2, 2023, 8:13am

I’m having a similar issue. It started a couple of days ago and I’ve since upgraded from 4.0.1 to 4.0.3 and increased my max heap size to 2GB (I’m running on a 4GB Pi 4) to no avail.

I’m not using many bindings but I can see the number of runnable HttpClient threads continually grow. Is there any way to see what is spawning them?

wborn · October 2, 2023, 8:27am

Which bindings do you use? I read that NEEO has some issues, see openhab-addons#15563.

Lolodomo · October 2, 2023, 10:44am

And it was also said that the unofficial sony binding has a similar issue.

morph166955 · October 2, 2023, 1:55pm

Neeo and sony were both created by the same author. Not surprising that he probably used similar code. I’d bet it needs a similar fix.

There’s also a thread leak coming out of the core (I think), I opened Thread Leak - Excessive number of pools · Issue #3816 · openhab/openhab-core · GitHub to hunt that down.

cmachtel · October 2, 2023, 3:35pm

Hello, I do not use Neeo and also not Sony binding. There is a similar thread here: OutOfMemoryError after Migration to 4.1.0.M1 - #12 by cmachtel
I’m still testing to disable one binding after the other to find the exact origin. On some places they also think it could be http binding.
If you ssh your openhab you can do a request like this one:

shell:threads | grep -i httpclient | grep -i runnable | wc -l

Mherwege · October 2, 2023, 5:15pm

Its not because the grep refers to httpclient that it is the http binding that is the issue. Many binding use an httpclient without using the http binding code. I doubt he issue is with the http binding, but with other bindings using http. That’s where nee where identified to be affected for sure, and sony probably. This also only impacted OH4M1 and not the release version.

markus7017 · October 2, 2023, 6:11pm

for me it was the remote openhab binding, cleaned up at lot of items there and problem was solved
yes the shelly binding also uses the build-in http client

I a bunch of bindings is affected it smells like a problem in core or the http client implementation (I suppose the http binding uses this too)

sjcliffe · October 3, 2023, 3:59am

Okay, after disabling a few bindings in turn the culprit for me was the Nest binding.

Mherwege · October 3, 2023, 5:30am

To be more precise, the Neeo binding and Sony binding do not use the built in http client. That´s why the number of clients was increasing out of control. I don’t know for other bindings.

cmachtel · October 3, 2023, 8:04am

You are right, but i have the issue with OH 4.0.3 and i’m quite sure it is coming from Shelly binding. I disabled currently the Shelly binding and since 3 days everything is fine. I Plan to enable the binding but disable a lot of items to see how it reacts

hmerk · October 3, 2023, 10:45am

I doubt it is coming from Shelly Binding. Running 4.0.3 with shipped Binding and having about 45 Shelly Things with their Items, I am not seeing any out of memory issues.

cmachtel · October 3, 2023, 11:26am

would be happy but i had OH3 since years with shelly’s and no issue. Now i moved to a new setup and complete new Raspberry 4 with 8GB ram and new sd with OH4.0.3. As long ass Shelly binding is uninstalled everything works well. As sson as i Install it i get ±30mn later only errors and system become unavailable. I have around 65 Shelly devices, including pro and plus and BLE devices aswell as the new panel
Error is:

java.lang.OutOfMemoryError: unable to create native thread: possibly out of memory or process/resource limits reached.