Where is this latency coming from when executing simple rules?

Hi,

I’m running OH on Windows 10, Intel Core I5 @2,5Ghz.
Lately, I’ve noticed some considerable delays or latencies in the execution of rules.
I would like to know what’s causing this, because for example entering a (dark) room and having to wait 3 or more seconds before the light comes on after a PIR detection is quite frustrating :wink:
Most of the times there is no noticeable delay or latency, but sometimes (occurance seems to increase lately) the latency can be 5 or more seconds.

For example this simple rule I setup to test the latency ;

rule "DEBUG KAKU_I_3_AB ===================================================================="
when
Item KAKU_I_3_AB received update
then
if(KAKU_I_3_AB.state==ON) {
sendCommand(MQTT_SPOTS_LVING, ON)
} else if(KAKU_I_3_AB.state==OFF) {
sendCommand(MQTT_SPOTS_LVING, OFF)
}
end
`
And here’s the OSGI output ;

21:20:31.482 [DEBUG] [.b.r.internal.RFXComConnection:148 ] - Data received:
Raw data = 0B11004900C8674203000070

  • Packet type = LIGHTING2
  • Seq number = 73
  • Sub type = AC
  • Id = 13133634
  • Unit code = 3
  • Command = OFF
  • Dim level = 0
  • Signal level = 7
    21:20:32.772 [DEBUG] [o.p.d.i.Db4oPersistenceService:118 ] - Stored item state ‘ElecAmp1’ -> '6.504347826086956274593831039965152740478515625’
    21:20:32.773 [INFO ] [runtime.busevents :26 ] - ElecAmp1 state updated to 6.504347826086956274593831039965152740478515625
    21:20:32.774 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'Update Energy Electricty KPI +++++++++++++++++++++++++++++++++++++++++++++++++++++'
    21:20:32.834 [DEBUG] [o.p.d.i.Db4oPersistenceService:118 ] - Stored item state ‘ElecPOWER’ -> '1495.999999999999943156581139191985130310058593750’
    21:20:32.835 [INFO ] [runtime.busevents :26 ] - ElecPOWER state updated to 1495.999999999999943156581139191985130310058593750
    21:20:32.836 [INFO ] [runtime.busevents :26 ] - DATUM state updated to 2016-03-15T21:20:30
    21:20:32.837 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'DEBUG KAKU_I_3_AB ===================================================================='
    21:20:32.838 [INFO ] [runtime.busevents :26 ] - KAKU_I_3_AB state updated to OFF
    21:20:33.080 [DEBUG] [o.p.d.i.Db4oPersistenceService:118 ] - Stored item state ‘Out_HumiDH’ -> '84.0’
    21:20:33.081 [INFO ] [runtime.busevents :26 ] - Out_HumiDH state updated to 84.0
    21:20:33.081 [INFO ] [runtime.busevents :22 ] - MQTT_SPOTS_LVING received command OFF
    21:20:33.081 [DEBUG] [.b.i.internal.imperiHabBinding:119 ] - imperiHab: internalReceiveUpdate(Out_HumiDH,84.0) is called!
    21:20:33.082 [DEBUG] [.mqtt.internal.MqttItemBinding:44 ] - Publishing command OFF to MyMQTT/32/3/1/0/2
    21:20:33.082 [INFO ] [runtime.busevents :26 ] - TempTuinhuis_IH state updated to 5.800000000000000710542735760100185871124267578125
    21:20:33.084 [DEBUG] [.b.i.internal.imperiHabBinding:119 ] - imperiHab: internalReceiveUpdate(TempTuinhuis_IH,5.800000000000000710542735760100185871124267578125) is called!
    21:20:33.084 [DEBUG] [o.i.t.m.i.MqttBrokerConnection:437 ] - Publishing message 97 to topic 'MyMQTT/32/3/1/0/2’
    21:20:33.085 [DEBUG] [avaScriptTransformationService:61 ] - about to transform ‘0’ by the Java Script 'gpio2sw.js’
    21:20:33.085 [DEBUG] [.b.i.internal.imperiHabBinding:107 ] - imperiHab: internalReceiveCommand(MQTT_SPOTS_LVING,OFF) is called!
    21:20:33.112 [INFO ] [runtime.busevents :26 ] - MQTT_SPOTS_LVING state updated to OFF

So, as you can see the RFXCOM receives data at 21:20:31.482
and the publish to MQTT is done at 21:20:33.082
So in this case a delay or latency of about 1,6 seconds before the light goes on.
This time only 1,6 seconds, but in other occasions it goes up to 5 or more seconds.

What can I do to improve this ? Where to look ?
And I forgot to mention that the computer is doing nothing else than OH.

Thanks in advance,
DirkB

Be aware of the fact, that Windows is no realtime OS and there is no guarantee to see constant response time.

@21:20:31.482 the data is received,
@21:20:32.837 the rule is triggered.
@21:20:33.81 the rule has done its work and the item MQTT_SPOTS_LIVING received the command.

So it’s obvious where there was lack of processor time. But there were also 6 other events including persistence and rules in this 1.35secs, so maybe these are unfortunate circumstances :wink: would be interesting to see the systemload at this time.

Sometimes I see poor response time myself, though it’s rare, I’m using openHAB virtualized with xen, one virtual processor and 1GByte RAM, and there are about 12 other VMs on the same machine (Core i5, too) so I don’t think that openHAB itself is the bottleneck.

Hi Udo,

Thanks for your reply.
System CPUI load varies from 3% to 40-55 %, also there’s 8 Gbyte RAM and an SSD drive. So plenty of power I guess.
No, before I never noticed this kind of delays response time.
But I’m not sure when it started.
I do suspect some causes like ;

  • the ImperiHab binding
  • the db4o persistence
  • some rules that keep spitting out : "Cannot cast org.openhab.core.types.UnDefType to org.openhab.core.library.types.DecimalType "

Yesterday, I’ve managed to capture another delay of 9 seconds !!! ;

21:59:00.349 [DEBUG] [.b.r.internal.RFXComConnection:148 ] - Data received:
Raw data = 0B11005900C8674203010F70

  • Packet type = LIGHTING2
  • Seq number = 89
  • Sub type = AC
  • Id = 13133634
  • Unit code = 3
  • Command = ON
  • Dim level = 15
  • Signal level = 7
    21:59:02.750 [DEBUG] [.b.i.internal.imperiHabBinding:96 ] - execute() method is called!
    21:59:02.969 [DEBUG] [avaScriptTransformationService:61 ] - about to transform ‘1’ by the Java Script 'gpio2sw.js’
    21:59:03.612 [DEBUG] [.b.r.internal.RFXComConnection:148 ] - Data received:
    Raw data = 115A025A81920000000649000017987B0E79
  • Packet type = ENERGY
  • Seq number = 90
  • Sub type = UNKNOWN
  • Id = 33170
  • Count = 0
  • Instant Amps = 6.995652173913044
  • Total Amp Hours = 7695.265754407857
  • Signal level = 7
  • Battery level = 9
    21:59:03.692 [DEBUG] [inding.ntp.internal.NtpBinding:83 ] - Got time from 0.be.pool.ntp.org: dinsdag 15 maart 2016 21.59 u. CET
    21:59:03.970 [DEBUG] [avaScriptTransformationService:61 ] - about to transform ‘0’ by the Java Script 'gpio2sw.js’
    21:59:06.164 [DEBUG] [g.internal.GCalEventDownloader:170 ] - gcal: found 1 calendar events to process
    21:59:06.167 [INFO ] [g.internal.GCalEventDownloader:348 ] - gcal: created new endJob ‘VERWARMING AAN’ with details 'SchedulerJob [jobKey=crjul20q3g5jc69dumgctol4j8@google.com_end, jobGroup=gcal, 1 triggers=[Tue Ma
    r 15 23:30:00 CET 2016], content=start {
    send CALENDER_VERWARMING ON
    }
    end {
    send CALENDER_VERWARMING OFF
    }'
    21:59:09.000 [DEBUG] [o.p.d.i.Db4oPersistenceService:118 ] - Stored item state ‘BadK_HumiDH’ -> '39.3’
    21:59:09.001 [INFO ] [runtime.busevents :26 ] - BadK_HumiDH state updated to 39.3
    21:59:09.002 [DEBUG] [.b.i.internal.imperiHabBinding:119 ] - imperiHab: internalReceiveUpdate(BadK_HumiDH,39.3) is called!
    21:59:09.002 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'DEBUG KAKU_I_3_AB ===================================================================='
    21:59:09.003 [INFO ] [runtime.busevents :26 ] - KAKU_I_3_AB state updated to ON
    21:59:09.004 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'VERANDA THERMISCH GORDIJN CONTROL <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<'
    21:59:09.005 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'Update Temperature VERANDA +++++++++++++++++++++++++++++++++++++++++++++++++++++'
    21:59:09.012 [DEBUG] [o.p.d.i.Db4oPersistenceService:118 ] - Stored item state ‘Veranda_TempDH’ -> '22.5’
    21:59:09.013 [INFO ] [runtime.busevents :26 ] - Veranda_TempDH state updated to 22.5
    21:59:09.014 [DEBUG] [.b.i.internal.imperiHabBinding:119 ] - imperiHab: internalReceiveUpdate(Veranda_TempDH,22.5) is called!
    21:59:09.015 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'MQTT DOMO WATCHDOG’
    21:59:09.017 [INFO ] [runtime.busevents :26 ] - DomoWD state updated to ON
    21:59:09.018 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'ELECTRICITEITSVERBRUIK’
    21:59:09.021 [DEBUG] [o.p.d.i.Db4oPersistenceService:118 ] - Stored item state ‘ElecAmp1’ -> '6.995652173913043725406168960034847259521484375’
    21:59:09.022 [INFO ] [runtime.busevents :26 ] - ElecAmp1 state updated to 6.995652173913043725406168960034847259521484375
    21:59:09.023 [INFO ] [runtime.busevents :26 ] - DATUM state updated to 2016-03-15T21:59:03
    21:59:09.024 [INFO ] [runtime.busevents :26 ] - DomoWD state updated to OFF
    21:59:09.027 [DEBUG] [o.p.d.i.Db4oPersistenceService:118 ] - Stored item state ‘Living_HumiDH’ -> '38.5’
    21:59:09.028 [INFO ] [runtime.busevents :26 ] - Living_HumiDH state updated to 38.5
    21:59:09.029 [DEBUG] [.b.i.internal.imperiHabBinding:119 ] - imperiHab: internalReceiveUpdate(Living_HumiDH,38.5) is called!
    21:59:09.030 [INFO ] [runtime.busevents :26 ] - BADKAMER_T_TREND state updated to -2.400000000000012789769243681803345680236816406250
    21:59:09.043 [INFO ] [runtime.busevents :26 ] - BADKAMERTempTrend state updated to 21,7 ¦C | -2,4 ¦C/h
    21:59:09.046 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule 'Update Energy Electricty KPI +++++++++++++++++++++++++++++++++++++++++++++++++++++'
    21:59:09.042 [ERROR] [o.o.c.s.ScriptExecutionThread :50 ] - Error during the execution of rule ‘ELECTRICITEITSVERBRUIK’: Cannot cast org.openhab.core.types.UnDefType to org.openhab.core.library.types.DecimalType
    21:59:09.040 [INFO ] [runtime.busevents :22 ] - MQTT_SPOTS_LVING received command ON
    21:59:09.050 [DEBUG] [.mqtt.internal.MqttItemBinding:44 ] - Publishing command ON to MyMQTT/32/3/1/0/2
    21:59:09.052 [DEBUG] [o.i.t.m.i.MqttBrokerConnection:437 ] - Publishing message 137 to topic ‘MyMQTT/32/3/1/0/2’

I think I found what’s causing the latency/delay/slow response :slight_smile:

I tested some more and used an elimination method to come to this finding.

First I eliminated the rule “ELECTRICITEITSVERBRUIK” that was giving me " Error during the execution of rule ‘ELECTRICITEITSVERBRUIK’: Cannot cast org.openhab.core.types.UnDefType to org.openhab.core.library.types.DecimalType"
I commented the rule (disabled it), but still the same problem …

Then I noticed on the OSGI that each time the delay occurres also Db4oPersistenceService is showing activity…
So for example, when the LIGHTNING2 message comes in at approx. the same time as the ENERGY packet (both via RFXCOM) it would trigger the db4o storing (on everyChange) of ‘ElecAMP1’.
So I removed the “everyChange” strategy from the db4o.persist file and replaced it by a everyMinute strategy.
This seemed to have solved the problem, I could no longer reproduce the delay/latency phenomena .

So, my preliminary conclusion, is that in my setup (see above), an “everyChange” strategy in db4o.persist is causing occasional latency on rules.
Does this make any sense ?

Grts,
DirkB