Sitemap causing OOM?

  • Platform information:
    • Hardware: Intel® Core™ i5-2400 CPU @ 3.10GHz / 4GB
    • OS: Ubuntu 16.04
    • Java Runtime Environment: Java™ SE Runtime Environment (build 1.8.0_151-b12)
    • openHAB version: openHAB 2.3.0 Build #1188
  • Issue of the topic: please be detailed explaining your issue
    I’ve been having a lot of issues with OpenHab lately, I often have to restart it because it consistently use 100% CPU or because it has crashed apparently because it ran out of heap space.

I’ve set the log level in Karaf to DEBUG and there was a ton of messages apparently coming from the Karaf module itself (to be confirmed):

11:32:33.883 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047466
11:32:33.883 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=1, available=1047466
11:32:33.883 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 64 bytes
11:32:33.883 [DEBUG] [t.www.protocol.http.HttpURLConnection] - sun.net.www.MessageHeader@3d2b27248 pairs: {null: HTTP/1.1 200 OK}{Content-Type: text/xml;charset=utf-8}{Content-Length: 403}{Connection: Keep-Alive}{Keep-Alive: timeout=20}{X-Plex-Protocol: 1.0}{Cache-Control: no-cache}{Date: Thu, 18 Jan 2018 16:32:33 GMT}
11:32:33.884 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=64
11:32:33.884 [DEBUG] [.xml.internal.bind.v2.util.XmlFactory] - SAXParserFactory instance: com.sun.org.apache.xerces.internal.jaxp.SAXParserFactoryImpl@6a723734
11:32:34.354 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleReadCycleCompletion(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) read 64 bytes
11:32:34.355 [DEBUG] [he.sshd.server.channel.ChannelSession] - handleData(ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298]) SSH_MSG_CHANNEL_DATA len=1
11:32:34.356 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047465
11:32:34.356 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=1, available=1047465
11:32:34.356 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 64 bytes
11:32:34.357 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=64
11:32:34.547 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleReadCycleCompletion(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) read 64 bytes
11:32:34.547 [DEBUG] [he.sshd.server.channel.ChannelSession] - handleData(ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298]) SSH_MSG_CHANNEL_DATA len=1
11:32:34.548 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047464
11:32:34.548 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=1, available=1047464
11:32:34.549 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 64 bytes
11:32:34.549 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=64
11:32:34.810 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleReadCycleCompletion(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) read 64 bytes
11:32:34.810 [DEBUG] [he.sshd.server.channel.ChannelSession] - handleData(ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298]) SSH_MSG_CHANNEL_DATA len=1
11:32:34.811 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047463
11:32:34.812 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=1, available=1047463
11:32:34.812 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 64 bytes
11:32:34.812 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=64
11:32:34.977 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleReadCycleCompletion(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) read 64 bytes
11:32:34.977 [DEBUG] [he.sshd.server.channel.ChannelSession] - handleData(ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298]) SSH_MSG_CHANNEL_DATA len=1
11:32:34.978 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047462
11:32:34.978 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=1, available=1047462
11:32:34.979 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 64 bytes
11:32:34.979 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=64
11:32:35.201 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleReadCycleCompletion(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) read 64 bytes
11:32:35.201 [DEBUG] [he.sshd.server.channel.ChannelSession] - handleData(ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298]) SSH_MSG_CHANNEL_DATA len=1
11:32:35.205 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047461
11:32:35.205 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=3, available=1047461
11:32:35.206 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 80 bytes
11:32:35.206 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047458
11:32:35.206 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=80
11:32:35.206 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=15, available=1047458
11:32:35.206 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 80 bytes
11:32:35.207 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=80
11:32:35.207 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047443
11:32:35.207 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=8, available=1047443
11:32:35.207 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 80 bytes
11:32:35.207 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=80
11:32:35.208 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Executing command: 'log:set INFO’
11:32:35.219 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Command: ‘log:set INFO’ returned 'null’
11:32:35.221 [DEBUG] [org.apache.sshd.common.channel.Window] - waitForSpace(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) available: 1047435
11:32:35.221 [DEBUG] [org.apache.sshd.common.channel.Window] - waitAndConsume(Window[server/remote](ChannelSession[id=0, recipient=0]-ServerSessionImpl[openhab@/127.0.0.1:50298])) - requested=232, available=1047435
11:32:35.221 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - Writing 304 bytes
11:32:35.222 [DEBUG] [pache.sshd.common.io.nio2.Nio2Session] - handleCompletedWriteCycle(Nio2Session[local=/127.0.0.1:8101, remote=/127.0.0.1:50298]) finished writing len=304

