Identifying problematic item (out of Memory / Java heap)

Items: ~650
Bindings: amazondashbutton,astro,denon1,exec,fritzboxtr0641,harmonyhub,http1,km1001,mqtt1,mqttitude1,neato,netatmo,network,ntp,systeminfo,tankerkoenig,tcp1,wol1,weatherunderground,zwave
rules: 25 rule files with 327 rules

The thing is:
after a restart I got a java heap space error after less than 60 min.

EDIT:
This did not happen last week (AEC binding was removed) - however this was with M4 (have M5 today).
I will do another test with M5 and without AEC binding.

Same thing, with amazon echo control it happened again.

2018-11-16 21:41:44.048 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1ebbd82': Java heap space java.lang.OutOfMemoryError: Java heap space

Why restart?
Shouldn’t this do the job in karaf without a restart?

log:set DEBUG org.smarthome.eclipse.core.internal

Thanks - I will give it a try.
I am curious if it’s really the amazon echo binding (must be).

It will but he wants you to capture (also) the initial loading of the features during startup (I believe so :slight_smile:)

From what I remember, only during startup you can see some log entries regarding the loading of bundles and features etc.

Alright - thank you very much for the lightning fast response. :slight_smile:

So changing the log level in karaf will persist after restart without touching a loglevel file?
Sorry, I was ususally able to figure out the issues without a log level change

Yes, since any log:set command will be recorded as a setting permanently at the end of $OPENHAB_USERDATA/etc/org.ops4j.pax.logging.cfg

(after this section):

# OSGi appender
log4j2.appender.osgi.type = PaxOsgi
log4j2.appender.osgi.name = OSGI
log4j2.appender.osgi.filter = *

<it will appear here>

Even if you issue log:set DEFAULT ... it will stay there. I usually go in once a month and remove those autogenerated entries and keep my custom config :stuck_out_tongue:

Makes sense!
Thanks a lot.

I know this file (removed some obsolete stuff from events.log like CPU and Mem messages of system info binding), but I prefer karaf because messing up the config file manually is too easy :smiley:

I assume you’re located in Europe as well if you are up right now.
or US West coast :smiley:

Again.
Thanks for your help.

1 Like

Currently, Europe/Athens :sun_with_face: but most of the time, I am in Europe/Bucharest :snowflake: (it’s snowing)

Good morning !

can you post the contents of your rule handling this rules in/out during startup?

Does this WARN appear always after the loading of ‘car_state.rules’ file or it’s random?

You can fix this. Try adding pid:org.openhab.mqtt as the very first line in your $OPENHAB_CONF/services/mqtt.cfg file to see if this WARN goes away.

Athens… nice I am jealous.

It mainly from the forum here to ensure that the rules are loaded after the core is up and running:

val Integer secondsDelay = 240
val String executeCmdBack = "/etc/openhab2/scripts/moverules.sh rules_away rules"
val String executeCmdAway = "/etc/openhab2/scripts/moverules.sh rules rules_away"

var Timer renameTimer = null

rule "rename rules back in"
when 
    System started
then    
    logInfo("moverules.rules", "system started triggered")

    if (renameTimer === null) {
        renameTimer = createTimer(now.plusSeconds(secondsDelay)) [|
            logInfo("moverules.rules", "rename rules back in")
            executeCommandLine(executeCmdBack)
            sendTelegram("OH_TeleBot", "moverules -> back")
        ]
        logInfo("moverules.rules", "timer created")
    }
    else 
    {
        logInfo("moverules.rules", "timer already existing")
    }

	if(System_started.state == ON) {
		System_started.postUpdate(OFF)
	}
	else {
		System_started.postUpdate(ON)
	}
	logInfo("startup.rules:", "--------> System / Config reloaded <--------.")
	sendTelegram("OH_TeleBot", "System / Config wurde neu geladen.")
end

rule "rename rules away"
when 
System shuts down
then 
logInfo("moverules.rules", "rename rules away")
executeCommandLine(executeCmdAway)
sendTelegram("OH_TeleBot", "moverules -> away")
end    

