timing the "loop" Whats wrong?

Using Arduino Programming Questions
1

Hello everybody, I am trying to find the longest duration of my loop by timing each function and the loop itself with the code below

#define sp Serial.print
#define spln Serial.println
#define sp_ sp(F(" "))

void loop() {
  unsigned long int debut, fin, duree, loopStart, loopEnd;
  byte i=0;
  
  wdt_reset();
  loopStart=millis();

  debut=millis();  
  userInterrupt();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//0
  i++;
  
  //InetCheck();
  
  debut=millis();
  serve();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//1
  i++;
  
  debut=millis();
  timeAdjustment();  
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//2
  i++;
  
//anySensorInterrupt();////////////////////
  
  debut=millis();
  evaluateDensity();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//3
  i++;
  
  debut=millis();
  exceptionMgt();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//4
  i++;
  
  debut=millis();
  IPchangeCheck();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//5
  i++;
  
  debut=millis();
  rainServer();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//6
  i++;

  debut=millis();
  flowProcessor();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//7
  i++;

  debut=millis();
  checkReqTest();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//8
  i++;
 
  debut=millis();
  localAlarm();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//9
  i++;
  
  debut=millis();
  flipBoardLed();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//10
  i++;
  
  debut=millis();
  minuteClock();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//11
  i++;

  debut=millis();
  lanCheck();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//12
  i++;

  tenSecClock();

  debut=millis();
  managePresenceEmulator();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//13
  i++;

  debut=millis();
  cloudUpdate();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//14
  i++;

  debut=millis();
  newdayUpdates();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//15
  i++;

  debut=millis();
  emailException();
  fin=millis();
  duree=fin-debut;
  durations[i]=duree>durations[i]?duree:durations[i];//16
  i++;

  loopEnd=millis();
  duree=loopEnd-loopStart;
  durations[i]=duree>durations[i]?duree:durations[i];//17

}

the results are displayed every 2000 loops by

//flipBoardLed
void flipBoardLed() {
  const int COUNTER_MAX = 2000;
  static int counter = 0;
  counter++;
  if (counter==COUNTER_MAX) {
    counter=0;
    digitalWrite(BOARD_LED, !digitalRead(BOARD_LED));
  showDuration();
  }
}


void showDuration(){
  //unsigned long total=0;
  for(unsigned int i=0; i<18; i++){
    sp(i); sp_; sp(durations[i]); sp_;sp_;
  }
  spln();
}

Ran overnight and in the morning I found:

0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
05:25:20 actual flow= 0 Expected flow= 0 flow OK= true
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 3978 15 9 16 2846 17 6885
05:25:30 actual flow= 0 Expected flow= 0 flow OK= true
05:25:30 cloud-> posting to cloud
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9 16 2846 17 15030
05:25:50 actual flow= 0 Expected flow= 0 flow OK= true
0 2 1 5202 2 51 3 2 4 2 5 1289 6 25 7 8 8 2 9 2 10 32 11 15 12 4054 13 2 14 15029 15 9

Why hasn't the watchdog (~9") reset the machine at the second red result?

Thanks for your time

NB: If I add to cloudUpdate() the line

spln("long wait");activeWait(70000);

The machine restarts after few (thousand) iterations, the last one showing

0 2 1 2 2 2 3 2 4 2 5 423 6 26 7 2 8 2 9 2 10 26 11 15 12 1034 13 2 14 8543 15 2 16 184 17 8544
10:41:30 actual flow= 0 Expected flow= 0 flow OK= true
10:41:30 cloud-> posting to cloud
long wait
setup started

2

When did you actually enable the watchdog?

3

Thanks westfw

The watchdog is enabled before entering the "loop"

the flow is:

setup 1st part
ui
setup 2nd part
loop

in ui the watchdog is disabled
before exiting ui, either by a timeout or by the command 'go' the watchdog is enabled

code attached

arduino sw.zip (206 KB)

4

This did not happen again. It should be noted that since it worked overnight, the screen did NOT contain all the history from the program launch so that we may be missing something that explains the misbehavior. I can not imagine what this can be.