There’s usually a ton of message printed when I run the “log:tail” command and my Karaf becomes unresponsive, I need to start another SSH session.

I’ve lost the details of the apparent OOM, but IIRC there was something like “karaf java.lang.outofmemoryerror java heap space” in the log when running “/etc/init.d/openhab2 status”

Is there anything I can do to track this down? Is there some known performance issues with Karaf?

did this start to happen after you set the log level to DEBUG on the ROOT Logger or before?

If you set the entire OH2 system on DEBUG… you may stretch it too much :slight_smile:

Nop, I just set it to DEBUG temporarily to see if there was something suspicious in the log :slight_smile:

post the output of bundle:list (from the karaf console)

check also:

1 Like

But this might explain the OOM I’ve observed, the log level was at DEBUG when I observed this. My main issue is the high CPU usage, I’m not sure that it’s coming from Karaf but there was so many lines that ‘seemed’ to come from Karaf in the log that it looked suspicious.

I guess that I’ll need to get a Java profiler and grab a trace thew next time I observe this :frowning:

1 Like

Here’s the list of bundles:

 ID │ State    │ Lvl │ Version                │ Name
────┼──────────┼─────┼────────────────────────┼────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
 15 │ Active   │  80 │ 2.3.0.201712301408     │ Wink Binding
 16 │ Active   │  80 │ 5.3.1.201602281253     │ OSGi JAX-RS Connector
 17 │ Active   │  80 │ 2.4.5                  │ Jackson-annotations
 18 │ Active   │  80 │ 2.4.5                  │ Jackson-core
 19 │ Active   │  80 │ 2.4.5                  │ jackson-databind
 20 │ Active   │  80 │ 2.4.5                  │ Jackson-dataformat-XML
 21 │ Active   │  80 │ 2.4.5                  │ Jackson-dataformat-YAML
 22 │ Active   │  80 │ 2.4.5                  │ Jackson-module-JAXB-annotations
 23 │ Active   │  80 │ 2.7.0                  │ Gson
 24 │ Active   │  80 │ 18.0.0                 │ Guava: Google Core Libraries for Java
 25 │ Active   │  80 │ 3.0.0.v201312141243    │ Google Guice (No AOP)
 26 │ Active   │  80 │ 3.12.0.OH              │ nrjavaserial
 27 │ Active   │  80 │ 1.5.8                  │ swagger-annotations
 28 │ Active   │  80 │ 3.19.0.GA              │ Javassist
 30 │ Active   │  80 │ 3.5.2                  │ JmDNS
 33 │ Active   │  80 │ 1.1.0.Final            │ Bean Validation API
 35 │ Active   │  80 │ 2.0.1                  │ javax.ws.rs-api
 36 │ Active   │  80 │ 3.2.0.v201101311130    │ ANTLR Runtime
 39 │ Active   │  80 │ 3.2.1                  │ Commons Collections
 40 │ Active   │  80 │ 1.1                    │ Commons Exec
 41 │ Active   │  80 │ 2.2.0                  │ Commons IO
 42 │ Active   │  80 │ 2.6                    │ Commons Lang
 52 │ Active   │  80 │ 4.1.3                  │ Apache Karaf :: OSGi Services :: Event
 71 │ Active   │  80 │ 2.11.0.v20150805-0538  │ EMF Common
 72 │ Active   │  80 │ 2.11.1.v20150805-0538  │ EMF Ecore
 73 │ Active   │  80 │ 2.11.1.v20150805-0538  │ EMF XML/XMI Persistence
 74 │ Active   │  80 │ 3.8.0.v20160509-1230   │ Common Eclipse Runtime
 75 │ Active   │  80 │ 3.6.100.v20160223-2218 │ Extension Registry Support
