NTP sync takes much longer with 2.5.2-beta2 than with 2.4.2

[marcelstoer]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: ESP-12
• Core Version: 2.5.0-beta2
• Development Env: Arduino IDE
• Operating System: MacOS

Settings in IDE

• Module: WeMOS D1 mini Pro
• Flash Mode: [qio|dio|other]
• Flash Size: 4MB
• lwip Variant: v2 Lower Memory
• Reset Method: [ck|nodemcu]
• Flash Frequency: [40Mhz]
• CPU Frequency: 80Mhz
• Upload Using: SERIAL
• Upload Speed: 921600

Problem Description

NTP sync takes way too long (several seconds) with 2.5.2-beta2. With 2.4.2 it usually completes in a few 100ms.

MCVE Sketch

#include <Arduino.h>
#include <time.h>
#include <ESP8266WiFi.h>

#define WIFI_SSID "xxxxxxxx"
#define WIFI_PWD "xxxxxxxx"

// August 1st, 2018
#define NTP_MIN_VALID_EPOCH 1533081600
#define NTP_SYNC_TIMEOUT_SECONDS 5

boolean connectWifi() {
  wifi_set_opmode(STATION_MODE);
  wifi_station_connect();
  WiFi.persistent(false);

  if (WiFi.status() == WL_CONNECTED) return true;
  WiFi.begin(WIFI_SSID, WIFI_PWD);

  int i = 0;
  uint32_t startTime = millis();
  Serial.print("WiFi connect");
  while (WiFi.status() != WL_CONNECTED) {
    delay(300);
    i++;
    if (millis() - startTime > 20000) {
      Serial.println("\nFailed to connect to WiFi");
      return false;
    }
    Serial.print(".");
  }
  Serial.println(WiFi.localIP());
  return true;
}

bool initTime() {
  Serial.print("NTP sync");
  configTime(0, 0, "0.europe.pool.ntp.org", "1.europe.pool.ntp.org", "2.europe.pool.ntp.org");
  setenv("TZ", "CET-1CEST,M3.5.0,M10.5.0/3", 0);
  tzset();

  // wait until NTP time was correctly syncronized
  time_t now;
  uint32_t startTime = millis();
  uint16_t ntpTimeoutMillis = NTP_SYNC_TIMEOUT_SECONDS * 1000;
  while((now = time(nullptr)) < NTP_MIN_VALID_EPOCH) {
    uint32_t runtimeMillis = millis() - startTime;
    if (runtimeMillis > ntpTimeoutMillis) {
      Serial.printf("\nFailed to sync time through NTP. Giving up after %dms.\n", runtimeMillis);
      return false;
    }
    Serial.printf(".%d.", now);
    delay(300);
  }
  Serial.println();
  Serial.printf("Current time: %d\n", now);

  return true;
}

void setup() {
  Serial.begin(115200);
  Serial.println();
  if (connectWifi()) {
    if (initTime()) {
      Serial.println("Setup successfully completed");
    }
  }
}

void loop() {
  // put your main code here, to run repeatedly:
}

Debug Messages

With 2.5 I get something like this

WiFi connect.................192.168.0.50
NTP sync.28805..28805..28805..28806..28806..28806..28806..28807..28807..28807..28808..28808..28808..28809..28809..28809..28809.
Current time: 1546037682
Setup successfully completed

With 2.4.2 the NTP sync completes in no time

WiFi connect...........192.168.0.50
NTP sync.28803.
Current time: 1546039374
Setup successfully completed

[d-a-v]

fixed by #5567. Now It takes some 10th of ms.

[marcelstoer]

Woah, that was quick! Thanks David, you must obviously have known immediately which knob to turn.

[d-a-v]

you must obviously have known immediately which knob to turn.

I spent quite some time with lwIP, yes :)
But you found the "bug", that one might be called a feature elsewhere.
That change appeared between lwip-2.0.3 (core-2.4.2) and lwip-2.1.2 (now).

Woah, that was quick!

That's a lucky combination of availability, issue that rings a bell, mood, the will to preserve stability and coherency in this core, and 2.5.0-to-be-the-most-stable-possible approaching !