Shutters Timing #10366

Bascht74 · 2021-01-02T13:57:39Z

Bascht74
Jan 2, 2021

As I am trying to find out what it happening with the one shutter (stat constantly), I compared logs / values from another shutter.

I have some findings that I want to share with you (weblog 4):

After the command shutteropen is executed, there is always a aprr. 1,5s delay before the first position log comes in:

12:06:44.563 CMD: shutteropen
12:06:44.565 SRC: WebConsole from   192.168.175.172
12:06:44.568 CMD: Gruppe 0, Index 1,   Befehl "SHUTTEROPEN", Daten ""
12:06:44.572 SHT: Pos. in: payload  (0), payload 100, idx 1, src 7
12:06:44.574 SHT: lastsource 7:, real 0,   target 246000, payload 100
12:06:44.576 SHT: Delay Start. var0   <99>=<>, max10s?
12:06:44.592 SHT: Delay Start. Done
12:06:44.594 SRC: Shutter
12:06:44.597 SHT: Switched relay: 1 by   Shutter
12:06:44.599 SHT: Shutter 1: source:   Shutter, powerstate_local 1, ShutterGlobal.RelayCurrentMask 1, manual change   0
12:06:44.603 RSL: RESULT =   {"POWER1":"ON"}
12:06:44.606 RSL: POWER1 = ON
12:06:44.609 RSL: RESULT =   {"ShutterOpen1":100}
... delay here about 1,5 s, why?
12:06:46.124 SHT: time: 31, toBeAcc 0,   current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms   0, act.pos 30000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
12:06:46.128 SHT: Shutter 1 Real 30000,   Start 0, Stop 266000, Dir 1, Delay 0, Rtc 1.55 [s], Freq 0, PWM 0
12:06:46.132 RSL: RESULT =   {"Shutter1":{"Position":12,"Direction":1,"Target":100}}
12:06:46.189 SHT: time: 32, toBeAcc 0,   current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms   0, act.pos 31000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
12:06:46.225 SHT: time: 33, toBeAcc 0,   current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms   0, act.pos 32000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1

Do you know the cause of that?
I don't know if this is normal or should be fixed...

I see jumps in the log, and I don't know what is causing it:

Mostly they are big jumps like this (those happen from time to time) :

These about 1,5s "gaps", every 2,5 s:

03:18:20.859 SRC:   Shutter
...
03:18:23.344 SHT: time: 50,   toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000,   min_runtime_ms 0, act.pos 49000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
-> gap here, appr. 2.5s after start (23.344 - 20.859 = 2,485s), duration 1,616s (24,960 - 23,344)
03:18:24.960 SHT: time: 83,   toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000,   min_runtime_ms 0, act.pos 82000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
… 
03:18:25.853 SHT: time: 101,   toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000,   min_runtime_ms 0, act.pos 100000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
gap here -->  (25.853 - 23.344 = 2,509s)
03:18:27.440 SHT: time: 132,   toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000,   min_runtime_ms 0, act.pos 131000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
...
03:18:28.341 SHT: time: 150,   toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000,   min_runtime_ms 0, act.pos 149000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
gap here
03:18:30.061 SHT: time: 185,   toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000,   min_runtime_ms 0, act.pos 184000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
... 
03:18:30.967 SHT: time: 203, toBeAcc 0,   current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms   0, act.pos 202000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
gap here
03:18:32.607 SHT: time: 236, toBeAcc 0,   current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms   0, act.pos 235000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1

Funny thing is, that these gaps have almost the same duration as the first gap (first gap: 1-31 missing (=30), here: 50 - 84 (34) / 101 - 131 (30) missing). 

So from time to time SHT is logging nothing for about 1,5 s.

At the interface of you code I see:

     case FUNC_EVERY_50_MSECOND:
        ShutterUpdatePosition();
        break;

I know, that the positioning code is executed, bit why is the log somehow missing

At the end there is a delay of almost 500 ms:

12:06:57.883 SHT:   time: 266, toBeAcc 0, current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change   1000, min_runtime_ms 0, act.pos 265000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
12:06:57.934 SHT: time: 267, toBeAcc 0,   current_stop_way 0,vel_cur 0, vel_max 0, act_vel_change 1000, min_runtime_ms   0, act.pos 266000, next_stop 0, target: 266000,  max_vel_change 0, dir: 1
12:06:57.937 SHT: Stop Shutter 0.   Switchmode 0
12:06:57.939 SRC: Shutter
12:06:57.941 SHT: Switched relay: 1 by   Shutter
12:06:57.944 SHT: Shutter 1: source:   Shutter, powerstate_local 0, ShutterGlobal.RelayCurrentMask 1, manual change   0
12:06:57.948 RSL: RESULT =   {"POWER1":"OFF"}
12:06:57.951 RSL: POWER1 = OFF
--> Delay here 0,5 s
12:06:58.455 SHT: Shutter 1 Real 246000,   Start 246000, Stop 246000, Dir 0, Delay 0, Rtc 13.35 [s], Freq 0, PWM 0
12:06:58.458 RSL: SHUTTER1 = 100
12:06:58.462 RSL: RESULT =   {"Shutter1":{"Position":100,"Direction":0,"Target":100}}

I don't know exactly where that delay comes from...

But maybe it would be a good idea to call maybe ShutterUpdatePosition() and ShutterReportPosition(false, MAX_SHUTTERS) at the end of ShutterPowerOff() so the position and report is done right away.

Sebastian

Answered by Bascht74

Jan 2, 2021