102 │ Active   │  80 │ 0.2.1.v20170706-0855   │ org.eclipse.lsp4j
103 │ Active   │  80 │ 0.2.1.v20170706-0855   │ org.eclipse.lsp4j.jsonrpc
104 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Config Core
105 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Configuration Discovery
106 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Configuration mDNS Discovery
107 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Config Dispatcher
108 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Config Serial
109 │ Active   │  75 │ 0.10.0.201801152239    │ Eclipse SmartHome Config XML
110 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core
111 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core Audio
112 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome AutoUpdate Binding
113 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core Binding XML
114 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core ID
115 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core Persistence
116 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Scheduler Service
117 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core Thing
118 │ Active   │  75 │ 0.10.0.201801152239    │ Eclipse SmartHome Core Thing XML
119 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Transformation Service
120 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core Voice
121 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Console
122 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Console for OSGi runtime Karaf
123 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome JavaSound I/O, Fragments: 189
124 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Monitor
125 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Net I/O Bundle
126 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome REST Interface Bundle
127 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Core REST API
128 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome REST mDNS Announcer
129 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome REST Interface JAX-RS optimization Bundle
130 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Sitemap REST API
131 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome SSE REST API
132 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Voice REST API
133 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Bonjour/MDS Service Discovery Bundle
134 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Web Audio Support
135 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Model Core
136 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Item Model
137 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Item Model IDE
138 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Item Model Runtime
139 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Language Server
140 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Persistence Model
141 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Persistence Model IDE
142 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Persistence Runtime
143 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Rule Model
144 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Rule Model IDE
145 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Rule Runtime
146 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Script
147 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Script Model IDE
148 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Script Runtime
149 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Sitemap Model
150 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Sitemap Model IDE
151 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Sitemap Runtime
152 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Thing Model
153 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Thing Model IDE
154 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Thing Model Runtime
155 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Json Storage Service
156 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome UI
157 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome UI Icons
158 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Classic IconSet
159 │ Active   │  80 │ 2.12.0.v20170518-0757  │ Xtend Runtime Library
160 │ Active   │  80 │ 2.12.0.v20170518-0757  │ Xtend Macro Interfaces
161 │ Active   │  80 │ 2.12.0.v20170518-0959  │ Xtext
162 │ Active   │  80 │ 2.12.0.v20170519-0752  │ Xtext Common Types
163 │ Active   │  80 │ 2.12.0.v20171017-1700  │ Xtext IDE Core
164 │ Active   │  80 │ 2.12.0.v20170518-0959  │ Xtext Utility
165 │ Active   │  80 │ 2.12.0.v20170519-0752  │ Xbase Model
166 │ Active   │  80 │ 2.12.0.v20170519-0752  │ Xbase Generic IDE Services
167 │ Active   │  80 │ 2.12.0.v20170518-0757  │ Xbase Runtime Library
182 │ Active   │  80 │ 2.3.0                  │ JUPnP Library
183 │ Active   │  80 │ 1.9.6                  │ MIME streaming extension
184 │ Active   │  80 │ 5.0.2                  │ Require-Bundle Fix :: org.objectweb.asm
186 │ Active   │  90 │ 2.3.0.201801141430     │ openHAB Core
187 │ Active   │  80 │ 2.3.0.201801141430     │ openHAB Karaf Integration
189 │ Resolved │  80 │ 2.3.0.201801141430     │ openHAB Sound Support, Hosts: 123
190 │ Active   │  80 │ 2.3.0.201801141430     │ openHAB Dashboard UI
195 │ Active   │  80 │ 3.1.4                  │ Stax2 API
196 │ Active   │  80 │ 1.1.1.201605111122     │ Swagger Provider
197 │ Active   │  80 │ 1.5.8                  │ swagger-core
198 │ Active   │  80 │ 1.5.8                  │ swagger-jaxrs
199 │ Active   │  80 │ 1.5.8                  │ swagger-models
200 │ Active   │  80 │ 1.6.0                  │ Commons Codec
201 │ Active   │  80 │ 3.4.0                  │ Apache Commons Lang
202 │ Active   │  80 │ 3.2.0                  │ Commons Net
203 │ Active   │  80 │ 4.2.3                  │ Apache HttpClient OSGi bundle
204 │ Active   │  80 │ 4.2.3                  │ Apache HttpCore OSGi bundle
205 │ Active   │  80 │ 3.1.0.7                │ Apache ServiceMix :: Bundles :: commons-httpclient
206 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation API
207 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation commands
208 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Core
209 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Module Core
210 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Media Modules
211 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Module Script
212 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Script Globals
213 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Script RuleSupport
214 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Module Timer
215 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation GSON Parser
216 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation Providers
217 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Automation REST API
218 │ Active   │  80 │ 0.10.0.201801152239    │ Sonos Binding
219 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Wemo Binding
220 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Configuration UPnP Discovery
221 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome UPnP Transport Bundle
222 │ Active   │  75 │ 0.10.0.201801152239    │ Eclipse SmartHome Map Transformation Service
223 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Basic UI, Fragments: 236
224 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome WebApp UI, Fragments: 237
225 │ Active   │  80 │ 0.10.0.201801152239    │ Eclipse SmartHome Paper UI, Fragments: 240
226 │ Active   │  80 │ 2.3.0.201801141430     │ Chromecast Binding
227 │ Active   │  80 │ 1.12.0.201801160209    │ openHAB Insteon PLM Binding
228 │ Active   │  80 │ 1.12.0.201801160209    │ openHAB MQTT Binding
229 │ Active   │  80 │ 1.12.0.201801160209    │ openHAB Mqttitude Binding
230 │ Active   │  80 │ 1.12.0.201801160209    │ openHAB Plex Binding
231 │ Active   │  80 │ 2.3.0.201801141430     │ Systeminfo Binding
232 │ Active   │  80 │ 2.3.0.201801141430     │ openHAB 1.x Compatibility Layer
233 │ Active   │  80 │ 2.3.0.201801141430     │ openHAB Cloud Connector Bundle
234 │ Active   │  80 │ 2.3.0.201801141430     │ openHAB REST Documentation
235 │ Active   │  80 │ 1.12.0.201801160209    │ openHAB MQTT Transport Bundle
236 │ Resolved │  75 │ 2.3.0.201801141430     │ openHAB Basic UI Fragment, Hosts: 223
237 │ Resolved │  75 │ 2.3.0.201801141430     │ openHAB Classic UI Fragment, Hosts: 224
238 │ Active   │  80 │ 2.3.0.201801141430     │ HABmin User Interface
239 │ Active   │  80 │ 2.3.0.201801141430     │ HABPanel User Interface
240 │ Resolved │  75 │ 2.3.0.201801141430     │ openHAB Paper UI Theme Fragment, Hosts: 225
241 │ Active   │  80 │ 0.9.10.v20160429-1435  │ reflections (wrap)
242 │ Active   │  80 │ 1.5.8.v20160511-1038   │ swagger-jersey2-jaxrs (wrap)

