Item status update delayed

manolo · September 2, 2017, 9:52am

Hi,

recently I noticed that items are no longer updated in time i.e. I’m facing a small delay.
Let me share a rule which I’m using to switch on a socket whenever it is switched off:

rule "Dunstabzug control"
when
        Item Dunstabzug received command
then
        var month = now.getMonthOfYear
        logWarn("FILE", "Dunstabzug state 01: " + Dunstabzug.state)
//Thread::sleep(10)
        if (month > 3 && month < 10 && Chimney.state!=ON) {
                logWarn("FILE", "Dunstabzug state 02: " + Dunstabzug.state)
                if (Dunstabzug.state==OFF || Dunstabzug.state==NULL) Dunstabzug.sendCommand(ON)
                logWarn("FILE", "Dunstabzug state 03: " + Dunstabzug.state)
        }
        logWarn("FILE", "Dunstabzug state 04: " + Dunstabzug.state)
end

If I switch of Dunstabzug then I see the following in my openhab.log:

2017-09-02 11:50:21.105 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 01: OFF
2017-09-02 11:50:21.106 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 02: OFF
2017-09-02 11:50:21.107 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 03: OFF
2017-09-02 11:50:21.107 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 04: OFF
2017-09-02 11:50:21.126 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 01: ON
2017-09-02 11:50:21.129 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 02: ON
2017-09-02 11:50:21.129 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 03: ON
2017-09-02 11:50:21.130 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 04: ON

Seems to be there’s a delay until the state is updated. What’s the issue?
Thanks,
Manolo

P.S.: One more thing. If I uncomment the Thread Sleep of 10ms it is working fine.

rlkoshak · September 2, 2017, 5:52pm

There is no issue. It is working as designed and as expected.

It takes time for a sendCommand or postUpdate to go out the the event bus, be processed, and then have the Item reflect the new state. In your car is looks like it takes around 20 msec from the time you sendCommand until the rule triggers again so I would guess it takes around 10 msec on your state to get to the point where the item gets the new state.

OH is not a realtime system and sendCommand and postUpdate don’t just merely set a classes data member. Lots of processing goes on. The fact that it only takes 10 msec is really quite a miracle.

The conclusion though is if you need this sort of realtime restraints, OH is never going to live up to your needs.

manolo · September 5, 2017, 8:01am

Well 10ms might be fast but in regards to computing it isn’t.

Nonetheless I’m not complaining but I didn’t face this issue with previous versions of openhab. Just wondering what happened.
Thanks, Manolo

rlkoshak · September 5, 2017, 6:17pm

It is fast when you consider the amount of “computing” that goes on when you call sendCommand.

manolo · September 6, 2017, 6:23am

Well if OH needs to process more than 300 commands for a sendCommand then I could understand why it’s taking 10ms.

But again don’t see this as a complaint just wondering why it does not happen with previous versions.

rlkoshak · September 6, 2017, 4:16pm

You would have to look at the code over on ESH. From what I’ve seen of the architecture and the code, 300 commands is probably an order of magnitude too low for the number of commands that typically execute for a single sendCommand. Remember a sendCommand needs to:

be sent to the event bus
process through all the bindings/channels attached to that Item which can include going through transformations
kick off processing to update the state of all Groups it is a member of
save the new state to persistence
kick off any rules that are triggered by commands and updates to

It’s not just saving the new state. I admit I don’t know how much of the above takes place in parallel verses serial, but it is a lot of commands.

I don’t know what previous version of OH you are referring to, but if it is 1.8, the architecture of OH 2 is completely different and has to do a lot more than 1.8 used to which would account for the extra delay.

manolo · September 7, 2017, 6:00am

Hi,

you’re right there are a lot of transaction linked to a sendCommand. I don’t know exactly which version didn’t cause this delay. Maybe I’ve to test one of the previous one. Could be that it was 2.0. Let me check and reply to this thread.
Thanks for your feedback.
Manolo

manolo · September 30, 2017, 7:10am

Holy crap,

this is still not working. I’ve added a Thread Sleep of 500ms!!!
What the Heck is wrong with openhab?!

This is the rule to switch off Dunstabzug

rule "All lights out"
when
    Item Zentral_Licht_aus received command
