Delays, how to look for reasons?

[CzarnyLewis]

Hello,

I am very pleased with Domoticz from dzVents, but I can't deal with the delays that generate scripts. In section Switches devices responds immediately, but when I am write a relations between them in dzVents, sometimes response in 1 second, another time 4 seconds. I don`t know how to find a problem.
Example of log with debug:

Code: Select all

2020-04-24 23:04:40.391 Status: dzVents: Info: ############################################################
2020-04-24 23:04:40.391 Status: dzVents: Info:
2020-04-24 23:04:43.299 Status: dzVents: Info: ------ Finished Salon Światło Łóźko
2020-04-24 23:04:43.299 Status: dzVents: Debug: Commands sent to Domoticz:

Delays are completely random. In above example, as you can see I have 3 seconds delay, but why? It`s just example, I have many of this situations.
Everything on Raspberry Pi 3 B +, before it was Stretch, now Burst. I tried to reinstall everything and nothing. No scripting errors.

Where to find a problem?

[waaren]

Hello,

I am very pleased with Domoticz from dzVents, but I can't deal with the delays that generate scripts. In section Switches devices responds immediately, but when I am write a relations between them in dzVents, sometimes response in 1 second, another time 4 seconds. I don`t know how to find a problem.
Example of log with debug:

Code: Select all

2020-04-24 23:04:40.391 Status: dzVents: Info: ############################################################
2020-04-24 23:04:40.391 Status: dzVents: Info:
2020-04-24 23:04:43.299 Status: dzVents: Info: ------ Finished Salon Światło Łóźko
2020-04-24 23:04:43.299 Status: dzVents: Debug: Commands sent to Domoticz:

Delays are completely random. In above example, as you can see I have 3 seconds delay, but why? It`s just example, I have many of this situations.
Everything on Raspberry Pi 3 B +, before it was Stretch, now Burst. I tried to reinstall everything and nothing. No scripting errors.

Where to find a problem?

You do not give enough information to start analyzing.

• What version dzVents
• What is in the scripts (Please show the complete script and ALL resulting loglines,)
• What else is happening on your system
• What kind of storage do you use

to name a few things relevant for analyzing your delays.
If the delays are really random then it would be useless to investigate but I expect there is some kind of issue causing it.

[CzarnyLewis]

Hello,

What version dzVents

3.0.1 but before I have 2.5.6 and the problem is the same

What is in the scripts (Please show the complete script and ALL resulting loglines,)

I write simple script (it only changes state for every 5 seconds):

Code: Select all

local Light1Str='Salon Zasilanie Stolik Jadalny i Kawowy'

return {
	on = {devices = {Light1Str}},
	execute = function(dz, item)
	local Light1=dz.devices(Light1Str)

	if Light1.state=="Off" then Light1.switchOn().afterSec(5) else Light1.switchOff().afterSec(5) end        
        
	end
}

and this is a log:

Code: Select all

2020-04-25 13:49:49.292 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2020-04-25 13:49:49.336 Status: dzVents: Debug: Processing device-adapter for Salon Zasilanie Stolik Jadalny i Kawowy: Switch device adapter
2020-04-25 13:49:49.337 Status: dzVents: Debug: dzVents version: 3.0.1
2020-04-25 13:49:49.337 Status: dzVents: Debug: Event triggers:
2020-04-25 13:49:49.337 Status: dzVents: Debug: - Device: Salon Zasilanie Stolik Jadalny i Kawowy
2020-04-25 13:49:49.367 Status: dzVents: Info: Handling events for: "Salon Zasilanie Stolik Jadalny i Kawowy", value: "On"
2020-04-25 13:49:49.367 Status: dzVents: Info: ------ Start internal script: Script #1: Device: "Salon Zasilanie Stolik Jadalny i Kawowy (Shelly)", Index: 31
2020-04-25 13:49:49.368 Status: dzVents: Debug: Constructed timed-command: Off
2020-04-25 13:49:49.368 Status: dzVents: Debug: Constructed timed-command: Off AFTER 5 SECONDS
2020-04-25 13:49:49.368 Status: dzVents: Info: ------ Finished Script #1
2020-04-25 13:49:49.368 Status: dzVents: Debug: Commands sent to Domoticz:
2020-04-25 13:49:49.368 Status: dzVents: Debug: - Salon Zasilanie Stolik Jadalny i Kawowy = Off AFTER 5 SECONDS
2020-04-25 13:49:49.368 Status: dzVents: Debug: =====================================================
2020-04-25 13:49:49.369 Status: EventSystem: Script event triggered: /home/pi/domoticz/dzVents/runtime/dzVents.lua
2020-04-25 13:49:54.540 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2020-04-25 13:49:56.090 Status: dzVents: Debug: Processing device-adapter for Salon Zasilanie Stolik Jadalny i Kawowy: Switch device adapter
2020-04-25 13:49:56.091 Status: dzVents: Debug: dzVents version: 3.0.1
2020-04-25 13:49:56.091 Status: dzVents: Debug: Event triggers:
2020-04-25 13:49:56.091 Status: dzVents: Debug: - Device: Salon Zasilanie Stolik Jadalny i Kawowy
2020-04-25 13:49:56.121 Status: dzVents: Info: Handling events for: "Salon Zasilanie Stolik Jadalny i Kawowy", value: "Off"
2020-04-25 13:49:56.121 Status: dzVents: Info: ------ Start internal script: Script #1: Device: "Salon Zasilanie Stolik Jadalny i Kawowy (Shelly)", Index: 31
2020-04-25 13:49:56.121 Status: dzVents: Debug: Constructed timed-command: On
2020-04-25 13:49:56.122 Status: dzVents: Debug: Constructed timed-command: On AFTER 5 SECONDS
2020-04-25 13:49:56.122 Status: dzVents: Info: ------ Finished Script #1
2020-04-25 13:49:56.122 Status: dzVents: Debug: Commands sent to Domoticz:
2020-04-25 13:49:56.122 Status: dzVents: Debug: - Salon Zasilanie Stolik Jadalny i Kawowy = On AFTER 5 SECONDS
2020-04-25 13:49:56.122 Status: dzVents: Debug: =====================================================
2020-04-25 13:49:56.123 Status: EventSystem: Script event triggered: /home/pi/domoticz/dzVents/runtime/dzVents.lua
2020-04-25 13:50:00.504 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2020-04-25 13:50:00.555 Status: dzVents: Debug: Event triggers:
2020-04-25 13:50:00.555 Status: dzVents: Debug: - Timer
2020-04-25 13:50:05.807 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2020-04-25 13:50:05.839 Status: dzVents: Debug: Processing device-adapter for Salon Zasilanie Stolik Jadalny i Kawowy: Switch device adapter
2020-04-25 13:50:05.839 Status: dzVents: Debug: dzVents version: 3.0.1
2020-04-25 13:50:05.839 Status: dzVents: Debug: Event triggers:
2020-04-25 13:50:05.839 Status: dzVents: Debug: - Device: Salon Zasilanie Stolik Jadalny i Kawowy
2020-04-25 13:50:05.869 Status: dzVents: Info: Handling events for: "Salon Zasilanie Stolik Jadalny i Kawowy", value: "On"
2020-04-25 13:50:05.869 Status: dzVents: Info: ------ Start internal script: Script #1: Device: "Salon Zasilanie Stolik Jadalny i Kawowy (Shelly)", Index: 31
2020-04-25 13:50:05.869 Status: dzVents: Debug: Constructed timed-command: Off
2020-04-25 13:50:05.869 Status: dzVents: Debug: Constructed timed-command: Off AFTER 5 SECONDS
2020-04-25 13:50:05.870 Status: dzVents: Info: ------ Finished Script #1
2020-04-25 13:50:05.870 Status: dzVents: Debug: Commands sent to Domoticz:
2020-04-25 13:50:05.870 Status: dzVents: Debug: - Salon Zasilanie Stolik Jadalny i Kawowy = Off AFTER 5 SECONDS
2020-04-25 13:50:05.870 Status: dzVents: Debug: =====================================================
2020-04-25 13:50:05.871 Status: EventSystem: Script event triggered: /home/pi/domoticz/dzVents/runtime/dzVents.lua
2020-04-25 13:50:11.055 Status: dzVents: Debug: Dumping domoticz data to /home/pi/domoticz/scripts/dzVents/domoticzData.lua
2020-04-25 13:50:11.087 Status: dzVents: Debug: Processing device-adapter for Salon Zasilanie Stolik Jadalny i Kawowy: Switch device adapter
2020-04-25 13:50:11.088 Status: dzVents: Debug: dzVents version: 3.0.1
2020-04-25 13:50:11.088 Status: dzVents: Debug: Event triggers:
2020-04-25 13:50:11.088 Status: dzVents: Debug: - Device: Salon Zasilanie Stolik Jadalny i Kawowy
2020-04-25 13:50:11.117 Status: dzVents: Info: Handling events for: "Salon Zasilanie Stolik Jadalny i Kawowy", value: "Off"
2020-04-25 13:50:11.118 Status: dzVents: Info: ------ Start internal script: Script #1: Device: "Salon Zasilanie Stolik Jadalny i Kawowy (Shelly)", Index: 31
2020-04-25 13:50:11.118 Status: dzVents: Debug: Constructed timed-command: On
2020-04-25 13:50:11.118 Status: dzVents: Debug: Constructed timed-command: On AFTER 5 SECONDS
2020-04-25 13:50:11.119 Status: dzVents: Info: ------ Finished Script #1
2020-04-25 13:50:11.119 Status: dzVents: Debug: Commands sent to Domoticz:
2020-04-25 13:50:11.119 Status: dzVents: Debug: - Salon Zasilanie Stolik Jadalny i Kawowy = On AFTER 5 SECONDS
2020-04-25 13:50:11.119 Status: dzVents: Debug: =====================================================
2020-04-25 13:50:11.119 Status: EventSystem: Script event triggered: /home/pi/domoticz/dzVents/runtime/dzVents.lua

As you can see from 13:49:49 to 13:49:56 we have about 6 seconds, but from 13:49:56 to 13:50:05 we have about 9 seocnds.

What else is happening on your system

For above test I completely off every scripts but leave one.
On Raspberry I have:
- Raspbian Buster
- Mosquitto Server
- Node.js
- Xiaomi Plugin - https://github.com/Maxmudjon/com.xiaomi-miio
- Zigbee2MQTT - https://github.com/Koenkk/zigbee2mqtt
- Domoticz 2020.1

On Domoticz I use:
- Shelly MQTT plugin - built in Domoticz
- Mi Light controler plugin - built in Domoticz
- YeeLight LED - built in Domoticz
- Dashticz (but I`m not using that) - https://github.com/Dashticz/dashticz
- Aurora Theme - https://github.com/flatsiedatsie/domoticz-aurora-theme
- Zigbee2MQTT plugin - https://github.com/stas-demydiuk/domoti ... qtt-plugin

