Big time delay between execution.

[Mayki07]

I have four light bulbs added to the Domoticz. I have created a script for DzVents.

return {
    active = true,
    on = {
        devices = { 
                         'Downlight', 
                      }
    },
    execute = function(dz, item)
        
        
    if item.state == 'Bright' then
        dz.devices('Downlight levá - Scenes').dimTo(10)
        dz.devices('Downlight střed levá - Scenes').dimTo(10)
        dz.devices('Downlight střed pravá - Scenes').dimTo(10)
        dz.devices('Downlight pravá - Scenes').dimTo(10)
    elseif item.state == 'TV' then
        dz.devices('Downlight levá - Scenes').dimTo(20)
        dz.devices('Downlight střed levá - Scenes').dimTo(20)
        dz.devices('Downlight střed pravá - Scenes').dimTo(20)
        dz.devices('Downlight pravá - Scenes').dimTo(20)
    elseif item.state == 'Warm' then
        dz.devices('Downlight levá - Scenes').dimTo(30)
        dz.devices('Downlight střed levá - Scenes').dimTo(30)
        dz.devices('Downlight střed pravá - Scenes').dimTo(30)
        dz.devices('Downlight pravá - Scenes').dimTo(30)
    elseif item.state == 'Midnight' then
        dz.devices('Downlight levá - Scenes').dimTo(40)
        dz.devices('Downlight střed levá - Scenes').dimTo(40)
        dz.devices('Downlight střed pravá - Scenes').dimTo(40)
        dz.devices('Downlight pravá - Scenes').dimTo(40)    
     end
    end
}

If I execute a command, the time delay between each bulb is about 8 seconds. The same thing when I create a scene to turn all the bulbs on and off at once, the time delay between the bulbs is 8-10 seconds. Is there anything we can do about it?

[Mayki07]

I made some video:

[SamaelRanger]

@Mayki07 please enable Debug log per device and attach log where your scene is activated.

[Napalmcold]

Hi everyone! Any update? I have the same issue

[SamaelRanger]

@Napalmcold Can you gather and attach log with debug enabled?

[eserero]

Just stumbled upon this thread. have the same problem. logs below.
there seem to be a very long delay in the middle (5 seconds) then another 2 delays afterward...
any idea what can be the issue?

