Lost 5 Seconds in Runtime

[alfderheld (Alf)]

Hello together,

based on the following Rule and the event on the ZWAVE-Bus I dont know, where I lost 5 seconds between event and action. It looks like this problem is a sleep-lag, because its not overall time, i think only if i dont use the hole System for a longer time. Where can i get more debugging-informations?
rule “Schlafzimmertuer geöffnet”
when
Item TuerSensorSchlafzimmer_SensorDoor changed to OPEN
then
// logInfo(“bewegung”, “Schlafzimmertuer geöffnet”)
if (orte_schlafzimmer_state.state == 0) {
logInfo(“bewegung”, “Schlafzimmer von aussen geöffnet”)
orte_schlafzimmer_state.sendCommand(1)
orte_flur_state.sendCommand(3)
}
if (orte_schlafzimmer_state.state == 2) {
logInfo(“bewegung”, “Schlafzimmer von innen geöffnet”)
orte_schlafzimmer_state.sendCommand(3)
}

2020-02-29 05:18:30.410 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 15 00 04 00 15 0D 56 01 71 05 00 00 00 FF 06 16 00 FF C5 C9 00 C9
2020-02-29 05:18:30.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=21, callback=0, payload=00 15     0D 56 01 71 05 00 00 00 FF 06 16 00 FF C5 C9 00
2020-02-29 05:18:30.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=21, callback=0, payload=00 15 0D 56 01 71 05 00     00 00 FF 06 16 00 FF C5 C9 00
2020-02-29 05:18:30.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-02-29 05:18:30.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Application Command Request (ALIVE:UPDATE_NEIGHBORS)
2020-02-29 05:18:30.423 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
2020-02-29 05:18:30.425 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2020-02-29 05:18:30.426 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: SECURITY not supported
2020-02-29 05:18:30.427 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 21: Received COMMAND_CLASS_ALARM V5 NOTIFICATION_REPORT
2020-02-29 05:18:30.429 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 21: NOTIFICATION report - 0 = 0, event=22, status=255, plen=0
2020-02-29 05:18:30.430 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 21: Alarm Type = ACCESS_CONTROL (0)
2020-02-29 05:18:30.431 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2020-02-29 05:18:30.432 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_ALARM, value=255
2020-02-29 05:18:30.434 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.435 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OnOffType
2020-02-29 05:18:30.436 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.437 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OpenClosedType
2020-02-29 05:18:30.439 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:512:node21:sensor_door to OPEN [OpenClosedType]
2020-02-29 05:18:30.441 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.442 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OnOffType
2020-02-29 05:18:30.444 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.446 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OnOffType
2020-02-29 05:18:30.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Commands processed 1.
2020-02-29 05:18:30.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@158d37c.
2020-02-29 05:18:30.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-29 05:18:30.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-29 05:18:30.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-02-29 05:18:30.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-02-29 05:18:35.189 [INFO ] [ipse.smarthome.model.script.bewegung] - Schlafzimmer von innen geöffnet

[vossivossi]

@alfderheld

I dont know, where I lost 5 seconds between event and action

Without a debug log it is only guessing, but 5 seconds sounds like a typical timeout in Z-Wave communication.

[rossko57]

Related topics

Rule Takes a Few Seconds to Fire the First Time

Someone told me that this is a known issue, but I found a work around that seems to alleviate this problem, and I thought I would share it for anyone that might benefit from it. Just add a “System started” rule in each rules file, if it does not already contain one. This is an example: rule "System started" when System started then logInfo("info", "Loaded model 'file_name.rules'") end It seems to make it so that all of my rules fire right away. It seems to be working so far at least. …

Idea: hack to avoid rule delay, keep time-critical rules in memory

Maybe the java experts can comment on this… Problem: Rules can take 10-20 seconds to trigger if they not have triggered very recently. My theory is that a JIT compiler runs over them before they are executed, and after some time of not using it, the result is purged from memory. Thus it has to be compiled again, which takes time on my Raspi (3+). My solution: I put this in the rule file that I want to prevent from being recompiled: rule "keep this thing in memory" //use the compiled code in t…

[5iver (Scott Rushworth)]

The solution for this is to use the new rule engine. If you’d like to still use scripts, there is scripted automation.