Even faster response for shutterstop command possible? #10201

Bascht74 · 2020-12-20T10:18:19Z

Bascht74
Dec 20, 2020

the last commit fixed the delays / backward movements of shutterstop in lower positions.

The only thing that wonders me, now that we got the milliseconds ("Jammern auf hohem Niveau" / "Whining on a high level"):

Time 37 (.144) --> log says: act pos: 36000
at .218 --> shutterstop (what would be + 74 ms = act pos. 38000 (Time 39)
but it takes till .347 until the shutter logs the new stuff (Time 41) --> act pos: 40000 (.144 + 200ms = pos 36000 + 4000)

I don't know why it is not taking the time 39 or time 40 slot to process it ... (so that it reacts earlier)
There is also nothing in the log about time 38 - time 40...
So the position is of by 3000 ( = 150 ms)

If there is a cause for this (not checking / logging between Time 38 - 41) that can be optimized, the reaction to user inputs (e.g. push a button / remote button) would be a litte earlier (up to 150 ms)

Without understanding your code completely I right now think that might be because every 50ms only one shutter related code piece is executed. So it has to wait for the next slow until it will pickup the new stuff.
Could you get around it that way, that you trigger the position-check code right after you executed Shutter[i].target_position = Shutter[i].real_position;?

This way it would be as responsive as the shutteropen/-close commands (that take 50 ms to switch on the relay)...

But still, the way it is now ist a trillion better than before... Thx for that!

shutterstop:


10:43:30.144 SHT: time: 37, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 36000, next_stop 0, target: 628000,  max_vel_change 0, dir: 1
10:43:30.210 ADE: 6195236, 4473, [44758, -16336, 16536, -2520], [1773, 6, 654, -14]
10:43:30.213 ADE: U 6195236, C 4473, I 44758 + 0 = 44758, P 16336 + 0 = 16336
10:43:30.218 CMD: shutterstop
10:43:30.224 SRC: WebConsole from 192.168.175.172
10:43:30.227 CMD: Gruppe 0, Index 1, Befehl "SHUTTERSTOP", Daten ""
10:43:30.231 SHT: Stop moving 1: dir: 1
*** delay here ***
10:43:30.347 SHT: time: 41, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos  40000, next_stop 0, target: 38000,  max_vel_change 0, dir: 1
10:43:30.350 SHT: Stop Shutter 0. Switchmode 0
10:43:30.353 SRC: Shutter
10:43:30.355 SHT: Switched relay: 1 by Shutter
10:43:30.358 SHT: Shutter 1: source: Shutter, powerstate_local 0, ShutterGlobal.RelayCurrentMask 1, manual change 0
10:43:30.363 MQT: stat/tasmota_FB1089/RESULT = {"POWER1":"OFF"}
10:43:30.370 MQT: stat/tasmota_FB1089/POWER1 = OFF (beibehalten)
*** delay here ***
10:43:30.876 SHT: Shutter 1 Real 41000, Start 41000, Stop 38000, Dir 0, Delay 0, Rtc 2.10 [s], Freq 0, PWM 0
10:43:30.881 MQT: stat/tasmota_FB1089/SHUTTER1 = 1 (beibehalten)
10:43:30.886 MQT: stat/tasmota_FB1089/RESULT = {"Shutter1":{"Position":1,"Direction":0,"Target":1}}
10:43:30.983 CFG: in Flash gespeichert am F8, zählen 662, Bytes 4096

shutteropen/close:

11:06:27.072 CMD: shutteropen
11:06:27.077 SRC: WebConsole from 192.168.175.172
11:06:27.080 CMD: Gruppe 0, Index 1, Befehl "SHUTTEROPEN", Daten ""
11:06:27.084 SHT: Pos. in: payload  (0), payload 100, idx 1, src 7
11:06:27.086 SHT: lastsource 7:, real 41000, target 608000, payload 100
11:06:27.089 SHT: Delay Start. var0 <99>=<>, max10s?
11:06:27.107 SHT: Delay Start. Done
11:06:27.110 SRC: Shutter
11:06:27.112 SHT: Switched relay: 1 by Shutter
11:06:27.115 SHT: Shutter 1: source: Shutter, powerstate_local 1, ShutterGlobal.RelayCurrentMask 1, manual change 0
11:06:27.121 MQT: stat/tasmota_FB1089/RESULT = {"POWER1":"ON"}
11:06:27.128 MQT: stat/tasmota_FB1089/POWER1 = ON (beibehalten)
11:06:27.134 MQT: stat/tasmota_FB1089/RESULT = {"ShutterOpen1":100}
*** delay here ***
11:06:28.431 SHT: time: 27, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 67000, next_stop 0, target: 628000,  max_vel_change 0, dir: 1

Do you know what is causing these delays and how to get rid of it?
I would probably make the shutters as responsive as in the original Shelly integration.

Sebastian

arendst · 2020-12-20T10:33:07Z

arendst
Dec 20, 2020
Maintainer

Does it make any difference if you turn of syslog and mqqtlog?

1 reply

Bascht74 Dec 20, 2020
Author

both are of, as I can see:

16:16:54.778 CMD: mqttlog
16:16:54.785 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"MqttLog":0}
16:17:03.497 CMD: syslog
16:17:03.504 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"SysLog":{"0":{"Active":"0"}}}