2019-12-22 20:01:15.215 (Bedside Light (Xiaomi)) Pushing 'onCommandCallback' on to queue
2019-12-22 20:01:15.235 (Bedside Light (Xiaomi)) Processing 'onCommandCallback' message
2019-12-22 20:01:15.236 (Bedside Light (Xiaomi)) Calling message handler 'onCommand'.
2019-12-22 20:01:15.236 (Bedside Light (Xiaomi)) onCommand called for Unit 2 cmd 'Off' Level '25' Color ''
2019-12-22 20:01:15.236 (Bedside Light (Xiaomi)) Call command: ['./MyBulb.py', '10.0.0.65', '*************************', '--power', 'OFF']
2019-12-22 20:01:15.535 (Bedside Light (Xiaomi))
2019-12-22 20:01:15.535 (Bedside Light (Xiaomi)) onHeartbeat called, fetch True
2019-12-22 20:01:15.535 (Bedside Light (Xiaomi)) sensor_measurement
2019-12-22 20:01:15.215 Status: User: Admin initiated a switch command (253/Bedside Light (Xiaomi - CCCW)/Off)
2019-12-22 20:01:20.972 (Bedside Light (Xiaomi))
2019-12-22 20:01:20.972 (Bedside Light (Xiaomi)) power => off
2019-12-22 20:01:20.972 (Bedside Light (Xiaomi)) brightness => 25
2019-12-22 20:01:20.972 (Bedside Light (Xiaomi)) color_temperature => 68
2019-12-22 20:01:20.972 (Bedside Light (Xiaomi)) scene => 0
2019-12-22 20:01:20.972 (Bedside Light (Xiaomi)) delay_off_countdown => 0
2019-12-22 20:01:20.972 (Bedside Light (Xiaomi - CCCW)) Updating device from 1:'25' to have values 0:'25'.
2019-12-22 20:01:20.975 (Bedside Light (Xiaomi)) Update 0: '25' '{"m": 2, "t": 81, "r": 0, "g": 0, "b": 0, "cw": 0, "ww": 0}' (Bedside Light (Xiaomi - CCCW))
2019-12-22 20:01:20.975 (Bedside Light Scene (Xiaomi)) Updating device from 0:'0' to have values 0:'0'.
2019-12-22 20:01:20.979 (Bedside Light (Xiaomi)) Update 0: '0' '{"m": 2, "t": 81, "r": 0, "g": 0, "b": 0, "cw": 0, "ww": 0}' (Bedside Light Scene (Xiaomi))
2019-12-22 20:01:20.979 (Bedside Light (Xiaomi)) Starting device update
2019-12-22 20:01:20.979 (Bedside Light (Xiaomi)) onHeartbeat finished
2019-12-22 20:01:20.988 Status: dzVents: Debug: Dumping domoticz data to /home/adminuser/domoticz/scripts/dzVents/domoticzData.lua
2019-12-22 20:01:21.005 Status: dzVents: Debug: Processing device-adapter for Bedside Light (Xiaomi - CCCW): RGB(W) device adapter
2019-12-22 20:01:21.005 Status: dzVents: Debug: Processing device-adapter for Bedside Light (Xiaomi - CCCW): Switch device adapter
2019-12-22 20:01:21.005 Status: dzVents: Debug: dzVents version: 2.4.19
2019-12-22 20:01:21.005 Status: dzVents: Debug: Event triggers:
2019-12-22 20:01:21.005 Status: dzVents: Debug: - Device: Bedside Light (Xiaomi - CCCW)
2019-12-22 20:01:21.041 Status: dzVents: Debug: Dumping domoticz data to /home/adminuser/domoticz/scripts/dzVents/domoticzData.lua
2019-12-22 20:01:21.054 Status: dzVents: Debug: Processing device-adapter for Bedside Light Scene (Xiaomi): Switch device adapter
2019-12-22 20:01:21.054 Status: dzVents: Debug: dzVents version: 2.4.19
2019-12-22 20:01:21.054 Status: dzVents: Debug: Event triggers:
2019-12-22 20:01:21.054 Status: dzVents: Debug: - Device: Bedside Light Scene (Xiaomi)
2019-12-22 20:01:22.479 (Bedside Light (Xiaomi)) Pushing 'onHeartbeatCallback' on to queue
2019-12-22 20:01:22.981 (Bedside Light (Xiaomi)) Processing 'onHeartbeatCallback' message
2019-12-22 20:01:22.982 (Bedside Light (Xiaomi)) Calling message handler 'onHeartbeat'.
2019-12-22 20:01:22.982 (Bedside Light (Xiaomi)) onHeartbeat called, fetch False
2019-12-22 20:01:22.982 (Bedside Light (Xiaomi)) Awaiting next pool: 2019-12-22 20:02:15.535707

[eserero]

A couple more observations. I run the mybulb.py script directly - and it works reasonably fast. then I run it again from domoticz, and I see the light bulb react quickly, but then domoticz takes a few more seconds until it updates, this slows down any scene or automation considerably

[eserero]

OK - further debugging put the culprit in this line in plugin.py in the BulbStatus init function. I just put some debug messages around and saw what takes time.
It seems that

1. "onCommand" uses the same line as below (create a sub process to run command line) - the line returns pretty fast, then
2. onCommand runs onHeartbeat in order to refresh the screen,
3. onHeartbeat runs BulbStatus init function, which also uses subprocess - but this take a few seconds to return.
   data = subprocess.check_output(cmd, cwd=Parameters["HomeFolder"], startupinfo=startupinfo)

any idea why it takes 5-6 seconds?

[SamaelRanger]

There is a dev branch exist. https://github.com/deennoo/domoticz-Xiaomi-Led-Lamp/tree/dev. You can try dev version of Domoticz with that version of plugin. In dev (Beta) version a bug with side-projects initialization of python is fixed so after that no need to use external script at all.

[SamaelRanger]

I am waiting the next release of Domoticz to merge dev branch to master.

[eserero]

Ah - much appreceated. I think I"ll wait for the next release then... dont want to mess my house too much :-)

[eserero]

just tried it on the latest domoticz. seems much improved. I will test more. beware that the latest domoticz breaks support in ubuntu 18 (but someone compiled a fix...)

[eserero]

