I keep getting the message:
Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items.ItemUpdater@133956’ takes more than 5000ms.
How do I decipher which item this is?
Maybe check for an item event in the log that occurred exactly 5000ms before?
Note that this is only a warning, the execution is continued as normal. But something in your system seems to be long running, although it is not expected to. Do you maybe have any long running rules?
I gave OH2 an other couple of weeks to mature and had an other go with the migration from OH1 to OH2
I keep getting the error in the log below:
Most (or all) of my knx related rules fail without further error. Which may or may not be connected to the error in the log. Yet - the same set of rules would work fine on OH1.7.1
The last event on the bus is from the (OH2) NTP binding which does not trigger anything (except updating the date in the GUI)
The log:
> 11:29:41.789 [INFO ] [marthome.event.ItemStateChangedEvent] - Date changed from 2016-05-31T11:28:41.631+0200 to 2016-05-31T11:29:41.631+0 200
> 11:30:09.399 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
> 11:30:14.419 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
> 11:30:19.432 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
> 11:30:24.443 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
> 11:30:29.469 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
> 11:30:34.483 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
> 11:30:39.498 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
> 11:30:40.474 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.internal.items. ItemUpdater@1023f6’ takes more than 5000ms.
Sounds very similar to https://github.com/eclipse/smarthome/issues/1575
Note that this message is only a warning though that some process runs longer than it should - it does not have any direct impact on the functionality.
Just now I have tested the latest build and I got the impression that there is a promlem with binding my items to the event bus. (knx)
Later the already posted "dispatching takes more than… " messages are written to the log.
07:39:03.369 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'sLichtwert' received command 5296
07:39:03.431 [ERROR] [ore.internal.events.OSGiEventManager] - Dispatching/filtering event for subscriber 'org.eclipse.smarthome.core.events.EventSubscriber' failed: java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_65]
at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_65]
at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:179)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:72)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:56)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.internal.events.OSGiEventManager.dispatchESHEvent(OSGiEventManager.java:188)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.internal.events.OSGiEventManager.handleEvent(OSGiEventManager.java:163)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.internal.events.OSGiEventManager.handleEvent(OSGiEventManager.java:146)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.apache.felix.eventadmin.impl.handler.EventHandlerProxy.sendEvent(EventHandlerProxy.java:415)[3:org.apache.karaf.services.eventadmin:4.0.4]
at org.apache.felix.eventadmin.impl.tasks.HandlerTask.run(HandlerTask.java:90)[3:org.apache.karaf.services.eventadmin:4.0.4]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_65]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_65]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_65]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_65]
Caused by: java.lang.NullPointerException
at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleContextHelper.getContext(RuleContextHelper.java:64)[125:org.eclipse.smarthome.model.rule.runtime:0.8.0.201605311814]
at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl.executeRule(RuleEngineImpl.java:304)[125:org.eclipse.smarthome.model.rule.runtime:0.8.0.201605311814]
at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl.executeRules(RuleEngineImpl.java:329)[125:org.eclipse.smarthome.model.rule.runtime:0.8.0.201605311814]
at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl.stateChanged(RuleEngineImpl.java:198)[125:org.eclipse.smarthome.model.rule.runtime:0.8.0.201605311814]
at org.eclipse.smarthome.core.items.GenericItem.notifyListeners(GenericItem.java:220)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.items.GenericItem.setState(GenericItem.java:195)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.internal.items.ItemUpdater.receiveUpdate(ItemUpdater.java:70)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.items.events.AbstractItemEventSubscriber.receive(AbstractItemEventSubscriber.java:44)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:192)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.internal.events.OSGiEventManager$1.call(OSGiEventManager.java:1)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:170)[100:org.eclipse.smarthome.core:0.8.0.201605311814]
//********************rule*************************************************************
rule "Daemmerung"
when
Item sLichtwert changed
then
//PS im Wohnzimmer hat bei 50Lux geschaltet und es ist Dunkel
//logInfo("Lichtwert","Lichwert f�r Daemmerung: "+sLichtwert.state)
if(sLichtwert.state<5000 && Dunkel<1){
logInfo("Lichtwert","Daemmerung eingetreten bei:"+sLichtwert.state)
sendCommand(EG_PS_Esszimmer_sperren,OFF)
Dunkel=1
Tageslicht.state=OFF
}
//der PS im Wohnzimmer hat bei 60lux geschaltet und es ist wieder hell
if(sLichtwert.state>6000 && Dunkel>0){
logInfo("Lichtwert","Daemmerung beendet bei: "+sLichtwert.state)
//logInfo("Lichtwert","Daemmerung beendet ")
if((Licht_EG_Wohnzimmer.state <1)&&(RGB_EG_Wohnzimmer.state<1)){
Dunkel=0
Tageslicht.state=ON
sendCommand(EG_PS_Esszimmer_sperren,ON)
}
}
endI have the same message in my log:
Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1d6db1c' takes more than 5000ms.
How to identify the thing behind 1d6db1c ?
I did check my item channels and PaperUI.
Is there a better way to check which Thing did not respond?
It is the ThingManager that takes so long, which is the central system service.
To figure out, why it is blocked, you might enable debug logging for it:
log:set DEBUG org.eclipse.smarthome.core.thing
Looks like this old issue is still causing headaches…
For me the resolution was to fix my rules file. The errors were not obvious and were not logged or reported anywhere - but I eventually found out by switching to the 4.1 nightly - where a parser told me which part of my rule was wrong.
Did the trick and now I am still running on a 6 month old nightly.
Thanks, Kai.
I will give it a try.