Test again:

16:20:03.619 CMD: weblog 4
16:20:03.626 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"WebLog":4}
16:20:03.999 ADE: 6060775, 4473, [1773, -8, 640, 39], [1773, 7, 640, 29]
16:20:03.002 ADE: U 6060775, C 4473, I 0 + 0 = 0, P 0 + 0 = 0
16:20:04.248 CFG: in Flash gespeichert am F6, zählen 778, Bytes 4096
16:20:04.995 ADE: 6062966, 4474, [1773, 43, 640, 56], [1773, -1, 640, -19]
16:20:04.998 ADE: U 6062966, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:20:05.994 ADE: 6060725, 4475, [1773, 14, 640, 32], [1773, -4, 640, 10]
16:20:05.997 ADE: U 6060725, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:20:06.995 ADE: 6064328, 4474, [1773, -43, 640, 16], [1773, 11, 640, -30]
16:20:06.998 ADE: U 6064328, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:20:07.995 ADE: 6069688, 4474, [1773, 5, 640, 43], [1773, -14, 640, -28]
16:20:07.997 ADE: U 6069688, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:20:08.995 ADE: 6070373, 4474, [1773, -11, 640, 33], [1773, 1, 640, -22]
16:20:08.998 ADE: U 6070373, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:20:09.995 ADE: 6071789, 4474, [1773, 27, 641, 9], [1773, -16, 641, 12]
16:20:09.998 ADE: U 6071789, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:20:10.995 ADE: 6071748, 4474, [1773, -39, 641, -28], [1773, -16, 641, 17]
16:20:10.998 ADE: U 6071748, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:20:11.998 ADE: 6071385, 4474, [1773, -7, 641, 11], [1773, -4, 641, -5]
16:20:11.000 ADE: U 6071385, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:20:12.993 ADE: 6068484, 4475, [1773, -23, 640, 25], [1773, 14, 640, -19]
16:20:12.996 ADE: U 6068484, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:20:13.992 ADE: 6066149, 4475, [1773, -42, 640, 7], [1773, -6, 640, -14]
16:20:13.995 ADE: U 6066149, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:20:14.406 CMD: shutterclose
16:20:14.409 SRC: WebConsole from 192.168.175.203
16:20:14.412 CMD: Gruppe 0, Index 1, Befehl "SHUTTERCLOSE", Daten ""
16:20:14.416 SHT: Pos. in: payload  (0), payload 0, idx 1, src 7
16:20:14.418 SHT: lastsource 7:, real 608000, target 0, payload 0
16:20:14.421 SHT: Delay Start. var0 <99>=<>, max10s?
16:20:14.435 SHT: Delay Start. Done
16:20:14.437 SRC: Shutter
16:20:14.440 SHT: Switched relay: 2 by Shutter
16:20:14.442 SHT: Shutter 1: source: Shutter, powerstate_local 2, ShutterGlobal.RelayCurrentMask 2, manual change 0
16:20:14.448 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"POWER2":"ON"}
16:20:14.452 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/POWER2 = ON (beibehalten)
16:20:14.456 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"ShutterClose1":0}
**** no log here... !?! ****
16:20:15.032 SHT: time: 12, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 596142, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.083 SHT: time: 14, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 593986, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.134 SHT: time: 15, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 592908, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.187 SHT: time: 16, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 591830, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.239 SHT: time: 17, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 590752, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.291 SHT: time: 18, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 589674, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.295 SHT: Shutter 1 Real 589674, Start 608000, Stop -20000, Dir -1, Delay 0, Rtc 0.90 [s], Freq 0, PWM 0
16:20:15.301 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"Shutter1":{"Position":96,"Direction":-1,"Target":0}}
16:20:15.354 SHT: time: 19, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 588596, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.394 SHT: time: 20, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 587518, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.449 SHT: time: 21, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 586440, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.499 SHT: time: 22, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 585362, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.549 SHT: time: 23, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 584284, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.601 SHT: time: 24, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 583206, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:15.991 ADE: 6057983, 4476, [1773, -80, 639, 41], [45956, 15857, 16591, 4845]
16:20:15.994 ADE: U 6057983, C 4476, I 0 + 45956 = 45956, P 0 + 15857 = 15857
16:20:16.992 ADE: 6051478, 4475, [1773, -35, 638, 35], [45860, 15824, 16537, 4816]
16:20:16.995 ADE: U 6051478, C 4475, I 0 + 45860 = 45860, P 0 + 15824 = 15824
**** no log here... !?! ****
16:20:17.801 SHT: time: 68, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 535774, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:17.805 SHT: Shutter 1 Real 535774, Start 608000, Stop -20000, Dir -1, Delay 0, Rtc 3.40 [s], Freq 0, PWM 0
16:20:17.811 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"Shutter1":{"Position":83,"Direction":-1,"Target":0}}
16:20:17.986 SHT: time: 71, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 532540, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:20:17.999 ADE: 6054415, 4475, [1773, -5, 639, 41], [45874, 15844, 16550, 4758]
16:20:17.001 ADE: U 6054415, C 4475, I 0 + 45874 = 45874, P 0 + 15844 = 15844
16:20:18.010 CMD: shutterstop
16:20:18.012 SRC: WebConsole from 192.168.175.203
16:20:18.015 CMD: Gruppe 0, Index 1, Befehl "SHUTTERSTOP", Daten ""
16:20:18.019 SHT: Stop moving 1: dir: -1
16:20:18.025 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"ShutterStop":"Done"}
**** Delay here ****
16:20:18.586 SHT: time: 84, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 518526, next_stop 0, target: 531462,  max_vel_change 0, dir: -1
16:20:18.589 SHT: Stop Shutter 0. Switchmode 0
16:20:18.591 SRC: Shutter
16:20:18.594 SHT: Switched relay: 2 by Shutter
16:20:18.597 SHT: Shutter 1: source: Shutter, powerstate_local 0, ShutterGlobal.RelayCurrentMask 2, manual change 0
16:20:18.604 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"POWER2":"OFF"}
16:20:18.609 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/POWER2 = OFF (beibehalten)
16:20:18.988 ADE: 6069606, 4475, [1773, -49, 640, 36], [1773, 10, 640, 6]
16:20:18.991 ADE: U 6069606, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:20:19.116 SHT: Shutter 1 Real 518526, Start 518526, Stop 531462, Dir 0, Delay 0, Rtc 4.20 [s], Freq 0, PWM 0
16:20:19.121 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/SHUTTER1 = 79 (beibehalten)
16:20:19.126 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"Shutter1":{"Position":79,"Direction":0,"Target":82}}
16:20:19.215 CFG: in Flash gespeichert am F4, zählen 780, Bytes 4096
16:20:19.992 ADE: 6069313, 4475, [1773, 3, 640, -34], [1773, -46, 640, 4]
16:20:19.995 ADE: U 6069313, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:20:22.347 CMD: weblog 2
16:20:22.358 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"WebLog":2}

