search

openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
914 stars 422 forks source link

Openhab's Java is using 120% CPU #1369

Closed openPhiL closed 3 years ago

openPhiL commented 4 years ago

Hi guys, I am running OpenHab 2.5M4 (in VMware, using Openhabian) since month, and upgraded to the latest stable (2.5.1-2) yesterday. First, I had a strugle that font's were missing, which I added by apt-get .. (see Issue https://github.com/openhab/openhabian/issues/748) Now (I haven't done anything else than opening the sitemap that shows the humidity in graphs), image and this happend: image image

I have no idea what else I can show you, system is not really responding, had to "systemctl restart openhab2" - works again. Maybe there is something you can do to prevent errors like that? Sorry for the little information I have.. This issue can be closed if not helpful. Best regards PhiL

openPhiL commented 4 years ago

Ok, so it happened again, it's not a one-time thing.

openPhiL commented 4 years ago

found this thread https://community.openhab.org/t/outofmemoryerror-java-heap-space-after-a-few-days-of-running-openhab2/50077/15

Stefan300381 commented 4 years ago

Hi,

similar issues here after upgrading to 2.5.3 (not 4) I see heap errors like openPhiL, but my CPU consumption is OK with just a few single digit percentage.

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 8317 openhab   20   0  709648 587740  11912 S   7.8 29.0 491:53.78 java

All working fine until 2020-03-28 11:23:49.125 [WARN ]

2020-03-28 11:19:50.453 [GroupItemStateChangedEvent] - gBodySensors changed from ON to OFF through BodySensor_02

2020-03-28 11:19:50.459 [vent.ItemStateChangedEvent] - BodySensor_02 changed from ON to OFF

2020-03-28 11:19:50.472 [vent.ItemStateChangedEvent] - BodySensor_02_TIMESTAMP changed from 2020-03-28T11:17:50.455+0100 to 2020-03-28T11:19:50.459+0100

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

2020-03-28 11:22:39.004 [INFO ] [thome.model.script.bodysensors.rules] - Bewegungsmelder 'Wintergarten' Batterielevel: 86%

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

2020-03-28 11:22:53.127 [vent.ItemStateChangedEvent] - Astro_Elevation changed from 39.25270120509614 to 39.60145142446089

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

2020-03-28 11:23:49.125 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@6d3937' takes more than 5000ms.

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

2020-03-28 11:24:09.563 [hingStatusInfoChangedEvent] - 'shelly:shelly25-roller:7409ff' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Das Gerät ist nicht erreichbar (API Timeout).

2020-03-28 11:24:09.569 [hingStatusInfoChangedEvent] - 'shelly:shelly1:939959' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Das Gerät ist nicht erreichbar (API Timeout).

2020-03-28 11:24:32.746 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: Disconnected

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

2020-03-28 11:24:41.435 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@6272a9' takes more than 5000ms.

2020-03-28 11:25:10.033 [ERROR] [io.openhabcloud.internal.CloudClient] - Error connecting to the openHAB Cloud instance: {}

io.socket.engineio.client.EngineIOException: websocket error

    at io.socket.engineio.client.Transport.onError(Transport.java:63) [bundleFile:?]

    at io.socket.engineio.client.transports.WebSocket.access$400(WebSocket.java:24) [bundleFile:?]

    at io.socket.engineio.client.transports.WebSocket$1$5.run(WebSocket.java:107) [bundleFile:?]

    at io.socket.thread.EventThread$2.run(EventThread.java:80) [bundleFile:?]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]

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

Caused by: java.io.EOFException

    at okio.RealBufferedSource.require(RealBufferedSource.java:60) ~[?:?]

    at okio.RealBufferedSource.readByte(RealBufferedSource.java:73) ~[?:?]

    at okhttp3.internal.ws.WebSocketReader.readHeader(WebSocketReader.java:113) ~[?:?]

    at okhttp3.internal.ws.WebSocketReader.processNextFrame(WebSocketReader.java:97) ~[?:?]

    at okhttp3.internal.ws.RealWebSocket.loopReader(RealWebSocket.java:262) ~[?:?]

    at okhttp3.internal.ws.RealWebSocket$2.onResponse(RealWebSocket.java:201) ~[?:?]

    at okhttp3.RealCall$AsyncCall.execute(RealCall.java:141) ~[?:?]

    at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]

    ... 3 more

2020-03-28 11:30:19.509 [ERROR] [tt.handler.connect.MqttConnAckSingle] - Unexpected exception thrown by disconnected listener.

java.lang.OutOfMemoryError: Java heap space

2020-03-28 11:26:44.255 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

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

2020-03-28 11:25:13.116 [hingStatusInfoChangedEvent] - 'harmonyhub:hub:HarmonyHub2' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Could not connect: Disconnected

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

2020-03-28 11:25:19.116 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@6272a9' takes more than 5000ms.

2020-03-28 11:30:39.895 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - 

java.lang.OutOfMemoryError: Java heap space

2020-03-28 11:30:45.877 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = a78cf15e-09e4-4ef3-b9fd-86d00c79c33c, base URL = http://localhost:8000)