Is “bundle:stop” {ID} equivalent to uninstalling a bundle? Last time I’ve observed the high CPU usage I’ve stopped all the bundles (except for the Karak one as I was using it) but it didn’t fixed the issue.

I’ll learn how to use a Java profiler (I’m a Windows developer, I’m more used to ETW traces etc…). I’ll also read the post you linked to for help. I’ll post my discoveries here :slight_smile:

I just got another OOM before I had a chance to enable heap profiling, here’s what “/etc/init.d/openhab2 status” say about it:

● openhab2.service - openHAB 2 - empowering the smart home
   Loaded: loaded (/usr/lib/systemd/system/openhab2.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2018-01-18 11:17:58 EST; 23h ago
     Docs: http://docs.openhab.org
           https://community.openhab.org
  Process: 3565 ExecStop=/usr/share/openhab2/runtime/bin/karaf stop (code=exited, status=0/SUCCESS)
 Main PID: 3931 (java)
    Tasks: 115
   Memory: 1.4G
      CPU: 2h 26min 32.431s
   CGroup: /system.slice/openhab2.service
           └─3931 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dope...

Jan 19 04:11:33 seb-server karaf[3931]: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "pool-44-thread-1"
Jan 19 04:12:15 seb-server karaf[3931]: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HttpClient@938571522-54487"
Jan 19 04:13:51 seb-server karaf[3931]: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HttpClient@1205478117-54486"
Jan 19 04:14:12 seb-server karaf[3931]: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HttpClient@752566810-54492"
Jan 19 04:14:18 seb-server karaf[3931]: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HttpClient@113430139-54485"
Jan 19 04:15:11 seb-server karaf[3931]: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HttpClient@938571522-54484"
Jan 19 04:15:16 seb-server karaf[3931]: Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "HttpClient@938571522-54491"
Jan 19 04:16:12 seb-server karaf[3931]: Exception in thread "pool-3958-thread-3" java.lang.OutOfMemoryError: Java heap space
Jan 19 04:16:12 seb-server karaf[3931]: Exception in thread "pool-3956-thread-1" java.lang.OutOfMemoryError: Java heap space
Jan 19 04:16:12 seb-server karaf[3931]: Exception in thread "pool-3958-thread-2" java.lang.OutOfMemoryError: Java heap space

It might be because I always keep an OpenHab tab open on my work machine? (connected to my OpenHab server at home via my personal openhab-cloud server (setup with these instructions). It’s still quite hypothetical, having the heap profiling enabled will tell me the truth (hopefully).

Adding the content of “log:tail” to this thread for completeness:

03:33:00.079 [ERROR] [home.binding.wemo.handler.WemoHandler] - Failed to get actual state for device 'wemo:socket:Socket-1_0-221327K0100529': Could not call WeMo
03:34:28.285 [WARN ] [se.jetty.util.thread.QueuedThreadPool] -     java.lang.OutOfMemoryError: Java heap space
03:34:25.539 [WARN ] [hannel.socket.nio.AbstractNioSelector] - Unexpected exception in the selector loop.
java.lang.OutOfMemoryError: Java heap space
        at java.util.HashMap$KeySet.iterator(HashMap.java:917) ~[?:?]
        at java.util.HashSet.iterator(HashSet.java:173) ~[?:?]
        at java.util.Collections$UnmodifiableCollection$1.<init>(Collections.java:1039) ~[?:?]
        at java.util.Collections$UnmodifiableCollection.iterator(Collections.java:1038) ~[?:?]
        at org.jboss.netty.channel.socket.nio.NioClientBoss.processConnectTimeout(NioClientBoss.java:119) ~[?:?]
        at org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:83) ~[?:?]
        at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:318) ~[?:?]
        at org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