What kind of storage do you use

GoodRAM 16 GB MicroSDHC Class 10 HC1

Thank you for your response.

[waaren]

As you can see from 13:49:49 to 13:49:56 we have about 6 seconds, but from 13:49:56 to 13:50:05 we have about 9 seocnds.

I tested this on two separate systems both with other scripts still active and with and without active full debug logging but cannot replicate these delays.
9 out of ten times the light switches in just over 5 seconds and the tenth time it is sill less then 6 seconds.
Could there be something else active on your system ?

[CzarnyLewis]

Could there be something else active on your system ?

Everything I wrote in the previous post about services and plugins.

Is there a place where I can find out what Domoticz is doing at the time?
Of course I can reinstall everything, run script and install one by one every service to find reason... but it`s only solution?

[waaren]

Is there a place where I can find out what Domoticz is doing at the time?

You could activate domoticz wide debug logging.

The domoticz logfile location and other settings are defined in /etc/init.d/domoticz.sh
the relevant settings are in set to the DAEMON_ARGS var.

with an editor of choice

Code: Select all

DAEMON_ARGS="$DAEMON_ARGS -log /var/log/domoticz.log" # or any other OS file 
DAEMON_ARGS="$DAEMON_ARGS -loglevel  normal,status,error, debug" # debug disabled for now 
#DAEMON_ARGS="$DAEMON_ARGS -loglevel  normal,status,error" # these loglevels will make it to the logfile
DAEMON_ARGS="$DAEMON_ARGS -debuglevel normal,hardware,received,webserver,eventsystem,python,thread_id"

Code: Select all

sudo systemctl daemon-reload
sudo service domoticz stop
sudo service domoticz start
sudo tail -f  /var/log/domoticz.log

The system and other logfiles can be found with sudo ls -lrt /var/log/*log

[CzarnyLewis]

I have disabled dzVents and run the Blockly script. The situation is the same.
In a word - dzVents is not guilty.

Where to look now?