Response to Z-Wave sensor - intermittent short delay

Tags: #<Tag:0x00007f5c93654ae0> #<Tag:0x00007f5c936549a0> #<Tag:0x00007f5c93654860>

I installed OH2 a couple of months ago, with a small system based on Z-Wave, initially just to automate the hall lights.

Platform information:
* Hardware: Raspberry Pi Model 3B,
* JAVA: openjdk version “1.8.0_152” , OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76). OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
* Z-Wave Node 005: Fibaro FGMS001 Motion Sensor
* Z-Wave Node 006: Fibaro FGD212 Dimmer 2
* Aeotec Z-Stick USB Controller

The simple expectation is for the lights to come on after movement has been detected by the sensor (although additionally time of day and luminance are used). The operational rules are based almost 100% from post 30 in ZekeB - How I have automated my lights - That is a great set of rules - thanks.

These worked almost from the start, but my problem was a delay of a few seconds between the sensor detecting movement and the light coming on. This occurred seemingly on a random basis. See here:

No Delay:

2020-03-16 21:10:16.787 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-16 21:10:16.792 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-16 21:10:16.908 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-16 21:10:16.917 [vent.ItemStateChangedEvent] - FibaroHall_Light_Virtual changed from 0 to 68.0

Delay:

2020-03-17 08:46:41.102 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-17 08:46:41.105 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-17 08:46:45.287 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 42.0
2020-03-17 08:46:45.293 [vent.ItemStateChangedEvent] - FibaroHall_Light_Virtual changed from 0 to 42.0

I noticed that delays did not occur one after the other, but only seemed to occur when there was a gap between detections of a few hours. Having searched on the forums about ‘delays’ and their remedies eg. [SOLVED] Rule execution delayed, I tried changing settings concerning the threadpool, EXTRA_JAVA and the sensitivity of the sensor, etc. But no luck

Next, a detailed comparison of the log entries between (1) occasions when the lights came on almost immediately and (2) occasions when there was a delay. One possibility I investigated was that any automatic updates of the sensor node caused the next sensor detection to have a delay. eg after:

2020-03-17 05:05:00.594 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated

The Z-wave binding settings for the sensor on OH2 allow me to change the updating frequency on the sensor. Under ‘Wakeup Configuration’, the ‘Wakeup interval’ was at the default of 2 hours, which suggested a possible cause of the problem. So I changed this to the maximum permitted of 65535 seconds (approx 18 hours). This significantly reduced the number of delays to about one per day.

My conclusion is that the problem is with this updating of the node/thing. It would be useful to eliminate the problem completely. I do not know whether the problem is with the rules or something to do with the Zwave binding. I have turned on debugging for Zwave and here is the log for the delayed incident:

2020-03-17 08:46:41.040 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 05 09 71 05 00 00 00 FF 07 08 00 7C 
2020-03-17 08:46:41.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 09 71 05 00 00 00 FF 07 08 00 
2020-03-17 08:46:41.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 09 71 05 00 00 00 FF 07 08 00 
2020-03-17 08:46:41.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-03-17 08:46:41.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2020-03-17 08:46:41.067 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2020-03-17 08:46:41.069 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2020-03-17 08:46:41.071 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_ALARM
2020-03-17 08:46:41.073 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_ALARM V5 NOTIFICATION_REPORT
2020-03-17 08:46:41.075 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 5: NOTIFICATION report - 0 = 0, event=8, status=255, plen=0
2020-03-17 08:46:41.077 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 5: Alarm Type = BURGLAR (0)
2020-03-17 08:46:41.079 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2020-03-17 08:46:41.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_ALARM, value=255
2020-03-17 08:46:41.084 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter processing NOTIFICATION
2020-03-17 08:46:41.087 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter NOTIFICATION event is 8, type OnOffType
2020-03-17 08:46:41.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:16fd2e2de4a:node5:alarm_motion to ON [OnOffType]
2020-03-17 08:46:41.094 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter processing NOTIFICATION
2020-03-17 08:46:41.097 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter NOTIFICATION event is 8, type OnOffType
2020-03-17 08:46:41.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
2020-03-17 08:46:41.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18cd06c.
2020-03-17 08:46:41.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-03-17 08:46:41.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-03-17 08:46:41.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-03-17 08:46:41.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-03-17 08:46:45.186 [INFO ] [pse.smarthome.model.script.Rule Info] - Step 1 of motion detectedHomeStatus: HomeStatus (Type=NumberItem, State=0, Label=State is, Category=null)
2020-03-17 08:46:45.220 [INFO ] [pse.smarthome.model.script.Rule Info] - Step 2 of motion detected room: FibaroHall control: FibaroHall_Motion_Pause (Type=SwitchItem, State=OFF, Label=Fibaro Hall Motion Control Pause, Category=null, Groups=[LightMotionControls, GF_Hall])FibaroHall_Motion_Override (Type=SwitchItem, State=OFF, Label=Fibaro Hall Motion Control Override, Category=null, Groups=[LightMotionControls, GF_Hall])Lux: 2

It does not seem to be any different to the log when there is no delay.

Any ideas please? Thank you.