03:34:25.538 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.addConditionWaiter(AbstractQueuedSynchronizer.java:1855) ~[?:?]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2068) ~[?:?]
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392) ~[91:org.eclipse.jetty.util:9.3.22.v20171030]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:563) ~[91:org.eclipse.jetty.util:9.3.22.v20171030]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:48) ~[91:org.eclipse.jetty.util:9.3.22.v20171030]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626) [91:org.eclipse.jetty.util:9.3.22.v20171030]
        at java.lang.Thread.run(Thread.java:748) [?:?]
04:07:51.080 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@5da7ff03 in HttpClient@113430139{STARTED,8<=8<=200,i=0,q=0}
04:07:51.058 [INFO ] [.internal.service.FeaturesServiceImpl] - Adding features: 
04:07:51.053 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@2caed57f in HttpClient@1205478117{STARTED,8<=8<=200,i=0,q=0}
04:07:51.053 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@32a8f1cf in HttpClient@938571522{STARTED,8<=9<=200,i=0,q=0}
04:07:48.084 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
04:07:48.084 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - 
java.lang.OutOfMemoryError: Java heap space
04:07:51.142 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@32a8f1cf in HttpClient@938571522{STARTED,8<=9<=200,i=2,q=0}
04:07:51.123 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@256e12e4 in HttpClient@752566810{STARTED,8<=8<=200,i=0,q=0}
04:07:51.145 [WARN ] [se.jetty.util.thread.QueuedThreadPool] - Unexpected thread death: org.eclipse.jetty.util.thread.QueuedThreadPool$2@32a8f1cf in HttpClient@938571522{STARTED,8<=9<=200,i=2,q=0}

Quick update, I’m still observing OOMs but I also got heap dumps for some of them! I’ll look at the data to see what can cause this, I call this progress!

The heap dump tells me that: “One instance of “org.eclipse.smarthome.io.rest.sitemap.internal.SitemapResource” loaded by “org.eclipse.smarthome.io.rest.sitemap” occupies 889,085,688 (89.27%) bytes. The memory is accumulated in one instance of “org.eclipse.smarthome.io.rest.sitemap.internal.SitemapResource” loaded by “org.eclipse.smarthome.io.rest.sitemap”.”

Not sure if it’s helpful, but here’s the “path to GC roots” for this object:

Class Name                                                                                               | Shallow Heap | Retained Heap
----------------------------------------------------------------------------------------------------------------------------------------
org.eclipse.smarthome.io.rest.sitemap.internal.SitemapResource @ 0xc70d9ec8                              |           48 |   889,085,688
|- m_implementationObject org.apache.felix.scr.impl.manager.ComponentContextImpl @ 0xc5c8ef58            |           56 |           720
|  '- m_componentContext org.apache.felix.scr.impl.manager.SingleComponentManager @ 0xc7071280           |          104 |         1,816
|     |- value java.util.HashMap$Node @ 0xc56b6998                                                       |           32 |            56
|     |  '- [139] java.util.HashMap$Node[512] @ 0xc56b40e0                                               |        2,064 |        14,056
|     |     '- table java.util.HashMap @ 0xc446a560                                                      |           48 |        14,104
|     |        '- m_componentsById org.apache.felix.scr.impl.ComponentRegistry @ 0xc5e65588              |           48 |        89,936
|     |           '- m_componentRegistry org.apache.felix.scr.impl.Activator @ 0xc5d832f8                |           80 |        31,560
|     |              '- logger org.apache.felix.scr.impl.ComponentActorThread @ 0xc5d89e18               |           24 |            24
|     |                 '- <Java Local>, target java.lang.Thread @ 0xc5d89c80  SCR Component Actor Thread|          120 |           592
----------------------------------------------------------------------------------------------------------------------------------------

Hey @sebmarchand,
Great research so far. SitemapResource have few references, but I don’t think they are leading to OOM. With such case you would see dominant object who would be next in the list having big percentage of sitemap resource memory allocation.

I see one suspicious filed which keep events in memory, but according to this field declaration values should be evicted once memory limit comes close.

Can you check what is next type in the list or browse with object explorer (such Yourkit) particular fields of SitemapResource and see which reference is causing troubles?

I’m not super familiar with Java heap profiling, but is it the kind of thing I should look at? (using Eclipse Memory Analizer). I’ll look at this more later this week otherwise (I also have a heap dump that I can share if this doesn’t contain any private info)

Class Name                                                                       | Shallow Heap | Retained Heap | Percentage
-----------------------------------------------------------------------------------------------------------------------------
org.eclipse.smarthome.io.rest.sitemap.internal.SitemapResource @ 0xc70d9ec8      |           48 |   889,085,688 |     89.27%
|- org.eclipse.smarthome.io.rest.sitemap.internal.SitemapEventOutput @ 0xc7c1f2a8|           72 |     1,847,432 |      0.19%
|- org.eclipse.smarthome.io.rest.sitemap.internal.SitemapEventOutput @ 0xf7a05ed8|           72 |     1,843,736 |      0.19%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfbad4118                        |           64 |     1,814,672 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfce3ba40                        |           64 |     1,812,928 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfd0ed680                        |           64 |     1,812,928 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfbc40500                        |           64 |     1,812,856 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfb6cbdf8                        |           64 |     1,810,616 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfa166738                        |           64 |     1,810,328 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfbdd0420                        |           64 |     1,810,328 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfc0a7290                        |           64 |     1,810,328 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfc2c2968                        |           64 |     1,810,328 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfc4f3c88                        |           64 |     1,810,328 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfc779ce8                        |           64 |     1,810,328 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfc9e08c0                        |           64 |     1,810,328 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xf9f18758                        |           64 |     1,799,608 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfacca340                        |           64 |     1,799,608 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfabd3bd8                        |           64 |     1,797,376 |      0.18%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfb4c4110                        |           64 |     1,657,776 |      0.17%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfb02db10                        |           64 |     1,578,232 |      0.16%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfa2b2398                        |           64 |     1,421,792 |      0.14%
|- org.glassfish.jersey.server.ServerRuntime @ 0xfb205a80                        |           64 |     1,421,792 |      0.14%
|- org.glassfish.jersey.server.ServerRuntime @ 0xc5a85640                        |           64 |     1,413,176 |      0.14%
|- org.glassfish.jersey.server.ServerRuntime @ 0xc8356050                        |           64 |     1,413,176 |      0.14%
|- org.glassfish.jersey.server.ServerRuntime @ 0xc836d3d0                        |           64 |     1,413,176 |      0.14%
|- org.glassfish.jersey.server.ServerRuntime @ 0xcb298490                        |           64 |     1,413,176 |      0.14%
'- Total: 25 of 211,812 entries; 211,787 more                                    |              |               |           
-----------------------------------------------------------------------------------------------------------------------------