I just added a simple
AddLog_P(LOG_LEVEL_INFO, PSTR("DEBUG: my_activity >= TasmotaGlobal.sleep %d"), my_activity);

  uint32_t my_activity = millis() - my_sleep;

  if (Settings.flag3.sleep_normal) {               // SetOption60 - Enable normal sleep instead of dynamic sleep
    //yield();                                   // yield == delay(0), delay contains yield, auto yield in loop
    SleepDelay(TasmotaGlobal.sleep);                            // https://github.com/esp8266/Arduino/issues/2021
  } else {
    if (my_activity < (uint32_t)TasmotaGlobal.sleep) {
      SleepDelay((uint32_t)TasmotaGlobal.sleep - my_activity);  // Provide time for background tasks like wifi
    } else {
      …

View full answer

Bascht74 · 2021-01-02T18:10:46Z

Bascht74
Jan 2, 2021
Author

About No. 3:

I added a line in the mail loop to see if the activity_time is bigger than the configured sleep time, and yes, it is.
Every about 2.5s the main loop takes more than 50 ms...
(I added the time difference in Excel)

19:04:09.621 SLEEP: my_activity >= TasmotaGlobal.sleep | 9,621 | 0,427
19:04:11.681 SLEEP: my_activity >= TasmotaGlobal.sleep | 11,681 | 2,060
19:04:14.631 SLEEP: my_activity >= TasmotaGlobal.sleep | 14,631 | 2,950
19:04:17.091 SLEEP: my_activity >= TasmotaGlobal.sleep | 17,091 | 2,460
19:04:19.537 SLEEP: my_activity >= TasmotaGlobal.sleep | 19,537 | 2,446
19:04:21.997 SLEEP: my_activity >= TasmotaGlobal.sleep | 21,997 | 2,460
19:04:24.475 SLEEP: my_activity >= TasmotaGlobal.sleep | 24,475 | 2,478
19:04:26.991 SLEEP: my_activity >= TasmotaGlobal.sleep | 26,991 | 2,516
19:04:29.451 SLEEP: my_activity >= TasmotaGlobal.sleep | 29,451 | 2,460
19:04:31.897 SLEEP: my_activity >= TasmotaGlobal.sleep | 31,897 | 2,446
19:04:34.356 SLEEP: my_activity >= TasmotaGlobal.sleep | 34,356 | 2,459
19:04:36.480 SLEEP: my_activity >= TasmotaGlobal.sleep | 36,480 | 2,124
19:04:37.072 SLEEP: my_activity >= TasmotaGlobal.sleep | 37,072 | 0,592
19:04:39.851 SLEEP: my_activity >= TasmotaGlobal.sleep | 39,851 | 2,779
19:04:42.315 SLEEP: my_activity >= TasmotaGlobal.sleep | 42,315 | 2,464
19:04:45.075 SLEEP: my_activity >= TasmotaGlobal.sleep | 45,075 | 2,760
19:04:47.808 SLEEP: my_activity >= TasmotaGlobal.sleep | 47,808 | 2,733
19:04:50.297 SLEEP: my_activity >= TasmotaGlobal.sleep | 50,297 | 2,489
19:04:53.432 SLEEP: my_activity >= TasmotaGlobal.sleep | 53,432 | 3,135
19:04:56.068 SLEEP: my_activity >= TasmotaGlobal.sleep | 56,068 | 2,636
19:04:58.839 SLEEP: my_activity >= TasmotaGlobal.sleep | 58,839 | 2,771
19:05:01.319 SLEEP: my_activity >= TasmotaGlobal.sleep | 1,319 | 2,480
19:05:03.799 SLEEP: my_activity >= TasmotaGlobal.sleep | 3,799 | 2,480
19:05:06.284 SLEEP: my_activity >= TasmotaGlobal.sleep | 6,284 | 2,485
19:05:06.516 SLEEP: my_activity >= TasmotaGlobal.sleep | 6,516 | 0,232
19:05:08.984 SLEEP: my_activity >= TasmotaGlobal.sleep | 8,984 | 2,468
19:05:11.436 SLEEP: my_activity >= TasmotaGlobal.sleep | 11,436 | 2,452
19:05:13.924 SLEEP: my_activity >= TasmotaGlobal.sleep | 13,924 | 2,488
19:05:16.391 SLEEP: my_activity >= TasmotaGlobal.sleep | 16,391 | 2,467

0 replies

Bascht74 · 2021-01-02T18:39:54Z

Bascht74
Jan 2, 2021
Author

I just added a simple
AddLog_P(LOG_LEVEL_INFO, PSTR("DEBUG: my_activity >= TasmotaGlobal.sleep %d"), my_activity);

  uint32_t my_activity = millis() - my_sleep;

  if (Settings.flag3.sleep_normal) {               // SetOption60 - Enable normal sleep instead of dynamic sleep
    //yield();                                   // yield == delay(0), delay contains yield, auto yield in loop
    SleepDelay(TasmotaGlobal.sleep);                            // https://github.com/esp8266/Arduino/issues/2021
  } else {
    if (my_activity < (uint32_t)TasmotaGlobal.sleep) {
      SleepDelay((uint32_t)TasmotaGlobal.sleep - my_activity);  // Provide time for background tasks like wifi
    } else {
      AddLog_P(LOG_LEVEL_INFO, PSTR("DEBUG: my_activity >= TasmotaGlobal.sleep %d"), my_activity);
      
      if (TasmotaGlobal.global_state.network_down) {
        SleepDelay(my_activity /2);                // If wifi down and my_activity > setoption36 then force loop delay to 1/3 of my_activity period
      }
    }
  }

So I get:
19:41:56.586 DEBUG: my_activity >= TasmotaGlobal.sleep 113
19:41:59.642 DEBUG: my_activity >= TasmotaGlobal.sleep 145
19:42:02.626 DEBUG: my_activity >= TasmotaGlobal.sleep 119
19:42:05.547 DEBUG: my_activity >= TasmotaGlobal.sleep 90
19:42:08.590 DEBUG: my_activity >= TasmotaGlobal.sleep 74
19:42:11.589 DEBUG: my_activity >= TasmotaGlobal.sleep 87
19:42:14.586 DEBUG: my_activity >= TasmotaGlobal.sleep 86
19:42:17.573 DEBUG: my_activity >= TasmotaGlobal.sleep 76
19:42:20.622 DEBUG: my_activity >= TasmotaGlobal.sleep 76
19:42:23.623 DEBUG: my_activity >= TasmotaGlobal.sleep 92

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Shutters Timing #10366

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 2 comments

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Select a reply

Shutters Timing #10366

Bascht74 Jan 2, 2021

Replies: 2 comments

Bascht74 Jan 2, 2021 Author

Bascht74 Jan 2, 2021 Author

Bascht74
Jan 2, 2021

Bascht74
Jan 2, 2021
Author

Bascht74
Jan 2, 2021
Author