Unexpected system time behaviour

[AlexTZA]

Hardware:

Board: Custom ESP32 board and ESP32 WROVER Kit
Core Installation version: 1.0.1
IDE name: Arduino IDE or Visual Studio/vMicro
Flash Frequency: 80Mhz
PSRAM enabled: yes
Upload Speed: 921600
Computer OS: Windows 10

Description:

I have run into some strange behaviour when attempting to get/set the ESP system time using the settimeofday/gettimeofday methods. The main issue is that if the timeofday is set and immediately read back, sometimes the set/read values are not the same or within an expected deviation of one another. This however, only occurs under certain circumstances which I have managed to replicated in the example below. However, uncommenting the marked code "fixes" the issue, at least on two PC's and three different pieces of hardware based on the ESP32 WROVER. Can anyone else reproduce this issue?

Sketch: (leave the backquotes for code formatting)

/*
  ESP8266 mDNS-SD responder and query sample

  This is an example of announcing and finding services.
  
  Instructions:
  - Update WiFi SSID and password as necessary.
  - Flash the sketch to two ESP8266 boards
  - The last one powered on should now find the other.
 */

#include <WiFi.h>
#include <ESPmDNS.h>
#include "time.h"

const char* ssid     = "ssid";
const char* password = "pwd";


void PrintTime()
{
  timeval tVal;
  tVal.tv_sec = 1000;

  settimeofday(&tVal, NULL);

  timeval b;
  gettimeofday(&b, NULL);

  Serial.printf("System time set = %d, System time read = %d\r\n", tVal.tv_sec, b.tv_sec);

  if (tVal.tv_sec != b.tv_sec)
  {
    Serial.printf("***** Unexpected time difference! ******\r\n");
  }  
}

void setup() 
{
  Serial.begin(115200);
  
  PrintTime();

  Serial.print("Connecting to Wifi");
    WiFi.begin(ssid, password);
    while (WiFi.status() != WL_CONNECTED) 
  {
        delay(250);
        Serial.print(".");
    }

    //***Uncommenting the following lines "fixes" the PrintTime method???*****
    //Serial.println("");
    //Serial.print("Connected to ");
    //Serial.println(ssid);
    //Serial.print("IP address: ");
    //Serial.print("IP address: ");
    //Serial.println(WiFi.localIP());

    //if (!MDNS.begin("ESP32_Browser")) {
    //    Serial.println("Error setting up MDNS responder!");
    //    while(1){
    //       delay(1000);
    //  }
    //}
    //*********
}

void loop() 
{
  //Serial.printf("RAM >> Total Heap[%d], Free Heap[%d], Free PSRAM[%d]\r\n", ESP.getHeapSize(), ESP.getFreeHeap(), ESP.getFreePsram());

  delay(1000);
  
  PrintTime(); 

  //browseService("http", "tcp");
  //delay(1000);
  //browseService("arduino", "tcp");
  //delay(1000);
  //browseService("workstation", "tcp");
  //delay(1000);
  //browseService("smb", "tcp");
  //delay(1000);
  //browseService("afpovertcp", "tcp");
  //delay(1000);
  //browseService("ftp", "tcp");
  //delay(1000);
  //browseService("ipp", "tcp");
  //delay(1000);
  //browseService("printer", "tcp");
  //delay(10000);
}

void browseService(const char * service, const char * proto){
    Serial.printf("Browsing for service _%s._%s.local. ... ", service, proto);
  //the queryService call seems to leak RAM
    int n = MDNS.queryService(service, proto);
    if (n == 0) {
        Serial.println("no services found");
    } else {
        Serial.print(n);
        Serial.println(" service(s) found");
        for (int i = 0; i < n; ++i) {
            // Print details for each service found
            Serial.print("  ");
            Serial.print(i + 1);
            Serial.print(": ");
            Serial.print(MDNS.hostname(i));
            Serial.print(" (");
            Serial.print(MDNS.IP(i));
            Serial.print(":");
            Serial.print(MDNS.port(i));
            Serial.println(")");
        }
    }
    Serial.println();
}

