Thread exhaustion - possibly out of memory or process/resource limits reached

[morph166955]

I've been having issues with jupnp failing after a random period of time. I had opened #3843 thinking this was related there. I'm now wondering if this is actually an OH/Java issue as I'm getting errors outside of jupnp as well (in this case the neeo binding also had a failing). I'm on Snapshot 4182 which is only a few behind right now.

My jupnp is configured with:

org.jupnp:asyncThreadPoolSize=-1
org.jupnp:threadPoolSize=-1

so they should be able to grow without limit. I have had this config in for years and have only had this issue for a few months now. This leads me to think this is more of a Java issue.

When I reset the jupnp bundle via the karaf console the first error I see is:

2024-07-12 12:01:22.234 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
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:809) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:945) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1364) ~[?:?]
        at org.jupnp.controlpoint.ControlPointImpl.execute(ControlPointImpl.java:118) ~[?:?]
        at org.openhab.core.io.transport.upnp.internal.UpnpIOServiceImpl.addSubscription(UpnpIOServiceImpl.java:235) ~[?:?]
        at org.openhab.binding.sonos.internal.handler.ZonePlayerHandler.addSubscription(ZonePlayerHandler.java:1096) ~[?:?]
        at org.openhab.binding.sonos.internal.handler.ZonePlayerHandler.poll(ZonePlayerHandler.java:279) ~[?:?]
        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:840) [?:?]

Then I get a TON of neeo errors:

2024-07-12 12:01:53.498 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
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:809) ~[?:?]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.startThread(QueuedThreadPool.java:788) ~[?:?]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.ensureThreads(QueuedThreadPool.java:770) ~[?:?]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.doStart(QueuedThreadPool.java:217) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:110) ~[?:?]
        at org.eclipse.jetty.io.ManagedSelector.doStart(ManagedSelector.java:113) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.io.SelectorManager.doStart(SelectorManager.java:262) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.AbstractConnectorHttpClientTransport.doStart(AbstractConnectorHttpClientTransport.java:64) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.start(ContainerLifeCycle.java:169) ~[?:?]
        at org.eclipse.jetty.util.component.ContainerLifeCycle.doStart(ContainerLifeCycle.java:117) ~[?:?]
        at org.eclipse.jetty.client.HttpClient.doStart(HttpClient.java:258) ~[?:?]
        at org.eclipse.jetty.util.component.AbstractLifeCycle.start(AbstractLifeCycle.java:73) ~[?:?]
        at org.openhab.io.neeo.internal.NeeoApi.getHttpClient(NeeoApi.java:481) ~[?:?]
        at org.openhab.io.neeo.internal.NeeoApi.notify(NeeoApi.java:515) ~[?:?]
        at org.openhab.io.neeo.internal.servletservices.NeeoBrainService.lambda$2(NeeoBrainService.java:566) ~[?:?]
        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:840) [?:?]

And then some more jupnp:

2024-07-12 12:01:53.786 [WARN ] [org.eclipse.jetty.server.HttpChannel] - /upnpcallback/dev/RINCON_48A6B8BF040E01400_MR/svc/upnp-org/AVTransport/event/cb
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:809) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:945) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1364) ~[?:?]
        at org.jupnp.transport.RouterImpl.received(RouterImpl.java:284) ~[?:?]
        at org.jupnp.transport.impl.async.AsyncServlet.service(AsyncServlet.java:112) ~[?:?]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:584) ~[bundleFile:4.0.4]
        at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102) ~[?:?]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[?:?]
        at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[?:?]
        at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:113) ~[?:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:334) ~[?:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[?:?]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[?:?]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[bundleFile:9.4.54.v20240208]
        at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[?:?]
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.54.v20240208]
        at java.lang.Thread.run(Thread.java:840) [?:?]

EDIT: Just crashed again. Grabbed some stats:

openhab> shell:info
Karaf
  Karaf version               4.4.6
  Karaf home                  /usr/share/openhab/runtime
  Karaf base                  /var/lib/openhab
  OSGi Framework              org.eclipse.osgi-3.18.0.v20220516-2155

JVM
  Java Virtual Machine        OpenJDK 64-Bit Server VM version 17.0.11+9-LTS
  Version                     17.0.11
  Vendor                      Azul Systems, Inc.
  Pid                         973246
  Uptime                      23 hours 19 minutes
  Process CPU time            1 hour 56 minutes
  Process CPU load            0.02
  System CPU load             0.02
  Open file descriptors       718
  Max file descriptors        102,642
  Total compile time          3 minutes
Threads
  Live threads                534
  Daemon threads              336
  Peak                        4537
  Total started               336266