1 Like

See also

There was a thread awhile back I recall where folks were discussing a delay on the first run of a rule, the delay comes from the time it takes to load the rule into memory of something. The discussion was about some method used to keep the rule from unloading although I don’t recall the solution.
I know when I first get home from work, it always seems to take an extra few seconds for the motion to trigger the lights on the first run

Thank you both for your suggestions.

I have tracked down the threads you suggested, and, having restored the ‘Wakeup interval’ of node 5 to its default of 2 hours, report as follows:

  1. My etc/default/openhab2 file already contains the line
    EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB-ZStick -Xms400m -Xmx650m", follwing my earlier researches, so I don’t think anything else is needed here.

  2. Arno’s rule ‘keep this thing in memory’ looked hopeful so I put it into the relevant rule file, running every minute.

Unfortunately the same delays were still occurring.

I now did some more investigation at the weekend of the automatic updating of the sensor node and this led to a interesting finding. To more conveniently observe what was happening I increased the ‘Wakeup interval’ to 20 minutes and examined the events.log file over the course of an evening. The following excerpt only shows an edited version containing lines relating to when the node was updated, and when the sensor triggered the light (FibaroHall_Light_Virtual) to come on. (i.e. I have excluded occasions when the sensor was triggered but the light was already on or when it did not need to come on as the light level was above the luminance threshold).

2020-03-21 16:25:30.651 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 16:45:48.300 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 17:06:05.206 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 17:26:21.922 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 17:46:38.872 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 17:50:40.021 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 17:50:40.026 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 17:50:42.691 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:04:00.663 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:04:00.668 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:04:00.774 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:06:55.788 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 18:08:49.487 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:08:49.491 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:08:52.324 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:11:12.050 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:11:12.053 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:11:12.183 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:14:41.875 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:14:41.878 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:14:41.978 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:25:27.738 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:25:27.741 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:25:27.854 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:27:12.570 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 18:30:29.771 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:30:29.774 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:30:32.709 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:34:45.622 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:34:45.625 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:34:45.726 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:36:38.095 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:36:38.099 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:36:38.223 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:47:29.727 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 18:50:31.891 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:50:31.896 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:50:32.034 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:52:22.998 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:52:23.005 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:52:23.107 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 18:53:14.797 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 18:53:14.801 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 18:53:14.903 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 19:06:47.976 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 19:06:47.979 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 19:06:48.105 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 19:07:46.890 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 19:08:55.366 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 19:08:55.379 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 19:08:58.917 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 19:10:11.923 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 19:10:11.926 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 19:10:12.032 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 19:28:04.911 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 19:45:03.075 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 19:45:03.079 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 19:45:06.398 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 19:45:06.406 [vent.ItemStateChangedEvent] - FibaroHall_Light_Virtual changed from 0 to 68.0
2020-03-21 19:48:21.881 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 19:50:01.637 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 19:50:01.645 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 19:50:05.036 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 20:05:08.920 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 20:05:08.923 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 20:05:09.046 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 20:08:40.400 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 20:12:03.049 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 20:12:03.054 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 20:12:06.591 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 20:14:43.180 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 20:14:43.185 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 20:14:43.306 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 20:18:25.634 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 20:18:25.637 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 20:18:25.739 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 20:18:56.096 [vent.ItemStateChangedEvent] - zwave_serial_zstick_16fd2e2de4a_serial_sof changed from 2341 to 2342
2020-03-21 20:19:12.147 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 20:19:12.150 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 20:19:12.271 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 20:28:58.968 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 20:49:16.580 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 21:09:33.696 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 21:29:53.561 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 21:35:02.413 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 21:35:02.416 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 21:35:06.203 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 21:36:02.925 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 21:36:02.928 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 21:36:03.042 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 21:39:31.303 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 21:39:31.309 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 21:39:31.424 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 21:42:49.737 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 21:42:49.742 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 21:42:49.875 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 21:50:13.449 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 22:10:31.575 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 22:30:51.608 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 22:51:11.993 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 22:55:09.314 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 22:55:09.318 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 22:55:12.772 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 22:56:29.967 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.
2020-03-21 22:58:10.729 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 22:58:10.732 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 22:58:13.940 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 23:00:08.852 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 23:00:08.855 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 23:00:08.984 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 23:01:21.352 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 23:01:21.357 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 23:01:21.448 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 23:02:46.395 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 23:02:46.398 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 23:02:46.498 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 23:04:46.776 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 23:04:46.779 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-21 23:04:46.871 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-21 23:09:04.370 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-21 23:11:32.016 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated.



Although I cannot claim this to be a scientific experiment, it seems to me that there is a delay of 2 or 3 seconds ONLY for the FIRST instance after every update. This is easy to see if you pick a set of 3 adjacent lines with very similar times. Sometimes they are very close, and sometimes the third item has the delay. When there is a delay, this is the one after the update.

I do not know why this updating causes the delay the first time the rule is run. My only solution is to increase the setting to the maximum permitted of 65535 seconds, as indicated in my original post. This at least means the delay only occurs about once a day. Although this is acceptable, it would be nice to fix the underlying problem.