2020-03-28 11:32:20.545 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.IllegalStateException: Timer already cancelled.

    at java.util.Timer.sched(Timer.java:398) ~[?:?]

    at java.util.Timer.schedule(Timer.java:194) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.deferredCommit(JsonStorage.java:359) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.put(JsonStorage.java:142) ~[?:?]

    at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:116) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:261) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:1) ~[?:?]

    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1.thingUpdated(ThingManagerImpl.java:249) ~[?:?]

    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateProperties(BaseThingHandler.java:488) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.flushProperties(ShellyBaseHandler.java:820) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.fillDeviceStatus(ShellyBaseHandler.java:452) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.updateStatus(ShellyBaseHandler.java:364) ~[?:?]

    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]

    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]

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

2020-03-28 11:32:38.939 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.IllegalStateException: Timer already cancelled.

    at java.util.Timer.sched(Timer.java:398) ~[?:?]

    at java.util.Timer.schedule(Timer.java:194) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.deferredCommit(JsonStorage.java:359) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.put(JsonStorage.java:142) ~[?:?]

    at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:116) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:261) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:1) ~[?:?]

    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1.thingUpdated(ThingManagerImpl.java:249) ~[?:?]

    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateProperties(BaseThingHandler.java:488) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.flushProperties(ShellyBaseHandler.java:820) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.fillDeviceStatus(ShellyBaseHandler.java:452) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.updateStatus(ShellyBaseHandler.java:364) ~[?:?]

    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]

    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]

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

2020-03-28 11:33:12.302 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = a78cf15e-09e4-4ef3-b9fd-86d00c79c33c, base URL = http://localhost:8000)

2020-03-28 11:33:36.149 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.IllegalStateException: Timer already cancelled.

    at java.util.Timer.sched(Timer.java:398) ~[?:?]

    at java.util.Timer.schedule(Timer.java:194) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.deferredCommit(JsonStorage.java:359) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.put(JsonStorage.java:142) ~[?:?]

    at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:116) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:261) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:1) ~[?:?]

    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1.thingUpdated(ThingManagerImpl.java:249) ~[?:?]

    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateProperties(BaseThingHandler.java:488) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.flushProperties(ShellyBaseHandler.java:820) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.fillDeviceStatus(ShellyBaseHandler.java:452) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.initializeThing(ShellyBaseHandler.java:258) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.updateStatus(ShellyBaseHandler.java:343) ~[?:?]

    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]

    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]

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

2020-03-28 13:02:44.176 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.IllegalStateException: Timer already cancelled.

    at java.util.Timer.sched(Timer.java:398) ~[?:?]

    at java.util.Timer.schedule(Timer.java:194) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.deferredCommit(JsonStorage.java:359) ~[?:?]

    at org.eclipse.smarthome.storage.json.internal.JsonStorage.put(JsonStorage.java:142) ~[?:?]

    at org.eclipse.smarthome.core.common.registry.AbstractManagedProvider.update(AbstractManagedProvider.java:116) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:261) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1$1.run(ThingManagerImpl.java:1) ~[?:?]

    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]

    at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$1.thingUpdated(ThingManagerImpl.java:249) ~[?:?]

    at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateProperties(BaseThingHandler.java:488) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.flushProperties(ShellyBaseHandler.java:820) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.fillDeviceStatus(ShellyBaseHandler.java:452) ~[?:?]

    at org.openhab.binding.shelly.internal.handler.ShellyBaseHandler.updateStatus(ShellyBaseHandler.java:364) ~[?:?]

    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]

    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?]

    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]

    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]

    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]

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

2020-03-28 13:05:16.645 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = a78cf15e-09e4-4ef3-b9fd-86d00c79c33c, base URL = http://localhost:8000)

2020-03-28 13:07:44.488 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2020-03-28 13:08:20.631 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2020-03-28 13:09:07.715 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space

2020-03-28 13:09:39.257 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 

java.lang.OutOfMemoryError: Java heap space
openPhiL commented 4 years ago

are you happen to use ms code as your IDE? I was able to trace it to that ms code as it only happens when I use it to change files. I also realized I had a "lot" of errors. So I turned off the LSP-service in MS CODE .. with some other things I think, but now i got it under control. image

Stefan300381 commented 4 years ago

no, I just use vim ;-) So, meanwhile I cleaned the cache and rebooted (although I did this already right after upgrading). Just to be on the safe side I increased the xmx value in /etc/default/openhab2 to 550M. Looks good so far:

top - 19:54:02 up  5:19,  1 user,  load average: 0.32, 0.23, 0.19
Tasks: 127 total,   1 running,  74 sleeping,   0 stopped,   0 zombie
%Cpu(s):  2.0 us,  1.7 sy,  0.0 ni, 96.1 id,  0.0 wa,  0.0 hi,  0.2 si,  0.0 st
KiB Mem :  2028932 total,   828884 free,   648644 used,   551404 buff/cache
KiB Swap:  1014464 total,  1014464 free,        0 used.  1313104 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 8104 openhab   20   0  917976 477872  12180 S   7.8 23.6  46:54.19 java
martinstuga commented 4 years ago

Hi @openPhiL , have you been able to solve this? It looks like a java heap space issue, so, increasing the Xmx as @Stefan300381 suggested might solve. Can you confirm if you managed to solved it and how?

Thanks.

kaikreuzer commented 3 years ago

openHAB 2.5 is out of support (for core issues), so I'd suggest to close this issue. If you experience something similar in openHAB 3, feel free to create a new one, but this will anyhow have different stacktraces then.