zigbee2mqtt: big delay in processing

Xiaomi, Ikea TRÅDFRI, Philips Hue and more.

Moderator: leecollings

Post Reply
mbacks
Posts: 2
Joined: Sunday 14 February 2021 11:02
Target OS: -
Domoticz version:
Contact:

zigbee2mqtt: big delay in processing

Post by mbacks »

Hi Forum,

at first, thank you for the knowledgebase here, i found much soulutions for my problems with domoticz.

i wrote the first dzvents scripts and use the zigbee2mqtt bridge.

while changing device states, sometimes domoticz need until around 20 seconds to change the state on gui.

here some events from my aquara cube with the output from mosquitto_sub. Each Block is one z2m event with the time beween mosquitto message and Statechange in Domoticz. In this tests, most are faster than 100msec, but there are also some until 5 seconds

is this delay normal?

Version: 2020.2
Build Hash: b63341bc0
Compile Date: 2020-04-26 11:47:55
dzVents Version: 3.0.2
Python Version: 3.7.3 (default, Jul 25 2020, 13:03:44) [GCC 8.3.0]
Uptime: 1 Days, 2 Hours, 26 Minutes, 15 Seconds
<plugin key="Zigbee2MQTT" name="Zigbee2MQTT" version="3.0.0">
zigbee2mqtt v.1.17.0 (zStack3x0 20201026)
Running in LXC Container with Proxmox on AMD Ryzen 7 PRO 4750G

best regards,
Max

Code: Select all

0,014
54.576 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"tap\",\"action_side\":0,\"angle\":-4.72,\"battery\":80,\"linkquality\":141,\"side\":0,\"voltage\":2965}'"}
54.577 zigbee2mqtt/aquara_cube1 {"action":"tap","action_side":0,"angle":-4.72,"battery":80,"linkquality":141,"side":0,"voltage":2965}
54.591  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:141 sValue:141 
54.592  Debug: SQLH HandleOnOffAction: OnAction:
54.592  Debug: SQLH UpdateValueInt aquara_cube1_cube HwID:3  DevID:0x00158d00051e1723_cube Type:244  sType:62 nValue:1 sValue:30 
54.593  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:0 sValue:0 
54.611  Status: dzVents: Info: ------ Finished cube1
54.611  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
54.611  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "141"
54.631  Status: dzVents: Info: ------ Finished cube1
54.631  Status: dzVents: Info: ------ Finished cube1
54.631  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_cube (z2m)", Index: 27
54.631  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
54.631  Status: dzVents: Info: Handling events for: "aquara_cube1_cube", value: "Tap"
54.631  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "0"
54.631  Status: dzVents: Info: side 0


5,35
29.589 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":1,\"action_side\":0,\"action_to_side\":0,\"angle\":-4.72,\"battery\":80,\"from_side\":1,\"linkquality\":135,\"side\":0,\"to_side\":0,\"voltage\":2965}'"}
29.591 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":1,"action_side":0,"action_to_side":0,"angle":-4.72,"battery":80,"from_side":1,"linkquality":135,"side":0,"to_side":0,"voltage":2965}
34.941  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:135 sValue:135 
34.942  Debug: SQLH HandleOnOffAction: OnAction:
34.943  Debug: SQLH UpdateValueInt aquara_cube1_cube HwID:3  DevID:0x00158d00051e1723_cube Type:244  sType:62 nValue:1 sValue:10 
34.960  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
34.960  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "135"
34.961  Status: dzVents: Info: ------ Finished cube1
34.980  Status: dzVents: Info: ------ Finished cube1
34.980  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_cube (z2m)", Index: 27
34.980  Status: dzVents: Info: Handling events for: "aquara_cube1_cube", value: "Flip 90"


2,086
48.374 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":0,\"action_side\":1,\"action_to_side\":1,\"angle\":-4.72,\"battery\":80,\"from_side\":0,\"linkquality\":138,\"side\":1,\"to_side\":1,\"voltage\":2965}'"}
48.375 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":0,"action_side":1,"action_to_side":1,"angle":-4.72,"battery":80,"from_side":0,"linkquality":138,"side":1,"to_side":1,"voltage":2965}
50.461  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:138 sValue:138 
50.462  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:1 sValue:1 
50.481  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "138"
50.482  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
50.489  Status: dzVents: Info: ------ Finished cube1
50.508  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "1"
50.509  Status: dzVents: Info: ------ Finished cube1
50.509  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
50.509  Status: dzVents: Info: side 1


0,001
56.874 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":1,\"action_side\":0,\"action_to_side\":0,\"angle\":-4.72,\"battery\":80,\"from_side\":1,\"linkquality\":114,\"side\":0,\"to_side\":0,\"voltage\":2965}'"}
56.875  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:114 sValue:114 
56.876  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:0 sValue:0 
56.876 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":1,"action_side":0,"action_to_side":0,"angle":-4.72,"battery":80,"from_side":1,"linkquality":114,"side":0,"to_side":0,"voltage":2965}
56.894  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "114"
56.895  Status: dzVents: Info: ------ Finished cube1
56.895  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
56.915  Status: dzVents: Info: ------ Finished cube1
56.915  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
56.915  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "0"
56.915  Status: dzVents: Info: side 0