then
    var month = now.getMonthOfYear

    if(receivedCommand==ON) {
            logWarn("FILE","All lights on!!! Month "+month)

            gLightAll.allMembers.forEach [ item | item.sendCommand(OFF) ]
            gLightGuest.allMembers.forEach [ item | item.sendCommand(OFF) ]
            gLightLiving.allMembers.forEach [ item | item.sendCommand(OFF) ]

And to switch on Dunstabzug I use:

rule "Dunstabzug control"
when
    Item Dunstabzug received command
then
    var month = now.getMonthOfYear
Thread::sleep(500)
    logWarn("FILE", "Dunstabzug state 01: " + Dunstabzug.state)
    if (month > 3 && month < 11 && Chimney.state!=ON) {
            logWarn("FILE", "Dunstabzug state 02: " + Dunstabzug.state)
            if (Dunstabzug.state==OFF || Dunstabzug.state==NULL) Dunstabzug.sendCommand(ON)
            logWarn("FILE", "Dunstabzug state 03: " + Dunstabzug.state)
    }
    logWarn("FILE", "Dunstabzug state 04: " + Dunstabzug.state)
end

But still it is not switched on because openhab says it is still ON. Common half a second is slower than switching the light manually.
Thanks,
Manuel

rlkoshak · September 30, 2017, 2:08pm

Something else is going on here. Half a second is more than enough.

Your first rule is not complete and doesn’t refer to Dunstabzug. That is probable in the coffee that got truncated.

Also post an example log so we can see the exact timing of events. Both openhab.log and events.log.

manolo · September 30, 2017, 2:47pm

Well here we go. The rule was triggered at 1:17am and as you can see in openhab.log the status of Dunstabzug is always on even 800ms later.
Thanks, Manuel

My rules:

rule "All lights out"
when
        Item Zentral_Licht_aus received command
then
        var month = now.getMonthOfYear

        if(receivedCommand==ON) {
                logWarn("FILE","All lights on!!! Month "+month)
                gLightAll.allMembers.forEach [ item | item.sendCommand(OFF) ]
                gLightGuest.allMembers.forEach [ item | item.sendCommand(OFF) ]
                gLightLiving.allMembers.forEach [ item | item.sendCommand(OFF) ]

                if(Coming_Home.state==OFF) Licht_Haustuer.sendCommand(OFF)

                if (now.getHourOfDay>20 || now.getHourOfDay<6) {
                        sendCommand(Taster_Luke, OFF)
                        sendCommand(Taster_Eltern, OFF)
                        sendCommand(Taster_Bad_OG, OFF)
                        sendCommand(Bad_West_Lamelle, 100)
                        sendCommand(Eltern_Sued_Lamelle, 100)
                }
                postUpdate(Zentral_Licht_aus, OFF)
        }
end

rule "Dunstabzug control"
when
        Item Dunstabzug received command
then
        var month = now.getMonthOfYear
Thread::sleep(500)
        logWarn("FILE", "Dunstabzug state 01: " + Dunstabzug.state)
        if (month > 3 && month < 11 && Chimney.state!=ON) {
                logWarn("FILE", "Dunstabzug state 02: " + Dunstabzug.state)
                if (Dunstabzug.state==OFF || Dunstabzug.state==NULL) Dunstabzug.sendCommand(ON)
                logWarn("FILE", "Dunstabzug state 03: " + Dunstabzug.state)
        }
        logWarn("FILE", "Dunstabzug state 04: " + Dunstabzug.state)
end

Items config:

Group gLightAll					"Zentral Licht"				(All)
Group gLightGuest				"Zentral Licht o. Gast"			(All)
Group gLightLiving				"Zentral Licht o. Wohnen"		(All)

Switch Dunstabzug                       "Dunstabzug"                                    (gEGController,gLightLiving)    { knx="2/0/9" }
Switch Zentral_Licht_aus	"Zentral Licht aus [(%s)]"	<switch>				(gScene)	{ knx="5/0/17" }

events.log (10 seconds):

2017-09-30 01:17:00.144 [ItemCommandEvent          ] - Item 'Zentral_Licht_aus' received command ON
2017-09-30 01:17:00.145 [ItemCommandEvent          ] - Item 'Steckdose_Server_KG' received command OFF
2017-09-30 01:17:00.164 [ItemStateChangedEvent     ] - Zentral_Licht_aus changed from OFF to ON
2017-09-30 01:17:00.165 [ItemCommandEvent          ] - Item 'Licht_Treppe_KG' received command OFF
2017-09-30 01:17:00.165 [ItemCommandEvent          ] - Item 'Licht_kleines_Buero' received command OFF
2017-09-30 01:17:00.165 [ItemCommandEvent          ] - Item 'Licht_Kinder' received command OFF
2017-09-30 01:17:00.166 [ItemCommandEvent          ] - Item 'Licht_Leinwand_LED' received command OFF
2017-09-30 01:17:00.166 [ItemCommandEvent          ] - Item 'Flur_OG_Hue' received command OFF
2017-09-30 01:17:00.166 [ItemCommandEvent          ] - Item 'Licht_Haustuer' received command OFF
2017-09-30 01:17:00.167 [ItemCommandEvent          ] - Item 'Licht_Podest_LED' received command OFF
2017-09-30 01:17:00.167 [ItemCommandEvent          ] - Item 'Licht_Kino_dim' received command OFF
2017-09-30 01:17:00.167 [ItemCommandEvent          ] - Item 'Licht_Kino_LW' received command OFF
2017-09-30 01:17:00.167 [ItemCommandEvent          ] - Item 'Licht_Flur_KG' received command OFF
2017-09-30 01:17:00.167 [ItemCommandEvent          ] - Item 'Licht_Abstellraum' received command OFF
2017-09-30 01:17:00.168 [ItemCommandEvent          ] - Item 'Licht_WC_OG' received command OFF
2017-09-30 01:17:00.168 [ItemCommandEvent          ] - Item 'Licht_Balkon' received command OFF
2017-09-30 01:17:00.168 [ItemCommandEvent          ] - Item 'Licht_grosses_Buero' received command OFF
2017-09-30 01:17:00.168 [ItemCommandEvent          ] - Item 'Licht_Ankleide' received command OFF
2017-09-30 01:17:00.169 [ItemCommandEvent          ] - Item 'Downlight_Bad_OG_dim' received command OFF
2017-09-30 01:17:00.169 [ItemCommandEvent          ] - Item 'Licht_Eltern' received command OFF
2017-09-30 01:17:00.169 [ItemCommandEvent          ] - Item 'Licht_Bad' received command OFF
2017-09-30 01:17:00.169 [ItemCommandEvent          ] - Item 'Licht_Garderobe' received command OFF
2017-09-30 01:17:00.170 [ItemCommandEvent          ] - Item 'Licht_Garage' received command OFF
2017-09-30 01:17:00.170 [ItemCommandEvent          ] - Item 'Licht_Nick' received command OFF
2017-09-30 01:17:00.170 [ItemCommandEvent          ] - Item 'Licht_Luke' received command OFF
2017-09-30 01:17:00.170 [ItemCommandEvent          ] - Item 'Downlight_Flur' received command OFF
2017-09-30 01:17:00.171 [ItemCommandEvent          ] - Item 'Downlight_Bad_EG' received command OFF
2017-09-30 01:17:00.171 [ItemCommandEvent          ] - Item 'Licht_Bad_EG' received command OFF
2017-09-30 01:17:00.172 [ItemCommandEvent          ] - Item 'Licht_Gast' received command OFF
2017-09-30 01:17:00.172 [ItemCommandEvent          ] - Item 'Stehlampe_EG_Hue' received command OFF
2017-09-30 01:17:00.172 [ItemCommandEvent          ] - Item 'Downlight_Kamin_dim' received command OFF
2017-09-30 01:17:00.172 [ItemCommandEvent          ] - Item 'Downlight_Essen_dim' received command OFF
2017-09-30 01:17:00.173 [ItemCommandEvent          ] - Item 'Downlight_Kueche' received command OFF
2017-09-30 01:17:00.173 [ItemCommandEvent          ] - Item 'Downlight_TV_dim' received command OFF
2017-09-30 01:17:00.173 [ItemCommandEvent          ] - Item 'Licht_Vorrat' received command OFF
2017-09-30 01:17:00.173 [ItemCommandEvent          ] - Item 'Esstisch_Hue' received command OFF
2017-09-30 01:17:00.174 [ItemCommandEvent          ] - Item 'Licht_Kuechenschrank' received command OFF
2017-09-30 01:17:00.174 [ItemCommandEvent          ] - Item 'Licht_Sofa' received command OFF
2017-09-30 01:17:00.174 [ItemCommandEvent          ] - Item 'Dunstabzug' received command OFF
2017-09-30 01:17:00.175 [ItemCommandEvent          ] - Item 'Licht_Treppe_OG' received command OFF
2017-09-30 01:17:00.175 [ItemCommandEvent          ] - Item 'Licht_Gemaelde' received command OFF
2017-09-30 01:17:00.175 [ItemCommandEvent          ] - Item 'Licht_TV' received command OFF
2017-09-30 01:17:00.175 [ItemCommandEvent          ] - Item 'Licht_Haustuer' received command OFF
2017-09-30 01:17:00.176 [ItemCommandEvent          ] - Item 'Taster_Eltern' received command OFF
2017-09-30 01:17:00.176 [ItemCommandEvent          ] - Item 'Taster_Bad_OG' received command OFF
2017-09-30 01:17:00.176 [ItemCommandEvent          ] - Item 'Bad_West_Lamelle' received command 100
2017-09-30 01:17:00.176 [ItemCommandEvent          ] - Item 'Eltern_Sued_Lamelle' received command 100
2017-09-30 01:17:00.178 [ItemCommandEvent          ] - Item 'Licht_Hue_Flur_3' received command OFF
2017-09-30 01:17:00.184 [ItemCommandEvent          ] - Item 'Licht_Hue_Stehlampe_12' received command OFF
2017-09-30 01:17:00.198 [ItemCommandEvent          ] - Item 'Light_Hue_Essen_Dim_4' received command 0
2017-09-30 01:17:00.210 [ItemCommandEvent          ] - Item 'Light_Hue_Essen_Dim_5' received command 0
2017-09-30 01:17:00.380 [ItemCommandEvent          ] - Item 'Sonos_Bad' received command OFF
2017-09-30 01:17:00.381 [ItemCommandEvent          ] - Item 'Sonos_Bad' received command OFF
2017-09-30 01:17:00.384 [ItemCommandEvent          ] - Item 'SonosWaterCtrl' received command PAUSE
2017-09-30 01:17:00.392 [ItemCommandEvent          ] - Item 'SonosWaterCtrl' received command PAUSE
2017-09-30 01:17:01.400 [GroupItemStateChangedEvent] - gTasterOG changed from ON to OFF through Taster_Bad_OG
2017-09-30 01:17:01.463 [ItemStateChangedEvent     ] - Zentral_Licht_aus changed from ON to OFF
2017-09-30 01:17:01.485 [ItemStateChangedEvent     ] - Azimuth changed from 357.21 to 357.55
2017-09-30 01:17:01.485 [ItemStateChangedEvent     ] - Elevation changed from -41.39 to -41.40
2017-09-30 01:17:02.363 [ItemStateChangedEvent     ] - Dunstabzug changed from ON to OFF
2017-09-30 01:17:02.488 [ItemStateChangedEvent     ] - Taster_Bad_OG changed from ON to OFF
2017-09-30 01:17:10.076 [ItemStateChangedEvent     ] - Power_Daily changed from 494 to 500
2017-09-30 01:17:10.076 [ItemStateChangedEvent     ] - Power_Weekly changed from 75268 to 75274
20

openhab.log:

2017-09-30 01:17:00.144 [WARN ] [.eclipse.smarthome.model.script.FILE] - +++REGULAR LIGHT 01: current hour & weekday 1 / 6
2017-09-30 01:17:00.145 [WARN ] [.eclipse.smarthome.model.script.FILE] - All lights on!!! Month 9
2017-09-30 01:17:00.150 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[/usr/bin/python, /Users/macadmin/Desktop/luxlogger.py, info]'
2017-09-30 01:17:00.171 [WARN ] [.eclipse.smarthome.model.script.FILE] - +++Luke Kinder aus: NULL
2017-09-30 01:17:00.171 [WARN ] [lipse.smarthome.model.script.MSGFILE] - BAD check
2017-09-30 01:17:00.172 [WARN ] [lipse.smarthome.model.script.MSGFILE] - BAD check
2017-09-30 01:17:00.251 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom...
2017-09-30 01:17:00.251 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom room triggered OFF.
2017-09-30 01:17:00.256 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom...
2017-09-30 01:17:00.257 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom room triggered OFF.
2017-09-30 01:17:00.382 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom music...
2017-09-30 01:17:00.382 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom music...
2017-09-30 01:17:00.382 [WARN ] [.eclipse.smarthome.model.script.FILE] - Lavatory_Volume.state=10
2017-09-30 01:17:00.383 [WARN ] [.eclipse.smarthome.model.script.FILE] - Lavatory_Volume.state=10
2017-09-30 01:17:00.383 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom room Music triggered OFF.
2017-09-30 01:17:00.383 [WARN ] [lipse.smarthome.model.script.MSGFILE] - Sonos bathroom room Music triggered OFF.
2017-09-30 01:17:00.804 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 01: ON
2017-09-30 01:17:00.805 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 02: ON
2017-09-30 01:17:00.806 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 03: ON
2017-09-30 01:17:00.806 [WARN ] [.eclipse.smarthome.model.script.FILE] - Dunstabzug state 04: ON
2017-09-30 01:17:00.913 [WARN ] [.eclipse.smarthome.model.script.FILE] - FLUR check 1 EG status=ON Timeout=5 DL Flur state=OFF
2017-09-30 01:17:00.913 [WARN ] [.eclipse.smarthome.model.script.FILE] - FLUR check
2017-09-30 01:17:01.530 [WARN ] [.eclipse.smarthome.model.script.FILE] - FLUR check 2 DL Flur state=OFF
2017-09-30 01:17:01.530 [WARN ] [.eclipse.smarthome.model.script.FILE] - FLUR check 3 DL Flur state=OFF
2017-09-30 01:17:09.023 [WARN ] [lipse.smarthome.model.script.MSGFILE] - +++Heat pump sent data: 23.4;23.1;24.6;24.2;18.5;30.7;40.0;Standby;1.0;0.0;Automatik;Automatik