Handler takes more than 5000ms for processing event

[OMR (Ole Morten Rønning)]

I’d suggest to discuss in a separate thread, …

Sure. Continuing here

[CodingHarry (Harry)]

I am running stable 2.0 on pi3 and rule checks semms to have a 5000ms delay after long inactivity.

OH2 Z-Wave refactoring and testing... and SECURITY

You are right chris. Now i have one with delay in it because i did not touched any device (remote ore other zwave devices) for a long time. logdelay.json (79.7 KB) please tell me how i can prepare the log the way you did the post before (ah already found it your hompage can do it…nice!) [image] Transmitter is not in sleep mode…as traffic logs show. Seems the rule engine is fireing to late as i can see the log created by the rule is delayed… 22:54:55.399 [INFO ] [rthome.model.script.Remote …

i installed the unstable version by using config tool and cause i could not get it running i went back to stable.

@Kai: So far stable users should solve it temporary that way?

Handler takes more than 5000ms for processing event

It seems as if the thread pools go out of threads. The warning logs actually blame the wrong ones in that case: It’s the ones that do not get a thread assigned anymore in time. This also explains why the binding receives the events only afterwards. One short term workaround would be to increase the safeCall threadpool size. You could try to add the line org.eclipse.smarthome.threadpool:safeCall=10 to conf/services/runtime.cfg and see if that helps. We will look at improving the thread assign…

THX Harry

[Axel (Axel Kaske)]

Hello,

I am migrating from OH1.8 to OH2.0.0-3 (latest version for QNAP - TP-419P).
On OH1.8 everything was working well but now, with OH2 I face several issues with homematic especially the “takes more than 5000ms” issue.

As shown below for all homematic handler initializations I get in a first step the warning.
But a the very end only 5 homematic devices (out of 34) are not handled correctly.

I also tried the advice “org.eclipse.smarthome.threadpool:safeCall=10” but that did not change the situation (only the kind of warnings etc.

Any idea how to solve this issue?
Thx
Axel

2017-07-11 01:31:25.501 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:bridge:f6d5a2d0' takes more than 5000ms.
2017-07-11 01:31:37.448 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@11d1524' takes more than 5000ms.
2017-07-11 01:31:39.357 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SCo:f6d5a2d0:LEQ1175183' takes more than 5000ms.
2017-07-11 01:31:39.527 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847188' takes more than 5000ms.
2017-07-11 01:31:39.530 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847221' takes more than 5000ms.
2017-07-11 01:31:39.532 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SCo:f6d5a2d0:LEQ1177448' takes more than 5000ms.
2017-07-11 01:31:39.621 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@11d1524' takes more than 5000ms.
2017-07-11 01:31:40.399 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0783686' takes more than 5000ms.
2017-07-11 01:31:42.798 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@11d1524' takes more than 5000ms.
2017-07-11 01:31:44.498 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0786117' takes more than 5000ms.
2017-07-11 01:31:44.647 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SD:f6d5a2d0:LEQ0388477' takes more than 5000ms.
2017-07-11 01:31:44.657 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SCo:f6d5a2d0:LEQ1175219' takes more than 5000ms.
2017-07-11 01:31:44.700 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SD:f6d5a2d0:LEQ0388917' takes more than 5000ms.
2017-07-11 01:31:44.780 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1cc46bd' takes more than 5000ms.
2017-07-11 01:31:45.417 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847115' takes more than 5000ms.
2017-07-11 01:31:47.827 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1cc46bd' takes more than 5000ms.
2017-07-11 01:31:49.517 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0846782' takes more than 5000ms.
2017-07-11 01:31:49.673 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SD:f6d5a2d0:LEQ0388481' takes more than 5000ms.
2017-07-11 01:31:49.677 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0846628' takes more than 5000ms.
2017-07-11 01:31:49.848 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0784255' takes more than 5000ms.
2017-07-11 01:31:49.937 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@5c265d' takes more than 5000ms.
2017-07-11 01:31:50.437 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847110' takes more than 5000ms.
2017-07-11 01:31:52.847 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@5c265d' takes more than 5000ms.
2017-07-11 01:31:54.597 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SD:f6d5a2d0:LEQ0388453' takes more than 5000ms.
2017-07-11 01:31:54.687 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SCo:f6d5a2d0:LEQ1177422' takes more than 5000ms.
2017-07-11 01:31:54.697 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847122' takes more than 5000ms.
2017-07-11 01:31:54.867 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-RCV-50:f6d5a2d0:BidCoS-RF' takes more than 5000ms.
2017-07-11 01:31:54.957 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@b61943' takes more than 5000ms.
2017-07-11 01:31:55.457 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SD-Team:f6d5a2d0:T-LEQ0388477' takes more than 5000ms.
2017-07-11 01:31:57.867 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@b61943' takes more than 5000ms.
2017-07-11 01:31:59.617 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SD:f6d5a2d0:LEQ0388445' takes more than 5000ms.
2017-07-11 01:31:59.707 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0784598' takes more than 5000ms.
2017-07-11 01:31:59.790 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0784622' takes more than 5000ms.
2017-07-11 01:31:59.977 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@78691e' takes more than 5000ms.
2017-07-11 01:32:00.513 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0784630' takes more than 5000ms.
2017-07-11 01:32:04.677 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SCo:f6d5a2d0:LEQ1177493' takes more than 5000ms.
2017-07-11 01:32:04.679 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847218' takes more than 5000ms.
2017-07-11 01:32:04.727 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0846682' takes more than 5000ms.
2017-07-11 01:32:04.807 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0846688' takes more than 5000ms.
2017-07-11 01:32:04.997 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@17f2539' takes more than 5000ms.
2017-07-11 01:32:05.527 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0783180' takes more than 5000ms.
2017-07-11 01:32:07.487 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@17f2539' takes more than 5000ms.
2017-07-11 01:32:09.697 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0846681' takes more than 5000ms.
2017-07-11 01:32:09.699 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SCo:f6d5a2d0:LEQ1177455' takes more than 5000ms.
2017-07-11 01:32:09.747 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:GATEWAY-EXTRAS-F6D5A2D0:f6d5a2d0:GWE00000000' takes more than 5000ms.
2017-07-11 01:32:09.827 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847184' takes more than 5000ms.
2017-07-11 01:32:10.028 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@3652cd' takes more than 5000ms.
2017-07-11 01:32:10.547 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-Sec-SCo:f6d5a2d0:LEQ1175903' takes more than 5000ms.
2017-07-11 01:32:12.507 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@3652cd' takes more than 5000ms.
2017-07-11 01:32:14.778 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'homematic:HM-CC-RT-DN:f6d5a2d0:LEQ0847185' takes more than 5000ms.
2017-07-11 01:32:15.047 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@1fac9f7' takes more than 5000ms.
2017-07-11 01:32:17.527 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@1fac9f7' takes more than 5000ms.
2017-07-11 01:32:20.067 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1cc46bd' takes more than 5000ms.
2017-07-11 01:32:22.547 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1cc46bd' takes more than 5000ms.
2017-07-11 01:32:25.277 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@5c265d' takes more than 5000ms.
2017-07-11 01:32:27.567 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@5c265d' takes more than 5000ms.
2017-07-11 01:32:30.297 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@b61943' takes more than 5000ms.
2017-07-11 01:32:32.587 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@b61943' takes more than 5000ms.
2017-07-11 01:32:37.607 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@78691e' takes more than 5000ms.
2017-07-11 01:32:40.007 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@17f2539' takes more than 5000ms.
2017-07-11 01:32:42.627 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@17f2539' takes more than 5000ms.
2017-07-11 01:32:55.593 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@11d1524' takes more than 5000ms.
2017-07-11 01:33:10.776 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.link.ThingLinkManager@11d1524' takes more than 5000ms.
 

[CodingHarry (Harry)]

Im sorry Axel, no ideas on that and i also have no experience with homematic.

[Kai (Kai Kreuzer)]

Note that openHAB 2.1 has been released meanwhile, which contains many fixes in the Homematic binding and also about such logging messages.

[Axel (Axel Kaske)]

After a complet reinstallation of JRE and OH2.0.0-3 as well as a reconfiguration of bindings etc. it is now working. I still have one “5000ms” warning when initializing the homematic bridge, but it works nevertheless as expected.
It seems that I misconfigured something during my first try.

Thx for your answers anyhow.

Axel

[markus7017 (Markus Michels)]

@Kai: I have tried 2.1 stable and 2.2SNAPSHOT as of yesterday and still encounter 10sec delays (2x5sec?); this happens from time to time, but isn’t an exception

**2017-08-07 22:29:00.760** [ItemCommandEvent          ] - Item 'Scene_Wohnzimmer' received command 9
2017-08-07 22:29:00.782 [ItemCommandEvent          ] - Item 'Scene_Guten_Morgen' received command OFF
2017-08-07 22:29:00.794 [ItemStateChangedEvent     ] - Scene_Wohnzimmer changed from 1 to 9
2017-08-07 22:29:00.795 [ItemCommandEvent          ] - Item 'Scene_Guten_Abend' received command OFF

==> openhab.log <==
2017-08-07 22:29:10.813 [INFO ] [clipse.smarthome.model.script.Scenes] - Activate Scene Gute_Nacht
2017-08-07 22:29:10.814 [INFO ] [clipse.smarthome.model.script.Scenes] -   Switch lights off

==> events.log <==
2017-08-07 22:29:10.818 [ItemCommandEvent          ] - Item 'Plug_WonZ_TVL' received command OFF
2017-08-07 22:29:10.824 [ItemCommandEvent          ] - Item 'Plug_1_Switch' received command OFF
2017-08-07 22:29:10.831 [ItemCommandEvent          ] - Item 'Light_Erker_left' received command OFF

The Scene_xxx items are just Switches to control the scenes .

• Alexa HUE emulation tiggers Scene_Gute_Nacht, which
• triggers Scene_Wohnzimmer with sendCommand
• it takes 10s until the Scene_Gute_Nacht event handler gets triggered