Zwave - Slow Device Response

Add-ons Bindings
1

Hi @chris

I have always had near instantaneous responses from my z-wave devices. However, in recent weeks we’ve found that there is often (but not always) a very noticeable delay between sending a command to a device and the physical device responding.

As an example, if we look at nodes 8 and 18 at 07:00:26.287 and 07:00:26:384, commands were sent to these two lamps to turn them on at a dim level of 10. If I am reading the logs correctly, the lamps did not turn on for about 4 seconds.

The network viewer shows that the two nodes in question seem to have good connectivity to the neighbours.

Is there anything else I can do to get back consistent response times or has something changed in the binding in recent times?

Thanks Chris

zwave_log.PNG1277×357 75.6 KB 

2017-01-12 07:00:25.941 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=230, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-01-12 07:00:26.287 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:controller:node8:switch_dimmer --> 10
2017-01-12 07:00:26.287 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 8: Creating new message for command SWITCH_MULTILEVEL_SET
2017-01-12 07:00:26.287 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 22. Queue={}
2017-01-12 07:00:26.304 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Command received zwave:device:controller:node18:switch_dimmer --> 10
2017-01-12 07:00:26.305 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Creating new message for command SWITCH_MULTILEVEL_SET
2017-01-12 07:00:26.305 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 23. Queue={}
2017-01-12 07:00:30.902 [WARN ] [ocol.ZWaveController$ZWaveSendThread] - NODE 17: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=17, callback=230, payload=11 09 60 0D 01 01 71 04 00 00 00 
2017-01-12 07:00:30.902 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 22
2017-01-12 07:00:30.902 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 08 03 26 01 0A 25 E7 02 
2017-01-12 07:00:30.902 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 8: Sending REQUEST Message = 01 0A 00 13 08 03 26 01 0A 25 E7 02 
2017-01-12 07:00:30.914 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-01-12 07:00:30.918 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-12 07:00:30.918 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-01-12 07:00:30.918 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-01-12 07:00:30.918 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-01-12 07:00:30.918 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 8: Sent Data successfully placed on stack.
2017-01-12 07:00:30.967 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E7 00 00 05 09 
2017-01-12 07:00:30.970 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-12 07:00:30.970 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E7 00 00 05 00 00 07 
2017-01-12 07:00:30.970 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E7 00 00 05 00 00 07 
2017-01-12 07:00:30.970 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=E7 00 00 05 
2017-01-12 07:00:30.970 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 8: SendData Request. CallBack ID = 231, Status = Transmission complete and ACK received(0)
2017-01-12 07:00:30.970 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 8: Starting initialisation from DONE
2017-01-12 07:00:30.970 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1f1d6f0a already registered
2017-01-12 07:00:30.970 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=8, callback=231, payload=08 03 26 01 0A 
2017-01-12 07:00:30.970 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=E7 00 00 05 
2017-01-12 07:00:30.970 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=231, expected=SendData, cancelled=false        transaction complete!
2017-01-12 07:00:30.970 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-01-12 07:00:30.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-01-12 07:00:30.970 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 8: Response processed after 67ms/4985ms.
2017-01-12 07:00:30.971 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 21
2017-01-12 07:00:30.971 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 12 03 26 01 0A 25 E8 17 
2017-01-12 07:00:30.971 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 0A 00 13 12 03 26 01 0A 25 E8 17 
2017-01-12 07:00:30.987 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-01-12 07:00:30.988 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-12 07:00:30.988 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-01-12 07:00:30.988 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-01-12 07:00:30.988 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-01-12 07:00:30.988 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: Sent Data successfully placed on stack.
2017-01-12 07:00:31.036 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E8 00 00 05 06 
2017-01-12 07:00:31.038 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-12 07:00:31.039 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 E8 00 00 05 00 00 08 
2017-01-12 07:00:31.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 E8 00 00 05 00 00 08 
2017-01-12 07:00:31.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=E8 00 00 05 
2017-01-12 07:00:31.039 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 18: SendData Request. CallBack ID = 232, Status = Transmission complete and ACK received(0)
2017-01-12 07:00:31.039 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 18: Starting initialisation from DONE
2017-01-12 07:00:31.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@20d3ede9 already registered
2017-01-12 07:00:31.039 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=18, callback=232, payload=12 03 26 01 0A 
2017-01-12 07:00:31.039 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=E8 00 00 05 
2017-01-12 07:00:31.039 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=232, expected=SendData, cancelled=false        transaction complete!
2017-01-12 07:00:31.039 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-01-12 07:00:31.039 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-01-12 07:00:31.039 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 18: Response processed after 65ms/4985ms.
2017-01-12 07:00:31.039 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 20
2017-01-12 07:00:31.040 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 11 06 60 0D 01 02 26 02 25 CB 52 
2017-01-12 07:00:31.040 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 17: Sending REQUEST Message = 01 0D 00 13 11 06 60 0D 01 02 26 02 25 CB 52 
2017-01-12 07:00:31.055 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-01-12 07:00:31.059 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-12 07:00:31.060 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-01-12 07:00:31.060 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-01-12 07:00:31.061 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-01-12 07:00:31.061 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: Sent Data successfully placed on stack.
2017-01-12 07:00:31.075 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 CB 00 00 02 22 
2017-01-12 07:00:31.078 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-12 07:00:31.078 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 CB 00 00 02 00 00 2C 
2017-01-12 07:00:31.078 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 CB 00 00 02 00 00 2C 
2017-01-12 07:00:31.079 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=CB 00 00 02 
2017-01-12 07:00:31.079 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 17: SendData Request. CallBack ID = 203, Status = Transmission complete and ACK received(0)
2017-01-12 07:00:31.079 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 17: Starting initialisation from DONE

zwave_network.PNG783×392 54.2 KB

2

What is the problem with node 17? It looks to be timing out and this delays other messages - at least in this case. The binding is only processing one transaction at a time so I f you have a device that is take a lot of time it will slow down everything.

3

Make sure your sd card is ok. I had alot of delays in my system, they all were related to a corrupted sdcard. Not saying this is your problem but might be worth looking into.

Regards s

4

@chris Thanks and you’re right - the logs show a lot of node 17 related entries. Node 17 is a Fibaro FGD 212 dimmer. I haven’t had any issues with it in the past, and from the network map, it looks to have good connectivity.

Is there anything specific I can do to resolve its issues other than try to exclude/re-include?

@Seaside I’m actually running in a VM on a normal PC (HP Microserver Gen8), and not an RPi, and so no sdcard involved. Thanks anyway!

5

I’m not sure why you should need to exclude/include the device, so this might not solve the issue. I’m not sure why it would be playing up - maybe it’s an issue with polling of a specific channel, or maybe it’s just a communication issue - it’s hard to say as there wasn’t anything in the log other than the end of a transaction that timed out and this was the cause of the issue you raised…

If you can provide a longer log I’m happy to have a look…

6

Thanks Chris. I’ve pm’d you some logs so as not to clog up the thread.

7

@smar What software are you using for log analysis in your screenshot? – Looks good!

8

http://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

9

Awesome! – Thanks, Chris!