Handler takes more than 5000ms for processing event

[Benjy (Ben Clark)]

A bit more information, I wasn’t having this issue until I increased the number of things I own. Now, when I restart openHAB two of my five Amazon Dash buttons (and it is always two, but could be different each time) will get stuck on initialising, one of my six hue bulbs will respond very slowly too. bundle:restart ### fixes this problem each time.

Will get a debug log when it next happens.

[Kai (Kai Kreuzer)]

@Benjy And you are on a snapshot that has the fixes already?

[Benjy (Ben Clark)]

I believe so yes, this is with the build on 12-02-17 10:46:42 (#789)

[Kai (Kai Kreuzer)]

Ok, then we’ll need logs…

[Benjy (Ben Clark)]

2017-02-13 17:25:36.282 [DEBUG] [rthome.core.common.ThreadPoolManager] - Created thread pool 'ConfigStatusService' with size 5
2017-02-13 17:25:37.110 [DEBUG] [ore.common.registry.AbstractRegistry] - Provider 'org.eclipse.smarthome.core.thing.internal.ChannelItemProvider' has been added.
2017-02-13 17:25:37.157 [DEBUG] [rthome.core.common.ThreadPoolManager] - Created scheduled thread pool 'thingManager' of size 5
2017-02-13 17:25:38.234 [DEBUG] [ore.common.registry.AbstractRegistry] - Provider 'org.eclipse.smarthome.model.item.internal.GenericItemProvider' has been added.
2017-02-13 17:25:41.585 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2017-02-13 17:25:46.604 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'other.rules'
2017-02-13 17:25:48.691 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alexwork.rules'
2017-02-13 17:25:49.281 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'bedroom.rules', using it anyway:
There is no context to infer the closure's argument types from. Consider typing the arguments or put the closures into a typed context.
2017-02-13 17:25:49.288 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'bedroom.rules'
2017-02-13 17:25:49.628 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'livingroom.rules'
2017-02-13 17:25:51.176 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'hallway.rules', using it anyway:
There is no context to infer the closure's argument types from. Consider typing the arguments or put the closures into a typed context.
2017-02-13 17:25:51.181 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'hallway.rules'
2017-02-13 17:25:51.637 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'kitchen.rules'
2017-02-13 17:25:52.855 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2017-02-13 17:25:52.988 [DEBUG] [ore.common.registry.AbstractRegistry] - Provider 'org.eclipse.smarthome.model.thing.internal.GenericItemChannelLinkProvider' has been added.
2017-02-13 17:25:53.021 [DEBUG] [ore.common.registry.AbstractRegistry] - Provider 'org.eclipse.smarthome.model.thing.internal.GenericThingProvider' has been added.
2017-02-13 17:25:53.350 [DEBUG] [rthome.core.common.ThreadPoolManager] - Created thread pool 'safeCall' with size 3
2017-02-13 17:25:53.456 [DEBUG] [ore.common.registry.AbstractRegistry] - Provider 'org.eclipse.smarthome.core.thing.link.ManagedItemChannelLinkProvider' has been added.
2017-02-13 17:25:53.839 [DEBUG] [ore.common.registry.AbstractRegistry] - Provider 'org.eclipse.smarthome.core.thing.ManagedThingProvider' has been added.
2017-02-13 17:25:54.013 [DEBUG] [ore.common.registry.AbstractRegistry] - Provider 'org.eclipse.smarthome.core.items.ManagedItemProvider' has been added.
2017-02-13 17:25:54.031 [DEBUG] [rthome.core.common.ThreadPoolManager] - Created scheduled thread pool 'discovery' of size 3
2017-02-13 17:25:55.251 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-02-13 17:25:55.516 [DEBUG] [rthome.core.common.ThreadPoolManager] - Created scheduled thread pool 'thingHandler' of size 3
2017-02-13 17:25:57.057 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-02-13 17:25:57.202 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-02-13 17:25:57.304 [DEBUG] [rthome.core.common.ThreadPoolManager] - Created scheduled thread pool 'pcapNetworkInterfaceService' of size 5
2017-02-13 17:25:58.399 [DEBUG] [rthome.core.common.ThreadPoolManager] - Created thread pool 'items' with size 5
2017-02-13 17:25:58.611 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.inet, use default value: null
2017-02-13 17:25:58.614 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.inet6, use default value: null
2017-02-13 17:25:58.616 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.packet, use default value: null
2017-02-13 17:25:58.617 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.af.link, use default value: null
2017-02-13 17:25:58.675 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-02-13 17:25:58.812 [WARN ] [org.pcap4j.util.PropertiesLoader    ] - [org/pcap4j/pcap4j.properties] Could not get value by org.pcap4j.dlt.raw, use default value: null
2017-02-13 17:25:58.823 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-02-13 17:26:01.732 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2017-02-13 17:26:01.832 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-02-13 17:26:01.859 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2017-02-13 17:26:01.901 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-02-13 17:26:01.903 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-02-13 17:26:02.315 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded, thread safeCall-2 (99) in state RUNNABLE is at org.pcap4j.core.NativeMappings.pcap_findalldevs(NativeMappings.java:-2).
2017-02-13 17:26:02.316 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'amazondashbutton:dashbutton:50-f5-da-93-9f-67' takes more than 5000ms.

Hope this helps.

[Kai (Kai Kreuzer)]

This is perfect - just exactly what the changes were about: To correctly identify badly behaving handlers and blame them (and no one else anymore):

2017-02-13 17:26:02.315 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded, thread safeCall-2 (99) in state RUNNABLE is at org.pcap4j.core.NativeMappings.pcap_findalldevs(NativeMappings.java:-2).
2017-02-13 17:26:02.316 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'amazondashbutton:dashbutton:50-f5-da-93-9f-67' takes more than 5000ms.

This is absolutely true: The handler takes more than 5s to initialize() because it does some fancy pcap stuff in there. Instead, it should schedule a job to do such long running activities asynchronously. @oliver Could you improve the implementation that way?

[oliver (Oliver Libutzki)]

@Kai, sure, but I don’t know when I will find the time.

[lopez1de (Markus Gehlhaar)]

I’m getting the same errors with the homematic binding.

[oliver (Oliver Libutzki)]

@Kai

@oliver Could you improve the implementation that way?

I created https://github.com/openhab/openhab2-addons/issues/1967 and https://github.com/openhab/openhab2-addons/pull/1968

[OMR (Ole Morten Rønning)]

Could this be related to my 5s delay problem?

OH2:Z-wave sendCommand burst often causes a 5s delay

Hello. I’m running OH2 2.0.0 Release under Ubuntu server 16.04 LTS on a Shuttle XS35GT (Dual Core Atom@1.6GHz, 2GB RAM) & Aeotec Z-Stick gen5 I have a rule triggered by a NodOn CWS-3101 wall-switch. Short pressing button 1, triggers this rule: var swState = WallSwitchStua.state logInfo("RemoteNodon5", "Rule: Got: " + swState) switch swState { case 1.0: { logInfo("RemoteNodon5", "Rule: Button1 SingleClick " + swState) if (BuildInKjokkenBench.state == ON) { sendCommand(Wallplug…

[chris (Chris Jackson)]

@OMR

Could this be related to my 5s delay problem?

OH2:Z-wave sendCommand burst often causes a 5s delay Bindings

No - your problem is related to a timeout on the network.

[OMR (Ole Morten Rønning)]

Indeed. I will look into it, but it seems to be systematic re-transmissions that fails after 3 attempts on multiple nodes.
I have a mix of Nexa WallPlugs and BuildIn Dimmers and ON/OFF switches.
Heard of any issues with Nexa Z-wave?

[chris (Chris Jackson)]

@OMR

it seems to be systematic re-transmissions

Ok, but it’s still not related to this thread - it’s a retransmission in the zwave binding - not the handler timeout.

I’d suggest to discuss in a separate thread, but please provide a debug log so we can see what’s happening.

[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