Memory
  Current heap size           739,651 kbytes
  Maximum heap size           3,145,728 kbytes
  Committed heap size         976,896 kbytes
  Pending objects             0
  Garbage collector           Name = 'G1 Young Generation', Collections = 3379, Time = 21.129 seconds
  Garbage collector           Name = 'G1 Old Generation', Collections = 0, Time = 0.000 seconds
Classes
  Current classes loaded      28,415
  Total classes loaded        28,685
  Total classes unloaded      270
Operating system
  Name                        Linux version 5.15.0-112-generic
  Architecture                amd64
  Processors                  4
  Total physical memory       4,005,328 kbytes
  Free physical memory        126,468 kbytes

EDIT2: I dialed up the RAM on the OH VM from 4GB to 8GB after seeing the free physical total was so low. Notice the amount of peak threads now.

openhab> shell:info
Karaf
  Karaf version               4.4.6
  Karaf home                  /usr/share/openhab/runtime
  Karaf base                  /var/lib/openhab
  OSGi Framework              org.eclipse.osgi-3.18.0.v20220516-2155

JVM
  Java Virtual Machine        OpenJDK 64-Bit Server VM version 17.0.11+9-LTS
  Version                     17.0.11
  Vendor                      Azul Systems, Inc.
  Pid                         3257
  Uptime                      2 minutes
  Process CPU time            3 minutes
  Process CPU load            0.10
  System CPU load             0.11
  Open file descriptors       350
  Max file descriptors        102,642
  Total compile time          2 minutes
Threads
  Live threads                1006
  Daemon threads              238
  Peak                        6465
  Total started               7725
Memory
  Current heap size           447,850 kbytes
  Maximum heap size           3,145,728 kbytes
  Committed heap size         1,005,568 kbytes
  Pending objects             0
  Garbage collector           Name = 'G1 Young Generation', Collections = 53, Time = 1.282 seconds
  Garbage collector           Name = 'G1 Old Generation', Collections = 0, Time = 0.000 seconds
Classes
  Current classes loaded      27,404
  Total classes loaded        27,412
  Total classes unloaded      8
Operating system
  Name                        Linux version 5.15.0-113-generic
  Architecture                amd64
  Processors                  4
  Total physical memory       8,127,948 kbytes
  Free physical memory        4,914,236 kbytes

[joerg1985]

@morph166955 you could try jstack {pid of openhab} to show the names and stack of these threads.

[morph166955]

The big thing that pops out with that is that I have over 1500 of these currently out of 1960 total threads. Also interesting that the elapsed time is no more than 60 seconds on any of them and it slowly decreases from 59.x to 0.23.

"pool-6368793-thread-1" #6808661 prio=5 os_prio=0 cpu=0.16ms elapsed=59.64s tid=0x00007faa84457090 nid=0x22dfa waiting on condition  [0x00007faa2eefe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.11/Native Method)
        - parking to wait for  <0x000000072581ac98> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.11/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.11/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.11/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.11/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.11/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.11/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.11/Thread.java:840)

[morph166955]

I believe this may be resolved. I ended up doubling the amount of memory allocated to the openhab VM (4GB to 8GB) and it calmed this issue down. I've had this up for 3 months now with no crashes. I would like to note that my max threads ended up being thousands higher than before when it finally stabilized. I do find it interesting that there were so many threads happening at the same time, that just seems excessive.

openhab> shell:info
Karaf
  Karaf version               4.4.6
  Karaf home                  /usr/share/openhab/runtime
  Karaf base                  /var/lib/openhab
  OSGi Framework              org.eclipse.osgi-3.18.0.v20220516-2155

JVM
  Java Virtual Machine        OpenJDK 64-Bit Server VM version 17.0.11+9-LTS
  Version                     17.0.11
  Vendor                      Azul Systems, Inc.
  Pid                         3257
  Uptime                      98 days 19 hours
  Process CPU time            11 days 23 hours
  Process CPU load            0.03
  System CPU load             0.04
  Open file descriptors       346
  Max file descriptors        102,642
  Total compile time          5 minutes
Threads
  Live threads                1188
  Daemon threads              227
  Peak                        7249
  Total started               152954402
Memory
  Current heap size           1,051,870 kbytes
  Maximum heap size           3,145,728 kbytes
  Committed heap size         2,045,952 kbytes
  Pending objects             0
  Garbage collector           Name = 'G1 Young Generation', Collections = 374188, Time = 1 hour 15 minutes
  Garbage collector           Name = 'G1 Old Generation', Collections = 0, Time = 0.000 seconds
Classes
  Current classes loaded      32,832
  Total classes loaded        3,629,375
  Total classes unloaded      3,596,543
Operating system
  Name                        Linux version 5.15.0-113-generic
  Architecture                amd64
  Processors                  4
  Total physical memory       8,127,948 kbytes
  Free physical memory        1,541,728 kbytes