- Platform information:
- Hardware: Intel(R) 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?