ESP32 - NTP inaccuracy after deep sleep

Question

I'm trying to create a sensor sampling project using ESP32 ( battery, solar panel and temperature affects are not part of test right now to reduce external effects that may cause/ increase such behaviour ).

In current phase, I'm only testing the sleep & waking up process.

A short description: System wakes up after deep sleep cycle, connects to Wifi, MQTT, NTP - and checks if wake up time ( wake up value is stored in ׳RTC_DATA_ATTR long calc_waketime׳ variable from previous cycle ), posting IFTTT, goes to deep sleep for another 10 min. cycle.

The phenomena I wish to share is: The longer deep sleep is the NTP has few seconds drift which gets longer (again - NTP sync has a drift and not RTC clock).

I'm aware that wake time/ RTC drifts during deep sleep ( especially in ESP8266 chips that wake up can be not accurate in terms of minute - I'm using ESP32). Since ESP32 uses RTC, waking up is very accurate ( matter of seconds ). In order to wake up in exact time ( 18:00, 18:10, 18:20... every hour ) code connects to Wifi& NTP, and verify that wake time was as intended (comparing the epoch value that was stored during the end of previous cycle and current epoch time ) if it woke up earlier, it will got to sleep for that missing time.

But - What puzzles me is why updated NTP time ( which is not related what so ever to RTC drifts ), is drifted the longer to sleep is ( for comparison : when less than a minute - almost no drift, when sleeping for 10 minutes, 3 seconds drift, 20 minutes get up to 5 seconds drifts ).

Please see NOTE(1) to witness the drift in 10 min sleep.

Posting terminal output: some explantions: NOTE (1) displays the 3 seconds drift , NOTE(2) calculated time that was stored at previous wake cycle, NOTE (3) shows that that drift get synced during the code run - 594 sec for next wake 18:50:00.

18:39:58.032 -> 09B⸮⸮L⸮1U1V(⸮⸮⸮1m1m1F⸮Connecting to Xiaomi_D6C8 .... // WAKING UP
18:39:58.595 -> 192.168.3.186
18:39:59.013 -> now is: 1580575203               **// NOTE (1)**
18:39:59.013 -> sleep time was: 1580574611
18:39:59.048 -> expected wake time: 1580575200   // NOTE (2)
18:39:59.085 -> total time delta: 3
18:39:59.122 -> OK - WOKE UP after due time: 
18:39:59.419 -> Attempting MQTT connection...connected
18:40:04.544 -> Connecting to maker.ifttt.com
18:40:04.855 -> Request resource: /trigger/send_reading/with/key/cFLymB4JT9tlODsKLFn9TA
18:40:05.376 -> HTTP/1.1 200 OK
18:40:05.376 -> Date: Sat, 01 Feb 2020 16:40:05 GMT
18:40:05.414 -> Content-Type: text/html; charset=utf-8
18:40:05.447 -> Content-Length: 52
18:40:05.480 -> Connection: close
18:40:05.515 -> X-Top-SecreTTT: VG9vIGVhc3k/IElmIHlvdSBjYW4gcmVhZCB0aGlzLCBFbWFpbCB1cyBhdCBqb2JzK3NlY3JldEBpZnR0dC5jb20uIFdlIHdhbnQgTWFrZXJzLg==
18:40:05.619 -> Server: web_server
18:40:05.619 -> 
18:40:05.619 -> Congratulations! You've fired the send_reading event
18:40:05.689 -> closing connection
18:40:07.007 -> Last Sleep: 1580574611
18:40:07.007 -> Time left: 594                 // NOTE (3)
18:40:07.041 -> Going to DeepSleep for [594] sec

Relevant code:

void sleepNOW(int sec2sleep = 2700)
{
  char tmsg[30];
  sprintf(tmsg, "Going to DeepSleep for [%d] sec", sec2sleep);
  Serial.println(tmsg);
  // mqtt_pubmsg(tmsg);
  Serial.flush();
  esp_sleep_enable_timer_wakeup(sec2sleep * uS_TO_S_FACTOR);
  esp_deep_sleep_start();
}
bool getTime()
{
  delay(200);
  if (getLocalTime(&timeinfo))
  {
    time(&now1);
    delay(200);
    return 1;
  }
  else
  {
    return 0;
  }
}

bool check_awake_ontime()
{
  getTime();
  if (timeinfo.tm_year >= 120) // year 2020
  {
    if (lastsleeptime != 0)
    { // not first boot
      long current_boottime = now1;
      int t_delta = now1 - calc_waketime;
      // int t_delta1 = TIME_TO_SLEEP * 60 - (t_delta + TIME_AWAKE);
      Serial.print("now is: ");
      Serial.println(now1);
      Serial.print("sleep time was: ");
      Serial.println(lastsleeptime);
      Serial.print("expected wake time: ");
      Serial.println(calc_waketime);

      Serial.print("total time delta: ");
      Serial.println(t_delta);
      if (t_delta >= 0)
      {
        Serial.println("OK - WOKE UP after due time: ");
        return 1;
      }
      else
      {
        Serial.println("FAIL- woke up before time: ");
        sleepNOW(-1 * t_delta);
        return 0;
      }
    }
    else
    {
      return 1;
    }
  }
  else
  {
    return 0;
  }
}

inside setup()

#if USE_WIFI
  if (startWifi())
  {
    mqttConnect();
    startNTP();
#if USE_SLEEP
    check_awake_ontime();   // PLEASE PAY ATTN ONLY THIS LINE 
#endif
  }

inside loop()

#if USE_SLEEP
  if (millis() >= TIME_AWAKE * 1000)
  {
    getTime();

    Serial.print("Last Sleep: ");
    Serial.println(lastsleeptime);

    long clockCount = TIME_TO_SLEEP * 60 - (timeinfo.tm_min * 60 + timeinfo.tm_sec) % (TIME_TO_SLEEP * 60);
    // Serial.print(timeinfo.tm_hour);
    // Serial.print(":");
    // Serial.print(timeinfo.tm_min);
    // Serial.print(":");
    // Serial.print(timeinfo.tm_sec);
    // Serial.println("");
    Serial.print("Time left: ");
    Serial.println(clockCount);

    lastsleeptime = now1;
    calc_waketime = now1 + clockCount;

    sleepNOW(clockCount);
  }

I'm not posting entire code, but only relevant parts. Appreciate any help,

Answer 1

As Juraj commented, a 2.5 [sec] delay, solved it, and NTP update was correct.