OK - still have some problems with the development branch.
in some cases, it works really fast, but in others it can take up to 5-10 seconds for the light to turn on, in this time it blocks the domoticz queue - so nothing else works until it get released.
it seems that the problem happens the first time I turn the light on or off after a few minutes then there is a big delay. subsequent switching on or off immediately afterward are very quick, but then after a few minutes it happens again.
any idea?

update: I put some debug messages after the " self.MyBulb.off()" and " self.MyBulb.on()" lines in the oncommand section and the printouts are coming pretty fast. but the light doesnt actually turn on or off until I see the onHeartbeat code get executed which appear after 10 seconds or so - at least this is how it seems.

another update - here is the log. note the 5 seconds gap from the moment the oncommand is run, until the onheartbeat finished. not sure if this is related or not, I thought the self.MyBulb.on() should have done the trick....

last update for today : maybe sensor_measurement takes a lot of time? its the last printout before the we get stuck for a few seconds. should we move the heartbeat to a different thread? (not on the oncommand thread.

couldn't resist update: its not sensor_measurement, it looks like the domoticz update is taking the time. any idea why?

2020-04-28 19:11:45.631 (Parents Right Bedside Light (Xiaomi)) Pushing 'onCommandCallback' on to queue
2020-04-28 19:11:45.646 (Parents Right Bedside Light (Xiaomi)) Processing 'onCommandCallback' message
2020-04-28 19:11:45.646 (Parents Right Bedside Light (Xiaomi)) Calling message handler 'onCommand'.
2020-04-28 19:11:45.646 (Parents Right Bedside Light (Xiaomi)) onCommand: Unit 2 cmd 'On' Level '99' Color ''
2020-04-28 19:11:45.663 (Parents Right Bedside Light (Xiaomi)) onCommand: mybulb is set to on
2020-04-28 19:11:45.663 (Parents Right Bedside Light (Xiaomi)) onHeartbeat called, fetch True
2020-04-28 19:11:45.663 (Parents Right Bedside Light (Xiaomi)) sensor_measurement
2020-04-28 19:11:45.992 (conbee II deconz) Pushing 'onHeartbeatCallback' on to queue
2020-04-28 19:11:45.631 Status: User: Admin initiated a switch command (251/Parents Right Bedside Light (Xiaomi - CCCW)/On)
2020-04-28 19:11:50.714 (Parents Right Bedside Light (Xiaomi))
2020-04-28 19:11:50.715 (Parents Right Bedside Light Scenes (Xiaomi)) Updating device from 0:'0' to have values 1:'0'.
2020-04-28 19:11:50.723 (Parents Right Bedside Light (Xiaomi)) Update 1: '0' '{"m": 2, "t": 130, "r": 0, "g": 0, "b": 0, "cw": 0, "ww": 0}' (Parents Right Bedside Light Scenes (Xiaomi))
2020-04-28 19:11:50.723 (Parents Right Bedside Light (Xiaomi - CCCW)) Updating device from 0:'99' to have values 1:'99'.
2020-04-28 19:11:50.727 (Parents Right Bedside Light (Xiaomi)) Update 1: '99' '{"m": 2, "t": 130, "r": 0, "g": 0, "b": 0, "cw": 0, "ww": 0}' (Parents Right Bedside Light (Xiaomi - CCCW))
2020-04-28 19:11:50.727 (Parents Right Bedside Light (Xiaomi)) Starting device update
2020-04-28 19:11:50.727 (Parents Right Bedside Light (Xiaomi)) onHeartbeat finished

[eserero]

I continued to investigate, and remove all the onheartbeat code completely, and the issue still happening, ist on the "self.MyBulb.off()" and " self.MyBulb.on()" lines in the oncommand section - the commands just takes 5-6 seconds (at least the time between the log before and after).
this does not seem to happen if I use the Xiaomi program from the phone.
any idea?

[SamaelRanger]

Try to update miio library in python: pip install -U python-miio

[eserero]

I did, using the latest now... if I run it from command line, it work immediatly. if I run it from domoticz, it gets delay....

[eserero]

I actually implemented a virtual button using dzvents running linux command line (python-miio) and it works great in terms of responsiveness, but of course I dont have the feedback and its quite an ugly implementation. any suggestion on what to investigate next? its pretty annoying to debug as it happens only after a short while.

[deennoo]

Sorry, but i flash Tasmota on it....doesn't use this plugin anymore.

Frok it ans make it yours, i will update domoticz forum about this