[SOLVED] Dispatching event to subscriber '...' takes more than 5000ms

Kellermeister · February 18, 2019, 5:24pm

the problem is the message “Dispatching event to subscriber ‘…’ takes more than 5000ms” (see log file below)
the system becomes very slow and is almost no longer usable/configurable. (very very slow)

what could this be and how can the origin of the problem be evaluated?

2019-02-18 18:11:48.518 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@10b5e5e' takes more than 5000ms.
2019-02-18 18:13:06.440 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@14870b7' takes more than 5000ms.
2019-02-18 18:13:18.089 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1ae5ec1' takes more than 5000ms.
2019-02-18 18:13:23.585 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@10b5e5e' takes more than 5000ms.
2019-02-18 18:13:29.095 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@10b5e5e' takes more than 5000ms.
2019-02-18 18:14:02.815 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@10b5e5e' takes more than 5000ms.
2019-02-18 18:14:24.946 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@10b5e5e' takes more than 5000ms.
2019-02-18 18:14:42.211 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@14870b7' takes more than 5000ms.
2019-02-18 18:14:52.441 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@e6d905' takes more than 5000ms.
2019-02-18 18:15:37.925 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@9d29b' takes more than 5000ms.
2019-02-18 18:15:55.057 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@e6d905' takes more than 5000ms.
2019-02-18 18:16:05.901 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.config.discovery.internal.AutomaticInboxProcessor@183f757' takes more than 5000ms.
2019-02-18 18:16:11.925 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.config.discovery.internal.AutomaticInboxProcessor@183f757' takes more than 5000ms.
2019-02-18 18:16:34.313 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1ae5ec1' takes more than 5000ms.
2019-02-18 18:16:39.892 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@10b5e5e' takes more than 5000ms.
2019-02-18 18:16:56.469 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1ae5ec1' takes more than 5000ms.
2019-02-18 18:17:18.220 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@10b5e5e' takes more than 5000ms.
2019-02-18 18:17:40.324 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.config.discovery.internal.AutomaticInboxProcessor@183f757' takes more than 5000ms.
2019-02-18 18:18:29.707 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1ae5ec1' takes more than 5000ms.
2019-02-18 18:18:57.688 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1ae5ec1' takes more than 5000ms.

Openhab Version 2.4.0
Hardware: Raspberry Pi 3

thanks a lot for a good tip on how i can analyze and fix the problem.

rlkoshak · February 18, 2019, 8:54pm

I could be wrong but I have a vague memory that this came up already and was fixed in OH 2.5 M1. I could be wrong but it’s worth a try.

rossko57 · February 18, 2019, 9:20pm

Cause and effect may be the other way around; system grinding to a halt is cause of delayed events processing?
See many other threads about thread pool, memory usage etc.

Kellermeister · February 25, 2019, 10:44pm

thanks for the replies.
i have no idea how to find the problem. does anyone have a tip?

rlkoshak · February 25, 2019, 11:06pm

Well, since it might already be fixed, I’d try upgrading to 2.5 M1 as a start. If there is a bug you’d have to do this anyway.

Kellermeister · February 26, 2019, 9:52pm

Thanks, how can i change from Release Version to Actual milestone? Where are these steps describded?

rlkoshak · February 26, 2019, 9:53pm

How did you install?

Kellermeister · February 26, 2019, 9:57pm

I had installed openhabian … Later Updated to Version 2.3 and 2.4

rlkoshak · February 26, 2019, 10:14pm

OK. In openhabian-config, go to “40. openHAB related” and switch to the “openHAB testing” which I think is the milestone builds.

Then I think you may need to run “02. Upgrade System”.

Kellermeister · March 2, 2019, 1:07pm

i have change now to the milestone and have upgrade the system.
but now, openhab doesn’t start.

2019-03-02 14:02:34.002 [ERROR] [org.openhab.binding.velux           ] - FrameworkEvent ERROR - org.openhab.binding.velux

org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.velux [74]

  Unresolved requirement: Import-Package: org.apache.commons.httpclient

	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]

	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1634) ~[?:?]

	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1614) ~[?:?]

	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1585) ~[?:?]

	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1528) ~[?:?]

	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1) ~[?:?]

	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]

	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]

2019-03-02 14:02:36.632 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.velux-1.14.0-SNAPSHOT.jar

org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.velux [74]

  Unresolved requirement: Import-Package: org.apache.commons.httpclient

	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]

	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]

	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]

	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]

	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1221) [10:org.apache.felix.fileinstall:3.6.4]

	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:515) [10:org.apache.felix.fileinstall:3.6.4]

	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]

	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]

how can i analyse this problem? what can i do?

rlkoshak · March 2, 2019, 4:58pm

First thing to try is Clear the Cache

Kellermeister · March 2, 2019, 5:16pm

I have found a same issue about update to version 2.3 …
openhab hadn’t started anymore.

with the following commands it had worked again, and also worked for me when updating to Milestone

sudo chown -R openhab:openhab /var/lib/openhab2
sudo chown -R openhab:openhab /etc/openhab2
sudo systemctl enable openhab2

problem is fixed … thanks

nibbs · March 4, 2019, 8:58pm

Hi there, I’m running OH 2.4 in Docker and have the same problem. Unfortunately, I can’t access the docker exec command while the container runs to implement that solution as the whole systems becomes unusual.
Does any one have an idea how to pass that command in the docker-compose.yaml or another way? Maybe docker-compose build command?

Thanks you for your help.

Additional info

Raspi 3
new to everything about Unix

EDIT: I managed to use docker exec but no dice:

OCI runtime exec failed: exec failed: container_linux.go:344: starting container                                                                 process caused "exec: \"sudo\": executable file not found in $PATH": unknown

EDIT2: Nevermind, somehow it’s working now…

eikowagenknecht · December 15, 2020, 11:19am

Replying here because it is the first google hit for the message and might help someone to fix this:

For me this messaged was caused by a breaking down SD card (<3MB/s remaining write and read speed). Replaced the card, message is gone, system way more responsive again.