No, that’s random.

By the way, I don’t see DEBUG entries in the openhab.log.
I switched this on for zwave as well (which should send a lot of DEBUG messages), but I don’t see them either.

post your $OPENHAB_USERDATA/etc/org.ops4j.pax.logging.cfg just to double check it

free space (df -h) on the rPi3 is enough… correct ? :slight_smile:

Did you ever analyze the generated heapdump file? With this option it generates a copy of the Java memory to a file when it runs out of memory. So you can analyze what is the root cause and if there is a memory leak.

See also:

How to find the cause of a OutOfMemoryError in OH2?

Ahhh I see you did in How to find the cause of a OutOfMemoryError in OH2? . Looks like it is caused by the sitemap events.

brings:

[15:10:21] openhabian@Homer:~$ df -h
Dateisystem Größe Benutzt Verf. Verw% Eingehängt auf
/dev/root 30G 8,5G 20G 31% /
devtmpfs 481M 0 481M 0% /dev
tmpfs 486M 32K 486M 1% /dev/shm
tmpfs 486M 50M 437M 11% /run
tmpfs 5,0M 4,0K 5,0M 1% /run/lock
tmpfs 486M 0 486M 0% /sys/fs/cgroup
/dev/sda1 41M 21M 20M 52% /boot
192.168.178.39:/volume1/openhab/backup 2,7T 1,8T 903G 68% /mnt/nfs/openhab/backup

contains:

log4j2.logger.amazon\ echo\ control\ binding.level = DEBUG
log4j2.logger.amazon\ echo\ control\ binding.name = Amazon Echo Control Binding
log4j2.logger.zwave\ binding.level = DEBUG
log4j2.logger.zwave\ binding.name = ZWave Binding

I used this in the beginning and had a look into it with Mem-Analyzer, but must admit that I had difficulties to interpret it.

After I increased the memory, I though I have solved the issue, but then it popped up again.

try replacing the delimiter from \ to _
and the name is something like: org.openhab.xyz

log4j2.logger.amazon_echo_control_binding.level = DEBUG
log4j2.logger.amazon_echo_control_binding.name = <org.openhab.xyz>

log4j2.logger.zwave_binding.level = DEBUG
log4j2.logger.zwave_binding.name = org.openhab.binding.zwave

alright.
I will delete the lines and set it new from karaf with the “real” jar-file name.
Thank you!

EDIT:
That’s better.
Now I see the DEBUG entries and will wait for the heap space error… :wink:

1 Like

Ooops - it did it again…

Regular restart:

2018-11-17 19:14:21.134 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2018-11-17 19:14:21.755 [INFO ] [arthome.model.script.moverules.rules] - system started triggered
2018-11-17 19:14:21.764 [INFO ] [arthome.model.script.moverules.rules] - timer already existing
2018-11-17 19:14:21.777 [INFO ] [marthome.model.script.startup.rules:] - --------> System / Config reloaded <--------.
...
2018-11-17 19:41:00.090 [DEBUG] [control.internal.WebSocketConnection] - Send Ping
2018-11-17 19:41:00.112 [DEBUG] [control.internal.WebSocketConnection] - Send message with length 98
2018-11-17 19:41:00.228 [DEBUG] [control.internal.WebSocketConnection] - Pong received
2018-11-17 19:43:24.098 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@d3076c' takes more than 5000ms.
2018-11-17 19:44:00.254 [DEBUG] [control.internal.WebSocketConnection] - Send Ping
2018-11-17 19:44:00.380 [DEBUG] [control.internal.WebSocketConnection] - Send message with length 98
2018-11-17 19:44:00.488 [DEBUG] [control.internal.WebSocketConnection] - Pong received
2018-11-17 19:44:19.045 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1bef69' takes more than 5000ms.
2018-11-17 19:44:37.310 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@d3076c' takes more than 5000ms.
2018-11-17 19:45:48.218 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@d3076c' takes more than 5000ms.
2018-11-17 19:46:06.017 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.core.internal.items.ItemUpdater@d3076c': Java heap space
java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:3332) ~[?:?]
    at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124) ~[?:?]
    at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448) ~[?:?]
    at java.lang.StringBuffer.append(StringBuffer.java:270) ~[?:?]
    at java.io.StringWriter.write(StringWriter.java:112) ~[?:?]
    at com.google.gson.stream.JsonWriter.string(JsonWriter.java:585) ~[?:?]
    at com.google.gson.stream.JsonWriter.value(JsonWriter.java:419) ~[?:?]
    at com.google.gson.internal.bind.TypeAdapters$16.write(TypeAdapters.java:422) ~[?:?]
    at com.google.gson.internal.bind.TypeAdapters$16.write(TypeAdapters.java:406) ~[?:?]
    at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.write(TypeAdapterRuntimeTypeWrapper.java:69) ~[?:?]
    at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.write(ReflectiveTypeAdapterFactory.java:125) ~[?:?]
    at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.write(ReflectiveTypeAdapterFactory.java:243) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:669) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:648) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:603) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:583) ~[?:?]
    at org.eclipse.smarthome.core.events.AbstractEventFactory.serializePayload(AbstractEventFactory.java:85) ~[?:?]
    at org.eclipse.smarthome.core.items.events.ItemEventFactory.createStateChangedEvent(ItemEventFactory.java:304) ~[?:?]
    at org.eclipse.smarthome.core.items.GenericItem.sendStateChangedEvent(GenericItem.java:231) ~[?:?]
    at org.eclipse.smarthome.core.items.GenericItem.applyState(GenericItem.java:225) ~[?:?]
    at org.eclipse.smarthome.core.items.GenericItem.setState(GenericItem.java:209) ~[?:?]
    at org.eclipse.smarthome.core.library.items.ImageItem.setState(ImageItem.java:64) ~[?:?]
    at org.eclipse.smarthome.core.internal.items.ItemUpdater.receiveUpdate(ItemUpdater.java:78) ~[?:?]
    at org.eclipse.smarthome.core.items.events.AbstractItemEventSubscriber.receive(AbstractItemEventSubscriber.java:50) ~[?:?]
    at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) ~[?:?]
    at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:?]
2018-11-17 19:46:43.096 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@14ad210' takes more than 5000ms.
2018-11-17 19:46:18.868 [ERROR] [me.core.internal.events.EventHandler] - Dispatching/filtering event for subscriber 'org.eclipse.smarthome.core.events.EventSubscriber' failed: Java heap space
java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:3332) ~[?:?]
    at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124) ~[?:?]
    at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448) ~[?:?]
    at java.lang.StringBuffer.append(StringBuffer.java:270) ~[?:?]
    at java.io.StringWriter.write(StringWriter.java:112) ~[?:?]
    at com.google.gson.stream.JsonWriter.string(JsonWriter.java:585) ~[?:?]
    at com.google.gson.stream.JsonWriter.value(JsonWriter.java:419) ~[?:?]
    at com.google.gson.internal.bind.TypeAdapters$16.write(TypeAdapters.java:422) ~[?:?]
    at com.google.gson.internal.bind.TypeAdapters$16.write(TypeAdapters.java:406) ~[?:?]
    at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.write(TypeAdapterRuntimeTypeWrapper.java:69) ~[?:?]
    at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.write(ReflectiveTypeAdapterFactory.java:125) ~[?:?]
    at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.write(ReflectiveTypeAdapterFactory.java:243) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:669) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:648) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:603) ~[?:?]
    at com.google.gson.Gson.toJson(Gson.java:583) ~[?:?]

I don’t see a direct link to amazonechocontrol though…

this does not work:

 Could not parse line 'pid:org.openhab.mqtt'

do you mean:
mosquitto.pid=org.openhab.mqtt

is it the first line in your /etc/openhab2/services/mqtt.cfg ?

it should look like:

pid:org.openhab.mqtt
...