It looks like Stefans Code (ShutterUpdatePosition(void)) is sometimes "blocked" by something and not executed in every 50ms loop...

Tried with mqttlog 4 and syslog 4 (as well weblog 4):

16:30:04.628 CMD: syslog 4
16:30:04.635 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"SysLog":{"4":{"Active":"4"}}}
16:30:06.906 CMD: mqttlog 4
16:30:06.918 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"MqttLog":4}
16:30:14.992 ADE: 6060301, 4473, [1773, -33, 640, 22], [1773, 7, 640, -22]
16:30:14.994 ADE: U 6060301, C 4473, I 0 + 0 = 0, P 0 + 0 = 0
16:30:15.993 ADE: 6060051, 4474, [1773, 21, 640, 55], [1773, -7, 640, -3]
16:30:15.996 ADE: U 6060051, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:30:16.993 ADE: 6053904, 4473, [1773, 19, 639, 91], [1773, -2, 639, -19]
16:30:16.996 ADE: U 6053904, C 4473, I 0 + 0 = 0, P 0 + 0 = 0
16:30:17.035 CMD: weblog 4
16:30:17.038 SRC: WebConsole from 192.168.175.203
16:30:17.041 CMD: Gruppe 0, Index 1, Befehl "WEBLOG", Daten "4"
16:30:17.047 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"WebLog":4}
16:30:17.436 CFG: in Flash gespeichert am F8, zählen 784, Bytes 4096
16:30:17.993 ADE: 6052421, 4474, [1773, 44, 639, 69], [1773, 9, 639, 20]
16:30:17.996 ADE: U 6052421, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:30:18.966 CMD: shutterclose
16:30:18.969 SRC: WebConsole from 192.168.175.203
16:30:18.972 CMD: Gruppe 0, Index 1, Befehl "SHUTTERCLOSE", Daten ""
16:30:18.977 SHT: Pos. in: payload  (0), payload 0, idx 1, src 7
16:30:18.980 SHT: lastsource 7:, real 518526, target 0, payload 0
16:30:18.982 SHT: Delay Start. var0 <99>=<>, max10s?
16:30:18.994 ADE: 6051981, 4474, [1773, -40, 639, -30], [1773, -2, 639, -28]
16:30:18.996 ADE: U 6051981, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:30:19.014 SHT: Delay Start. Done
16:30:19.017 SRC: Shutter
16:30:19.020 SHT: Switched relay: 2 by Shutter
16:30:19.022 SHT: Shutter 1: source: Shutter, powerstate_local 2, ShutterGlobal.RelayCurrentMask 2, manual change 0
16:30:19.029 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"POWER2":"ON"}
16:30:19.034 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/POWER2 = ON (beibehalten)
16:30:19.040 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"ShutterClose1":0}
**** no log ? ****
16:30:19.737 SHT: time: 15, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 503434, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:19.789 SHT: time: 16, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 502356, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:19.840 SHT: time: 17, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 501278, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:19.892 SHT: time: 18, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 500200, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:19.943 SHT: time: 19, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 499122, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:19.992 ADE: 6040346, 4474, [1773, -102, 638, 100], [45968, 15792, 16543, 4931]
16:30:19.995 ADE: U 6040346, C 4474, I 0 + 45968 = 45968, P 0 + 15792 = 15792
16:30:20.010 SHT: time: 20, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 498044, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:20.066 SHT: time: 21, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 496966, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:20.117 SHT: time: 22, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 495888, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:20.169 SHT: time: 23, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 494810, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:20.220 SHT: time: 24, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 493732, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:20.272 SHT: time: 25, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 492654, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:20.323 SHT: time: 26, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 491576, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:20.643 SHT: Shutter 1 Real 484030, Start 518526, Stop -20000, Dir -1, Delay 0, Rtc 1.65 [s], Freq 0, PWM 0
16:30:20.648 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"Shutter1":{"Position":71,"Direction":-1,"Target":0}}
16:30:20.993 ADE: 6042100, 4473, [1773, -56, 638, 60], [45851, 15783, 16505, 4830]
16:30:20.996 ADE: U 6042100, C 4473, I 0 + 45851 = 45851, P 0 + 15783 = 15783
16:30:21.993 ADE: 6035991, 4465, [1773, 13, 637, 56], [45701, 15714, 16435, 4798]
16:30:21.996 ADE: U 6035991, C 4465, I 0 + 45701 = 45701, P 0 + 15714 = 15714
***** no log ? ****
16:30:22.564 SHT: time: 71, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 443066, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:22.612 SHT: Shutter 1 Real 441988, Start 518526, Stop -20000, Dir -1, Delay 0, Rtc 3.60 [s], Freq 0, PWM 0
16:30:22.616 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"Shutter1":{"Position":61,"Direction":-1,"Target":0}}
16:30:22.651 SHT: time: 73, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 440910, next_stop 0, target: -20000,  max_vel_change 0, dir: -1
16:30:22.696 CMD: shutterstop
16:30:22.699 SRC: WebConsole from 192.168.175.203
16:30:22.702 CMD: Gruppe 0, Index 1, Befehl "SHUTTERSTOP", Daten ""
16:30:22.706 SHT: Stop moving 1: dir: -1
16:30:22.710 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"ShutterStop":"Done"}
**** missing log? ****
16:30:37.257 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"PulseTime5":{"Set":0,"Remaining":0}}
16:30:56.914 CMD: weblog 2
16:30:56.926 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"WebLog":2}
16:31:45.871 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS2 = {"StatusFWR":{"Version":"9.2.0.1(tasmota)","BuildDateTime":"2020.12.18 15:51:10","Boot":31,"Core":"2_7_4_9","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8266EX","CR":"648/699"}}
16:31:45.991 ADE: 6032764, 4475, [1773, -91, 637, 68], [1773, -11, 637, 23]
16:31:45.994 ADE: U 6032764, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:31:46.106 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":4,"MqttLog":4,"SysLog":4,"LogHost":"","LogPort":514,"SSId":["Qar5tz09e589mn05a0",""],"TelePeriod":300,"Resolution":"558180F0","SetOption":["0000C02B","0A05C80001000600003C5A00000000000000","400000C1","00006000","00000000"]}}
16:31:46.321 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS4 = {"StatusMEM":{"ProgramSize":588,"Free":412,"Heap":17,"ProgramFlashSize":1024,"FlashSize":2048,"FlashChipId":"1540C8","FlashFrequency":40,"FlashMode":3,"Features":["00000407","8FDAC787","04368001","000000CF","010013C0","C000F981","00004004","00001000"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,16,18,19,20,21,22,24,26,27,29,30,35,37,45","Sensors":"1,2,3,4,5,6"}}
16:31:46.539 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS5 = {"StatusNET":{"Hostname":"Rollo.EG.Wohnzimmer.Terrasse","IPAddress":"192.168.175.42","Gateway":"192.168.175.1","Subnetmask":"255.255.255.0","DNSServer":"192.168.175.1","Mac":"68:C6:3A:FB:10:89","Webserver":2,"WifiConfig":4,"WifiPower":17.0}}
16:31:46.666 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS6 = {"StatusMQT":{"MqttHost":"192.168.175.214","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_FB1089","MqttUser":"mqtt","MqttCount":13,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30}}
16:31:46.678 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS7 = {"StatusTIM":{"UTC":"2020-12-20T15:31:46","Local":"2020-12-20T16:31:46","StartDST":"2020-03-29T02:00:00","EndDST":"2020-10-25T03:00:00","Timezone":"+01:00","Sunrise":"08:18","Sunset":"16:19"}}
16:31:46.685 MQT: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS9 = {"StatusPTH":{"PowerDelta":[0,0,0],"PowerLow":0,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0}}
16:31:46.696 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS10 = {"StatusSNS":{"Time":"2020-12-20T16:31:46.689","ANALOG":{"Temperature":54.9},"ENERGY":{"TotalStartTime":"2020-12-09T09:59:34","Total":0.002,"Yesterday":0.001,"Today":0.001,"Power":[0,0],"ApparentPower":[0,0],"ReactivePower":[0,0],"Factor":[0.00,0.00],"Frequency":0,"Voltage":0,"Current":[0.000,0.000]},"Shutter1":{"Position":24,"Direction":0,"Target":25},"TempUnit":"C"}}
16:31:46.705 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS11 = {"StatusSTS":{"Time":"2020-12-20T16:31:46.701","Uptime":"0T05:59:49","UptimeSec":21589,"Heap":21,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":297,"MqttCount":13,"POWER1":"OFF","POWER2":"OFF","Wifi":{"AP":1,"SSId":"Qar5tz09e589mn05a0","BSSId":"E0:63:DA:53:3C:3E","Channel":6,"RSSI":100,"Signal":-48,"LinkCount":6,"Downtime":"0T00:00:53"}}}
16:31:46.711 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/STATUS13 = {"StatusSHT":{"SHT0":{"Relay1":1,"Relay2":2,"Open":304,"Close":282,"50perc":65,"Delay":0,"Opt":"0100","Calib":[1830,425,4085,900,1000],"Mode":"0"}}}
16:31:46.976 MQT: Verbindungsversuch...
16:31:46.991 ADE: 6034979, 4476, [1773, -35, 637, 25], [1773, -13, 637, 5]
16:31:46.993 ADE: U 6034979, C 4476, I 0 + 0 = 0, P 0 + 0 = 0
16:31:47.202 MQT: Verbindung fehlgeschlagen aufgrund von 192.168.175.214:1883, rc -2. Wiederversuch in 10 s
16:31:47.991 ADE: 6033529, 4474, [1773, 26, 637, 20], [1773, -10, 637, -1]
16:31:47.994 ADE: U 6033529, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:31:48.991 ADE: 6034514, 4475, [1773, -24, 637, -4], [1773, -17, 637, 14]
16:31:48.993 ADE: U 6034514, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:31:49.991 ADE: 6038978, 4475, [1773, -69, 637, 13], [1773, -1, 637, -19]
16:31:49.994 ADE: U 6038978, C 4475, I 0 + 0 = 0, P 0 + 0 = 0
16:31:50.991 ADE: 6040249, 4474, [1773, -50, 637, 59], [1773, 15, 638, 10]
16:31:50.994 ADE: U 6040249, C 4474, I 0 + 0 = 0, P 0 + 0 = 0
16:31:51.912 CMD: weblog 2
16:31:51.922 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"WebLog":2}
16:31:57.189 CMD: mqttlog 0
16:31:57.199 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"MqttLog":0}
16:31:57.832 CMD: syslog 0
16:31:57.841 RSL: stat/Rollo.EG.Wohnzimmer.Terrasse/RESULT = {"SysLog":{"0":{"Active":"0"}}}

Sebastian

arendst · 2020-12-20T15:20:51Z

arendst
Dec 20, 2020
Maintainer

No. It will just add possible delays although they may be unnoticed too.

I'll backoff.

0 replies

stefanbode · 2020-12-21T16:00:33Z

stefanbode
Dec 21, 2020

The maximum time between shutterstop and the stop of the relay is 50ms. The average should be 25ms; assuming you set the shutterstop in the middle of the 25ms second interval. The only workaround could be to call the Calculation directly after setting the target to the real position. This is not a big deal and I will submit a change for it.

2 replies

Bascht74 Dec 21, 2020
Author

This is not a big deal and I will submit a change for it.
@stefanbode Yes, please! And Thanks! I would love to see if the delay changes.
Right now, it takes (somehow) more time, as you can see in the example below.
Maybe you could add last known act.pos to the following log line as well: 10:43:30.231 SHT: Stop moving 1: dir: 1, so that it would say 10:43:30.231 SHT: Stop moving 1: dir: 1, act.pos xxxxxxx

I don't understand why there is nothing been logged between SHT: time: 37 and SHT: time: 41, see example.


10:43:30.144 SHT: time: 37, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos 36000, next_stop 0, target: 628000,  max_vel_change 0, dir: 1
10:43:30.210 ADE: 6195236, 4473, [44758, -16336, 16536, -2520], [1773, 6, 654, -14]
10:43:30.213 ADE: U 6195236, C 4473, I 44758 + 0 = 44758, P 16336 + 0 = 16336
10:43:30.218 CMD: shutterstop
10:43:30.224 SRC: WebConsole from 192.168.175.172
10:43:30.227 CMD: Gruppe 0, Index 1, Befehl "SHUTTERSTOP", Daten ""
10:43:30.231 SHT: Stop moving 1: dir: 1
*** delay 100 ms here *** 
10:43:30.347 SHT: time: 41, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms 0, act.pos  40000, next_stop 0, target: 38000,  max_vel_change 0, dir: 1
10:43:30.350 SHT: Stop Shutter 0. Switchmode 0
10:43:30.353 SRC: Shutter
10:43:30.355 SHT: Switched relay: 1 by Shutter
10:43:30.358 SHT: Shutter 1: source: Shutter, powerstate_local 0, ShutterGlobal.RelayCurrentMask 1, manual change 0
10:43:30.363 MQT: stat/tasmota_FB1089/RESULT = {"POWER1":"OFF"}
10:43:30.370 MQT: stat/tasmota_FB1089/POWER1 = OFF (beibehalten)
*** delay here ***
10:43:30.876 SHT: Shutter 1 Real 41000, Start 41000, Stop 38000, Dir 0, Delay 0, Rtc 2.10 [s], Freq 0, PWM 0
10:43:30.881 MQT: stat/tasmota_FB1089/SHUTTER1 = 1 (beibehalten)
10:43:30.886 MQT: stat/tasmota_FB1089/RESULT = {"Shutter1":{"Position":1,"Direction":0,"Target":1}}
10:43:30.983 CFG: in Flash gespeichert am F8, zählen 662, Bytes 4096

Bascht74 Dec 24, 2020
Author

Thank & Merry Chrismas!

I am already quite curious about weather that patch makes it even more responsive...

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Even faster response for shutterstop command possible? #10201

{{title}}

Replies: 3 comments 3 replies

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

Even faster response for shutterstop command possible? #10201

Bascht74 Dec 20, 2020

Replies: 3 comments · 3 replies

arendst Dec 20, 2020 Maintainer

Bascht74 Dec 20, 2020 Author

arendst Dec 20, 2020 Maintainer

stefanbode Dec 21, 2020

Bascht74 Dec 21, 2020 Author

Bascht74 Dec 24, 2020 Author

Bascht74
Dec 20, 2020

Replies: 3 comments 3 replies

arendst
Dec 20, 2020
Maintainer

Bascht74 Dec 20, 2020
Author

arendst
Dec 20, 2020
Maintainer

stefanbode
Dec 21, 2020

Bascht74 Dec 21, 2020
Author

Bascht74 Dec 24, 2020
Author