And the “Path to GC” for these ServerRuntime objects seems to point to the event logging:

Class Name                                                                                             | Shallow Heap | Retained Heap
--------------------------------------------------------------------------------------------------------------------------------------
org.glassfish.jersey.server.ServerRuntime @ 0xfce3ba40                                                 |           64 |     1,812,928
'- runtime org.glassfish.jersey.server.ServerRuntime$Responder @ 0xfce3b6a0                            |           32 |           104
   '- responder org.glassfish.jersey.server.ServerRuntime$AsyncResponderHolder @ 0xfce3ba20            |           32 |            32
      '- delegate org.glassfish.jersey.internal.util.collection.Values$LazyValueImpl @ 0xfce3b9f8      |           24 |            72
         '- asyncContext org.eclipse.smarthome.io.rest.sitemap.internal.SitemapEventOutput @ 0xfce359b0|           72 |        23,776
            '- referent com.google.common.collect.MapMakerInternalMap$WeakValueReference @ 0xfce658d0  |           32 |            32
               '- valueReference com.google.common.collect.MapMakerInternalMap$StrongEntry @ 0xfce658b0|           32 |           192
                  '- [442] java.lang.Object[1024] @ 0xe8df4dd8                                         |        4,112 |        41,232
                     '- array java.util.concurrent.atomic.AtomicReferenceArray @ 0xe8df4dc8            |           16 |        41,248
                        '- table com.google.common.collect.MapMakerInternalMap$Segment @ 0xc70da468    |           64 |        41,408
                           '- [0] com.google.common.collect.MapMakerInternalMap$Segment[4] @ 0xc70da268|           32 |       162,848
--------------------------------------------------------------------------------------------------------------------------------------

And now that I think about it I’ve often observed an error message in BasicUI saying “Offline: waiting for connection to become available” , despite being fully functional. Is it possible that an event get triggered each time this happen and doesn’t get freed?

So the error message I’m seeing in BasicUI might be caused by this: https://github.com/eclipse/smarthome/issues/4871 , but it still shouldn’t leak in the SitemapResource object…

Feel free to enter another issue at https://github.com/eclipse/smarthome/issues.

Thanks, I’ve opened https://github.com/eclipse/smarthome/issues/5008

@sebmarchand It looks like your bug and related bugs are closed. Did it resolve your issue?

--------------------------------------------------------------------------------------------------------------------------------------------------
                                                                                                                   |              |              
java.util.concurrent.LinkedBlockingDeque @ 0x815e22d40                                                             |           40 |   545 958 320
'- queue org.eclipse.smarthome.io.rest.sitemap.internal.SitemapEventOutput @ 0x815e22cf8                           |           72 |   545 958 440
   '- item java.util.concurrent.ConcurrentLinkedQueue$Node @ 0x815e22ce0                                           |           24 |            24
      '- head java.util.concurrent.ConcurrentLinkedQueue @ 0x813a341c8                                             |           24 |            96
         '- chunkedOutputs org.glassfish.jersey.media.sse.SseBroadcaster @ 0x813a34150                             |           24 |           216
            '- broadcaster org.eclipse.smarthome.io.rest.sitemap.internal.SitemapResource @ 0x813a340f8            |           64 |   545 960 600
               |- arg$1 org.eclipse.smarthome.io.rest.sitemap.internal.SitemapResource$$Lambda$211 @ 0x813a34620   |           16 |            16
               |  '- task java.util.concurrent.Executors$RunnableAdapter @ 0x813a34608                             |           24 |            40
               |     '- callable java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask @ 0x813a345c0|           72 |           112
               |        '- [1] java.util.concurrent.RunnableScheduledFuture[16] @ 0x814286d20                      |           80 |            80
               |           '- queue java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue @ 0x8143aeee0|           32 |           112
               |- m_implementationObject org.apache.felix.scr.impl.manager.ComponentContextImpl @ 0x814167710      |           56 |           848
               |- cachedService org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse @ 0x81550bc78          |           40 |            40
               '- Total: 3 entries                                                                                 |              |              
--------------------------------------------------------------------------------------------------------------------------------------------------

mem.txt (2.6 KB)

Heap in my openhab instance grow ~150 Mb/day

Yes, I haven’t observed any issue with memory usage recently. Thanks for the fixes!

I think I still have this issue, have started with a GitHub Issue before I found this thread.