Identifying problematic item (out of Memory / Java heap)

NCO · October 26, 2018, 6:52am

I am running openhabian v1.4.1-416(de039da) on a raspberry pi 3 (OH 2.4 M4)
The problem below is true for 2.3 stable as well:

I get another java heap space error (OOM) 17 minutes after a restart

2018-10-26 07:29:49.207 [INFO ] [.binding.km200.internal.KM200Binding] - ... Update of the KM200 Binding configuration completed
2018-10-26 07:29:49.242 [INFO ] [b.core.service.AbstractActiveService] - KM200 Binding has been started
2018-10-26 07:29:57.830 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2018-10-26 07:29:57.834 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'
2018-10-26 07:29:57.834 [INFO ] [b.core.service.AbstractActiveService] - Denon Refresh Service has been started
2018-10-26 07:30:00.015 [INFO ] [arthome.model.script.moverules.rules] - system started triggered
2018-10-26 07:30:00.260 [INFO ] [arthome.model.script.moverules.rules] - timer created
2018-10-26 07:30:00.278 [INFO ] [marthome.model.script.startup.rules:] - --------> System / Config reloaded <--------.
2018-10-26 07:34:00.036 [INFO ] [arthome.model.script.moverules.rules] - rename rules back in
2018-10-26 07:34:00.048 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/etc/openhab2/scripts/moverules.sh rules_away rules'
2018-10-26 07:34:37.685 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'abus.rules'
2018-10-26 07:34:48.406 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alexa.rules'
2018-10-26 07:36:41.368 [INFO ] [.smarthome.model.script.abus.rules: ] - Guard_Mode check: 1
2018-10-26 07:36:41.513 [INFO ] [smarthome.model.script.alexa.rules: ] - Ranzen set to Alexa
2018-10-26 07:36:41.966 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'berling.rules'
2018-10-26 07:37:18.247 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'car.rules'
2018-10-26 07:38:07.077 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'car_state.rules'
2018-10-26 07:38:30.649 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1202306' takes more than 5000ms.
2018-10-26 07:40:26.729 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1202306' takes more than 5000ms.
2018-10-26 07:41:45.592 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1202306' takes more than 5000ms.
2018-10-26 07:42:47.835 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1202306' takes more than 5000ms.
2018-10-26 07:43:32.403 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.config.discovery.internal.AutomaticInboxProcessor@9741a6' takes more than 5000ms.
2018-10-26 07:43:34.987 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@f9d79f' takes more than 5000ms.
2018-10-26 07:43:50.255 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1202306' takes more than 5000ms.
2018-10-26 07:44:39.490 [WARN ] [t.mqtt.internal.MqttBrokerConnection] - MQTT connection to 'mosquitto' was lost: Verbindung wurde getrennt : ReasonCode 32109 : Cause : null
2018-10-26 07:44:36.886 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1202306': 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:591) ~[?:?]
        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.GeneratedMethodAccessor26.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-10-26 07:45:01.166 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting connection helper to periodically try restoring connection to broker 'mosquitto'
2018-10-26 07:45:12.391 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'

I assume that there is an issue with a specific item / thing.
So, how to find out what

"org.eclipse.smarthome.core.internal.items.ItemUpdater@1202306"

is referring to?

mstormi · October 26, 2018, 7:06am

Well it says you’re out of Java heap space. What Java options do you use ? Try adding -Xmx600m.

NCO · October 26, 2018, 7:53am

Thanks for your help.
How do I set this?
And is this the right way to fight the symptoms instead of the root cause?

So I assume there is no way to find out what this is referring to?

I though this would help to identify the binding handling this item or such.

mstormi · October 26, 2018, 8:03am

EXTRA_JAVA_OPTS in /etc/default/openhab2.
Use ps -ef|grep java to see if it’s already started with those options.
Execute java -XX:+PrintFlagsFinal -version | findstr HeapSize, too.

It isn’t fighting symptoms, it’s to analyse if you hit the default maximum Java heap size, and if you do then it’s the proper fix, too.

NCO · October 26, 2018, 9:27am

I currently have

EXTRA_JAVA_OPTS="-XX:+HeapDumpOnOutOfMemoryError"

but will change it as suggested.

java -XX:+PrintFlagsFinal -version | grep HeapSize

returns:

[11:22:44] openhabian@Homer:~$ java -XX:+PrintFlagsFinal -version | grep HeapSize
    uintx ErgoHeapSizeLimit                         = 0                                   {product}
    uintx HeapSizePerGCThread                       = 67108864                            {product}
    uintx InitialHeapSize                          := 16777216                            {product}
    uintx LargePageHeapSizeThreshold                = 134217728                           {product}
    uintx MaxHeapSize                              := 255852544                           {product}
openjdk version "1.8.0_152"
OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76)
OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)

H102 · October 26, 2018, 11:32am

Here’s a great tutorial for RPI users that includes java memory management.
https://community.openhab.org/t/solutions-for-lazy-execution-of-rules/52956?u=h102

NCO · November 15, 2018, 6:05am

All,

I am using the following since quite a while (weeks):

EXTRA_JAVA_OPTS="-Xms400m -Xmx650m"

and everything seems to work fine.

However, after activating amazon echo control binding I see heap space issues again:

    2018-11-14 20:15:37.155 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'EventSubscriber.receive()' on 'org.eclipse.smarthome.core.internal.items.ItemUpdater@4c0be': Java heap space
java.lang.OutOfMemoryError: Java heap space

So how to find out what ItemUpdater@4c0be is referring to?
Is there a way to identify this item?

mstormi · November 15, 2018, 7:15am

None that I know of. You can possibly enable big time logging (org.smarthome.eclipse.core.internal to debug) and restart, then grep for lines of that ID in log.
But it’s well possible that the error is unrelated to that item but rather to the binding.

NCO · November 15, 2018, 10:05am

This is fine as well and would help to verify which binding is causing this issue.
I suspect the amazonechocontrol binding…

illnesse · November 15, 2018, 10:36am

Just out of curiousity, how many items, bindings and rules do you have?

NCO · November 15, 2018, 11:14am

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.

NCO · November 17, 2018, 6:11am

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

NCO · November 17, 2018, 6:23am

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).

Dim · November 17, 2018, 6:24am

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

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

NCO · November 17, 2018, 6:29am

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

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

Dim · November 17, 2018, 6:31am

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

NCO · November 17, 2018, 6:35am

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

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

Again.
Thanks for your help.

Dim · November 17, 2018, 6:36am

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

Good morning !

Dim · November 17, 2018, 6:42am

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.

NCO · November 17, 2018, 6:58am

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.