0,008
07.378 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":0,\"action_side\":1,\"action_to_side\":1,\"angle\":-4.72,\"battery\":80,\"from_side\":0,\"linkquality\":132,\"side\":1,\"to_side\":1,\"voltage\":2965}'"}
07.379 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":0,"action_side":1,"action_to_side":1,"angle":-4.72,"battery":80,"from_side":0,"linkquality":132,"side":1,"to_side":1,"voltage":2965}
07.387  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:132 sValue:132 
07.388  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:1 sValue:1 
07.407  Status: dzVents: Info: ------ Finished cube1
07.407  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
07.407  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "132"
07.427  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
07.427  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "1"
07.427  Status: dzVents: Info: side 1
07.428  Status: dzVents: Info: ------ Finished cube1


2,294
19.211 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":1,\"action_side\":0,\"action_to_side\":0,\"angle\":-4.72,\"battery\":80,\"from_side\":1,\"linkquality\":114,\"side\":0,\"to_side\":0,\"voltage\":2965}'"}
19.212 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":1,"action_side":0,"action_to_side":0,"angle":-4.72,"battery":80,"from_side":1,"linkquality":114,"side":0,"to_side":0,"voltage":2965}
21.506  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:114 sValue:114 
21.508  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:0 sValue:0 
21.526  Status: dzVents: Info: ------ Finished cube1
21.526  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
21.526  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "114"
21.545  Status: dzVents: Info: ------ Finished cube1
21.545  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
21.545  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "0"
21.545  Status: dzVents: Info: side 0


0,041
30.431 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":0,\"action_side\":1,\"action_to_side\":1,\"angle\":-4.72,\"battery\":80,\"from_side\":0,\"linkquality\":123,\"side\":1,\"to_side\":1,\"voltage\":2965}'"}
30.432 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":0,"action_side":1,"action_to_side":1,"angle":-4.72,"battery":80,"from_side":0,"linkquality":123,"side":1,"to_side":1,"voltage":2965}
30.473  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:123 sValue:123 
30.474  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:1 sValue:1 
30.493  Status: dzVents: Info: ------ Finished cube1
30.493  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
30.493  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "123"
30.513  Status: dzVents: Info: ------ Finished cube1
30.513  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
30.513  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "1"
30.513  Status: dzVents: Info: side 1


0,046
42.742 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":1,\"action_side\":0,\"action_to_side\":0,\"angle\":-4.72,\"battery\":80,\"from_side\":1,\"linkquality\":111,\"side\":0,\"to_side\":0,\"voltage\":2965}'"}
42.743 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":1,"action_side":0,"action_to_side":0,"angle":-4.72,"battery":80,"from_side":1,"linkquality":111,"side":0,"to_side":0,"voltage":2965}
42.789  Debug: SQLH UpdateValueInt aquara_cube1_signal HwID:3  DevID:0x00158d00051e1723_signal Type:243  sType:31 nValue:111 sValue:111 
42.791  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:0 sValue:0 
42.810  Status: dzVents: Info: ------ Finished cube1
42.810  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_signal (z2m)", Index: 24
42.810  Status: dzVents: Info: Handling events for: "aquara_cube1_signal", value: "111"
42.829  Status: dzVents: Info: ------ Finished cube1
42.829  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
42.829  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "0"
42.829  Status: dzVents: Info: side 0


0,031
55.626 zigbee2mqtt/bridge/logging {"level":"info","message":"MQTT publish: topic 'zigbee2mqtt/aquara_cube1', payload '{\"action\":\"flip90\",\"action_from_side\":0,\"action_side\":1,\"action_to_side\":1,\"angle\":-4.72,\"battery\":80,\"from_side\":0,\"linkquality\":111,\"side\":1,\"to_side\":1,\"voltage\":2965}'"}
55.628 zigbee2mqtt/aquara_cube1 {"action":"flip90","action_from_side":0,"action_side":1,"action_to_side":1,"angle":-4.72,"battery":80,"from_side":0,"linkquality":111,"side":1,"to_side":1,"voltage":2965}
55.659  Debug: SQLH UpdateValueInt aquara_cube1_side HwID:3  DevID:0x00158d00051e1723_side Type:243  sType:31 nValue:1 sValue:1 
55.678  Status: dzVents: Info: ------ Start internal script: cube1: Device: "aquara_cube1_side (z2m)", Index: 29
55.678  Status: dzVents: Info: Handling events for: "aquara_cube1_side", value: "1"
55.679  Status: dzVents: Info: ------ Finished cube1
55.679  Status: dzVents: Info: side 1
mbacks
Posts: 2
Joined: Sunday 14 February 2021 11:02
Target OS: -
Domoticz version:
Contact:

Re: zigbee2mqtt: big delay in processing

Post by mbacks »

maybe a few words about why these 2-5 seconds are too long for me:
I have a motion detector in the hallway, which should turn on the light. When I go from the bedroom to the kitchen, it takes me less than 5 seconds to cross the hall.
All the fun with domoticz makes no sense to me if I don't get light when I need it.
Besides, the female acceptance factor is not very high when she presses the button in the living room, wonders why nothing happens, presses it again, and the light flickers only once afterwards.
Post Reply

Who is online

Users browsing this forum: No registered users and 1 guest