Debug Messages:

ets Jun  8 2016 00:22:57
08:42:32.686 -> 
08:42:32.686 -> rst:0x10 (RTCWDT_RTC_RESET),boot:0x3e (SPI_FAST_FLASH_BOOT)
08:42:32.686 -> configsip: 0, SPIWP:0xee
08:42:32.686 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
08:42:32.686 -> mode:DIO, clock div:1
08:42:32.686 -> load:0x3fff0018,len:4
08:42:32.686 -> load:0x3fff001c,len:1100
08:42:32.686 -> load:0x40078000,len:10088
08:42:32.686 -> load:0x40080400,len:6380
08:42:32.686 -> entry 0x400806a4
[D][esp32-hal-psram.c:47] psramInit(): PSRAM enabled
System time set = 1000, System time read = 2074
08:42:34.387 -> ***** Unexpected time difference! ******
08:42:34.387 -> Connecting to Wifi[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 0 - WIFI_READY
08:42:34.489 -> [D][WiFiGeneric.cpp:342] _eventCallback(): Event: 2 - STA_START
...[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 4 - STA_CONNECTED
[D][WiFiGeneric.cpp:342] _eventCallback(): Event: 7 - STA_GOT_IP
08:42:35.476 -> [D][WiFiGeneric.cpp:385] _eventCallback(): STA IP: 192.168.0.87, MASK: 255.255.255.0, GW: 192.168.0.1
.System time set = 1000, System time read = 2073
08:42:36.494 -> ***** Unexpected time difference! ******
System time set = 1000, System time read = 2073
08:42:37.488 -> ***** Unexpected time difference! ******
System time set = 1000, System time read = 2073
08:42:38.504 -> ***** Unexpected time difference! ******
System time set = 1000, System time read = 2073
08:42:39.487 -> ***** Unexpected time difference! ******
System time set = 1000, System time read = 2073
08:42:40.514 -> ***** Unexpected time difference! ******
System time set = 1000, System time read = 2073
08:42:41.497 -> ***** Unexpected time difference! ******
System time set = 1000, System time read = 2073

...etc

[lbernstone]

I confirm this as very weird behavior. Unfortunately, settimeofday is an external function, so we can't do much about it here. It seems to be a timing thing, not related to WiFi/mDNS. PrintTime works at the very top of loop, but if you move it to the end of loop, it adds on the 1073 secs. At least it is consistent so you can work around it.

#include "sys/time.h"

uint32_t counter;

void PrintTime() {
  timeval tVal;
  tVal.tv_sec = 1E+6;
  if (counter<2) settimeofday(&tVal, NULL);
  counter++;
  timeval b;
  gettimeofday(&b, NULL);
  Serial.printf("System time: %d\n", b.tv_sec);
}

void setup() {
  Serial.begin(115200);
  PrintTime();
}

void loop() {
  PrintTime();
  delay(1000);
//  PrintTime();
}

[visicon-masc]

I can confirm this behavior still exist in 2021.

Environment:
PLATFORM: Espressif 32 (3.3.2)
PACKAGES:

• framework-arduinoespressif32 3.10006.210326 (1.0.6)
• tool-esptoolpy 1.30100.210531 (3.1.0)
• tool-mkspiffs 2.230.0 (2.30)
• toolchain-xtensa32 2.50200.97 (5.2.0)

Behavior: settimeofday adds "sometimes" 1073 seconds.

[VojtechBartoska]

@visicon-masc Can you please try it with the latest 2.0.1 release? Thanks!

[visicon-masc]

@VojtechBartoska Thanks for your fast reply.
I'd love to switch to the new 2.0.1 release, but I think it is not that easy. I'm using platformio as IDE. https://github.com/platformio/platform-espressif32/issues/619 tells me, that there are still flaws. I updated PLATFORM to Espressif 32 (3.4.0), but this does not change behaviour.

I would like to add more info:
Most of the time the difference between settimeofday and gettimeofday is 1164.
I've tried to delay, yield or lot of printf between settimeofday and gettimeofday, but the just get worse: sometimes gettimeofday alters tv_get.tv_sec to 0. I'm clueless on this...

I will have to give the 2.0.1 release a shot...

[VojtechBartoska]

@visicon-masc You are right, 2.0.1 version is not yet supported by PlatformIO. Thanks that you will find your way around and give it a shot with different IDE e.g.

[visicon-masc]

There where a few things a had to change to get the new release compiling...

I started with this to get it working with platformio ide.

Changes I had to do:

• .platformio\packages\toolchain-xtensa-esp32\xtensa-esp32-elf\include\c++\8.4.0\bits\locale_facets_nonio.tcc:773:21: error: #if with no expression
  -> change #if to #ifdef

• With
  platform = https://github.com/platformio/platform-espressif32.git#feature/arduino-idf-master
  it does not build I get:
  Linking .pio\build\esp32dev_main_ref1\firmware.elf c:/users/masc/.platformio/packages/toolchain-xtensa32/bin/../lib/gcc/xtensa-esp32-elf/8.4.0/../../../../xtensa-esp32-elf/bin/ld.exe: final link failed: bad value collect2.exe: error: ld returned 1 exit status *** [.pio\build\esp32dev_main_ref1\firmware.elf] Error 1

This compiles now:
platform = https://github.com/platformio/platform-espressif32.git#feature/arduino-upstream platform_packages = framework-arduinoespressif32 @ https://github.com/tasmota/arduino-esp32/releases/download/2.0.1/framework-arduinoespressif32-release_IDF4.4.tar.gz platformio/tool-esptoolpy @ https://github.com/tasmota/esptool/releases/download/v3.2/esptool-v3.2.zip

(btw: also I had to enable exceptions, and also get the newest stuff from https://github.com/me-no-dev/ESPAsyncWebServer.git to make my project build).

BUT: still no good.
Perhaps 1 in 10 attempts to settimeoftheday works. Most of the time gettimeofday is 1073 (sometimes 1075) seconds off.

Workaround i tried: calc diff between the time I wanted to set and gettimeofday and do a settimeofday again with the calculated offset: even worse, because after the second settimeofday gettimeofday reads garbage. Sometimes 0, sometimes big negative numbers...

What is going on here? No one else having problems setting the time?

Thanks again for all ideas and hints.

Bye Marc.

[visicon-masc]

Hi everyone!

Any news on this? This issue is unfortunately unresolved for me, since i can't find a reliable way to workaround. Anyone else?
How can I help? Using latest platform didn't helped.
@VojtechBartoska and @AlexTZA perhaps this issue should be reopened?

Thanks to everyone helping!

Bye, Marc.

[visicon-masc]

Hi again!

I have now a reliably working workaround: settimeofday in a task just created for this.

Like this:

void task_settime(void *parameter)
{
    static timeval tv_get;
    String msg;
    char buf[64];

#if DEBUG_TIME
    log_d("tv_set.tv_sec (set): %ld", ((timeval *)parameter)->tv_sec);
#endif

    settimeofday((timeval *)parameter, NULL); // set system time

    is_time_set = true;

    gettimeofday(&tv_get, NULL);

    int iDiff = tv_get.tv_sec - ((timeval *)parameter)->tv_sec;

#if DEBUG_TIME
    log_d("tv_get.tv_sec (get): %ld, diff: %d", tv_get.tv_sec, iDiff);
#endif

    strftime(buf, sizeof(buf), "%Y%m%d-%H:%M:%S", gmtime(&tv_get.tv_sec));

    msg = "setTime " + String(buf);
    parser_send_answer(&msg);

    vTaskDelete(NULL);
}

That this works indicates, that accessing vars by settimeofday is disturbed by task context switch?

Edit: even with platform = espressif32