Esp32 ULP/RTC time drift

fededim · Postby **fededim** » Sat May 02, 2020 6:40 pm

Hi,

I have written a simple ULP program which takes BME280 I2C data and the sample time by querying the RTC registers and saves it into a buffer in RTC memory. After having collected 180 samples, it wakes up the ESP32 in order to copy these samples from RTC memory to SPIFFS. While copying the data I print all the sampled values and I see that sometimes the rtc timestamps skips a sample (the ULP program is scheduled to run every second, debug output is below, the drift happens at 17:52:38). I double checked all the time functions to record the data and to print the values and they seem to be correct (I attach them below). Has anybody experienced also this drift in its ULP code ? I strongly doubt that it's RTC drift since it happens only after 1:06 mins since last NTP synchronization.

ULP code to sample RTC value

Code: Select all

    
    
    move R2,sdata
    
    // READ RTC 48 bit counter
    WRITE_RTC_FIELD(RTC_CNTL_TIME_UPDATE_REG, RTC_CNTL_TIME_UPDATE, 1)
waitSampleRtc:
    READ_RTC_FIELD(RTC_CNTL_TIME_UPDATE_REG, RTC_CNTL_TIME_VALID)
    jumpr waitSampleRtc, 0, EQ
    READ_RTC_REG(RTC_CNTL_TIME1_REG, 0, 16)      //[47:32]
    st  R0,R2,0  // sdata[0]
    READ_RTC_REG(RTC_CNTL_TIME0_REG, 16, 16)     //[31:16]
    st  R0,R2,4*1  // sdata[1]
    READ_RTC_REG(RTC_CNTL_TIME0_REG, 0, 16)      //[15:0]
    st  R0,R2,4*2  // sdata[2]

C++ code to convert RTC raw value to printable text (parts borrowed from ESP-IDF framework)

Code: Select all

  uint32_t *sdata=&ulp_sdata;
  for (int i=0;i<MAX_BME280_SAMPLES;i++) {
    int offset=i*8;

    uint64_t rawTimestamp=(((uint64_t) (sdata[offset+0]&0xFFFF))<<32)|((sdata[offset+1]&0xFFFF)<<16)|(sdata[offset+2]&0xFFFF);
    // ntpSynchedTime is the number of seconds returned from a NTP, synched at the boot of ESP32 before starting the ulp program
    // rtcOffset is the RTC clock value just following the assignment of ntpSynchedTime variable.
    uint32_t timestamp=(ntpSynchedTime+get_rtc_time_us(rawTimestamp-rtcOffset)/1000000);
    // timestamp is printed with TimeToString below
  }


char *TimeToString(long timestamp) {
 
  struct tm *timeinfo = localtime(&timestamp);

  return asctime(timeinfo);
}


void DoNTPSynch() {
    SERDBG("Performing NTP query...");
    timeClient.begin();
    while (!timeClient.update()) {
      SERDBG("Could not get time from NTP, retrying...");
      delay(100);
    }  

    ntpSynchedTime=timeClient.getEpochTime();
    setUnixtime(ntpSynchedTime);
    rtcOffset=rtc_time_get();
    
    SERDBG("Successfully set time to %s\n",TimeToString(ntpSynchedTime));
}


static uint32_t esp_clk_slowclk_cal_get(void)
{
    return REG_READ(RTC_SLOW_CLK_CAL_REG);
}


static uint64_t get_rtc_time_us(uint64_t ticks)
{
    if (ticks==0)
      ticks = rtc_time_get();
    const uint32_t cal = esp_clk_slowclk_cal_get();
    /* RTC counter result is up to 2^48, calibration factor is up to 2^24,
     * for a 32kHz clock. We need to calculate (assuming no overflow):
     *   (ticks * cal) >> RTC_CLK_CAL_FRACT
     *
     * An overflow in the (ticks * cal) multiplication would cause time to
     * wrap around after approximately 13 days, which is probably not enough
     * for some applications.
     * Therefore multiplication is split into two terms, for the lower 32-bit
     * and the upper 16-bit parts of "ticks", i.e.:
     *   ((ticks_low + 2^32 * ticks_high) * cal) >> RTC_CLK_CAL_FRACT
     */
    const uint64_t ticks_low = ticks & UINT32_MAX;
    const uint64_t ticks_high = ticks >> 32;
    return ((ticks_low * cal) >> RTC_CLK_CAL_FRACT) +
           ((ticks_high * cal) << (32 - RTC_CLK_CAL_FRACT));
}

Debug output of the program

Code: Select all

19:51:29.483 -> ⸮ets Jun  8 2016 00:22:57
19:51:29.483 -> 
19:51:29.483 -> rst:0x1 (POWERON_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
19:51:29.854 -> ets Jun  8 2016 00:22:57
19:51:29.854 -> 
19:51:29.854 -> rst:0x10 (RTCWDT_RTC_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
19:51:29.854 -> configsip: 0, SPIWP:0xee
19:51:29.889 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
19:51:29.889 -> mode:DIO, clock div:1
19:51:29.889 -> load:0x3fff0018,len:4
19:51:29.889 -> load:0x3fff001c,len:1044
19:51:29.889 -> load:0x40078000,len:8896
19:51:29.889 -> load:0x40080400,len:5816
19:51:29.889 -> entry 0x400806ac
19:51:30.193 -> EspWeatherSensor starts...
19:51:30.193 -> Initing SPIFFS...
19:51:30.394 -> SPIFFS total 2757KB free 2485KB
19:51:30.394 -> ReadCalibrationData: Read i2c id 60
19:51:30.394 -> BME280 test read RawTemperature 7fc20 Val 22.995354
19:51:30.394 -> BME280 test read RawPressure 483b0 Val 1004.175415
19:51:30.394 -> BME280 test read RawHumidity 82fc Val 65.657318
19:51:30.394 -> BME280 CalibrationData
19:51:30.394 -> --------------
19:51:30.394 -> Dig[0]=eb
19:51:30.394 -> Dig[1]=6d
19:51:30.394 -> Dig[2]=1b
19:51:30.394 -> Dig[3]=67
19:51:30.394 -> Dig[4]=32
19:51:30.394 -> Dig[5]=0
19:51:30.394 -> Dig[6]=59
19:51:30.394 -> Dig[7]=96
19:51:30.394 -> Dig[8]=7
19:51:30.394 -> Dig[9]=d6
19:51:30.394 -> Dig[10]=d0
19:51:30.427 -> Dig[11]=b
19:51:30.427 -> Dig[12]=34
19:51:30.427 -> Dig[13]=20
19:51:30.427 -> Dig[14]=b3
19:51:30.427 -> Dig[15]=ff
19:51:30.427 -> Dig[16]=f9
19:51:30.427 -> Dig[17]=ff
19:51:30.427 -> Dig[18]=c
19:51:30.427 -> Dig[19]=30
19:51:30.427 -> Dig[20]=20
19:51:30.427 -> Dig[21]=d1
19:51:30.427 -> Dig[22]=88
19:51:30.427 -> Dig[23]=13
19:51:30.427 -> Dig[24]=0
19:51:30.427 -> Dig[25]=63
19:51:30.427 -> Dig[26]=1
19:51:30.427 -> Dig[27]=0
19:51:30.427 -> Dig[28]=15
19:51:30.427 -> Dig[29]=20
19:51:30.427 -> Dig[30]=3
19:51:30.427 -> Dig[31]=1e
19:51:30.427 -> Attempting to connect to WPA SSID: Telecom-2G
19:51:31.000 -> Status=3
19:51:31.000 -> Performing NTP query...
19:51:31.068 -> Successfully set time to Sat May  2 17:51:31 2020
19:51:31.068 -> 
19:51:31.068 -> init_run_ulp starts...
19:51:31.068 -> init_run_ulp ends
19:51:31.068 -> start_ulp_program starts...
19:51:31.068 -> start_ulp_program ends...
19:54:31.609 -> ets Jun  8 2016 00:22:57
19:54:31.609 -> 
19:54:31.609 -> rst:0x5 (DEEPSLEEP_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
19:54:31.609 -> configsip: 0, SPIWP:0xee
19:54:31.609 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
19:54:31.643 -> mode:DIO, clock div:1
19:54:31.643 -> load:0x3fff0018,len:4
19:54:31.643 -> load:0x3fff001c,len:1044
19:54:31.643 -> load:0x40078000,len:8896
19:54:31.643 -> load:0x40080400,len:5816
19:54:31.643 -> entry 0x400806ac
19:54:31.920 -> Deep sleep wakeup from ULP
19:54:31.920 -> SampleCount 180
19:54:31.920 -> AppendToSPIFFS starts Sat May  2 17:54:32 2020
19:54:31.920 -> 
19:54:31.920 -> Finished copying 180 samples from RTC memory
19:54:32.226 -> SPIWrite Sample 0 Time Sat May  2 17:51:31 2020
19:54:32.226 ->  T 22.995 H 65.663 P 1004.149
19:54:32.260 -> SPIWrite Sample 1 Time Sat May  2 17:51:32 2020
19:54:32.260 ->  T 23.010 H 66.199 P 1004.175
19:54:32.260 -> SPIWrite Sample 2 Time Sat May  2 17:51:33 2020
19:54:32.260 ->  T 23.005 H 66.237 P 1004.244
19:54:32.260 -> SPIWrite Sample 3 Time Sat May  2 17:51:34 2020
19:54:32.260 ->  T 23.010 H 65.901 P 1004.227
19:54:32.260 -> SPIWrite Sample 4 Time Sat May  2 17:51:35 2020
19:54:32.260 ->  T 23.005 H 65.879 P 1004.244
19:54:32.260 -> SPIWrite Sample 5 Time Sat May  2 17:51:36 2020
19:54:32.260 ->  T 23.010 H 66.419 P 1004.227
19:54:32.294 -> SPIWrite Sample 6 Time Sat May  2 17:51:37 2020
19:54:32.294 ->  T 23.000 H 66.138 P 1004.132
19:54:32.294 -> SPIWrite Sample 7 Time Sat May  2 17:51:38 2020
19:54:32.294 ->  T 23.010 H 66.105 P 1004.227
19:54:32.294 -> SPIWrite Sample 8 Time Sat May  2 17:51:39 2020
19:54:32.294 ->  T 23.010 H 65.995 P 1004.201
19:54:32.294 -> SPIWrite Sample 9 Time Sat May  2 17:51:40 2020
19:54:32.294 ->  T 23.010 H 66.127 P 1004.175
19:54:32.294 -> SPIWrite Sample 10 Time Sat May  2 17:51:41 2020
19:54:32.294 ->  T 23.000 H 65.922 P 1004.236
19:54:32.294 -> SPIWrite Sample 11 Time Sat May  2 17:51:42 2020
19:54:32.328 ->  T 23.000 H 66.016 P 1004.210
19:54:32.328 -> SPIWrite Sample 12 Time Sat May  2 17:51:43 2020
19:54:32.328 ->  T 23.000 H 65.939 P 1004.236
19:54:32.328 -> SPIWrite Sample 13 Time Sat May  2 17:51:44 2020
19:54:32.328 ->  T 22.990 H 65.696 P 1004.167
19:54:32.328 -> SPIWrite Sample 14 Time Sat May  2 17:51:45 2020
19:54:32.328 ->  T 23.000 H 65.867 P 1004.236
19:54:32.361 -> SPIWrite Sample 15 Time Sat May  2 17:51:46 2020
19:54:32.361 ->  T 23.005 H 65.774 P 1004.218
19:54:32.361 -> SPIWrite Sample 16 Time Sat May  2 17:51:47 2020
19:54:32.361 ->  T 23.000 H 65.939 P 1004.236
19:54:32.361 -> SPIWrite Sample 17 Time Sat May  2 17:51:48 2020
19:54:32.361 ->  T 23.000 H 65.663 P 1004.184
19:54:32.361 -> SPIWrite Sample 18 Time Sat May  2 17:51:49 2020
19:54:32.395 ->  T 23.005 H 66.077 P 1004.244
19:54:32.395 -> SPIWrite Sample 19 Time Sat May  2 17:51:50 2020
19:54:32.395 ->  T 23.000 H 65.619 P 1004.210
19:54:32.395 -> SPIWrite Sample 20 Time Sat May  2 17:51:51 2020
19:54:32.395 ->  T 23.000 H 65.575 P 1004.262
19:54:32.395 -> SPIWrite Sample 21 Time Sat May  2 17:51:52 2020
19:54:32.395 ->  T 23.005 H 65.873 P 1004.192
19:54:32.395 -> SPIWrite Sample 22 Time Sat May  2 17:51:53 2020
19:54:32.395 ->  T 23.005 H 65.537 P 1004.192
19:54:32.395 -> SPIWrite Sample 23 Time Sat May  2 17:51:54 2020
19:54:32.428 ->  T 23.005 H 65.597 P 1004.244
19:54:32.428 -> SPIWrite Sample 24 Time Sat May  2 17:51:55 2020
19:54:32.428 ->  T 22.995 H 65.635 P 1004.149
19:54:32.428 -> SPIWrite Sample 25 Time Sat May  2 17:51:56 2020
19:54:32.428 ->  T 23.010 H 65.294 P 1004.201
19:54:32.428 -> SPIWrite Sample 26 Time Sat May  2 17:51:57 2020
19:54:32.428 ->  T 22.995 H 65.393 P 1004.175
19:54:32.428 -> SPIWrite Sample 27 Time Sat May  2 17:51:58 2020
19:54:32.428 ->  T 23.000 H 65.713 P 1004.236
19:54:32.463 -> SPIWrite Sample 28 Time Sat May  2 17:51:59 2020
19:54:32.463 ->  T 23.000 H 65.729 P 1004.210
19:54:32.463 -> SPIWrite Sample 29 Time Sat May  2 17:52:00 2020
19:54:32.463 ->  T 23.005 H 65.603 P 1004.192
19:54:32.463 -> SPIWrite Sample 30 Time Sat May  2 17:52:01 2020
19:54:32.463 ->  T 23.010 H 65.382 P 1004.253
19:54:32.463 -> SPIWrite Sample 31 Time Sat May  2 17:52:02 2020
19:54:32.463 ->  T 23.010 H 65.995 P 1004.149
19:54:32.463 -> SPIWrite Sample 32 Time Sat May  2 17:52:03 2020
19:54:32.463 ->  T 23.000 H 65.470 P 1004.236
19:54:32.463 -> SPIWrite Sample 33 Time Sat May  2 17:52:04 2020
19:54:32.497 ->  T 23.000 H 65.376 P 1004.184
19:54:32.497 -> SPIWrite Sample 34 Time Sat May  2 17:52:05 2020
19:54:32.497 ->  T 23.000 H 65.613 P 1004.184
19:54:32.497 -> SPIWrite Sample 35 Time Sat May  2 17:52:06 2020
19:54:32.497 ->  T 23.005 H 65.421 P 1004.192
19:54:32.497 -> SPIWrite Sample 36 Time Sat May  2 17:52:07 2020
19:54:32.497 ->  T 23.010 H 65.537 P 1004.201
19:54:32.497 -> SPIWrite Sample 37 Time Sat May  2 17:52:08 2020
19:54:32.497 ->  T 23.005 H 65.663 P 1004.192
19:54:32.497 -> SPIWrite Sample 38 Time Sat May  2 17:52:09 2020
19:54:32.531 ->  T 23.005 H 65.581 P 1004.192
19:54:32.531 -> SPIWrite Sample 39 Time Sat May  2 17:52:10 2020
19:54:32.531 ->  T 23.000 H 65.487 P 1004.184
19:54:32.531 -> SPIWrite Sample 40 Time Sat May  2 17:52:11 2020
19:54:32.531 ->  T 23.000 H 65.619 P 1004.158
19:54:32.531 -> SPIWrite Sample 41 Time Sat May  2 17:52:12 2020
19:54:32.531 ->  T 23.010 H 65.675 P 1004.253
19:54:32.531 -> SPIWrite Sample 42 Time Sat May  2 17:52:13 2020
19:54:32.531 ->  T 23.010 H 65.918 P 1004.149
19:54:32.565 -> SPIWrite Sample 43 Time Sat May  2 17:52:14 2020
19:54:32.565 ->  T 23.005 H 65.730 P 1004.192
19:54:32.565 -> SPIWrite Sample 44 Time Sat May  2 17:52:15 2020
19:54:32.565 ->  T 23.005 H 65.625 P 1004.192
19:54:32.565 -> SPIWrite Sample 45 Time Sat May  2 17:52:16 2020
19:54:32.565 ->  T 23.010 H 65.906 P 1004.201
19:54:32.565 -> SPIWrite Sample 46 Time Sat May  2 17:52:17 2020
19:54:32.565 ->  T 23.015 H 65.576 P 1004.235
19:54:32.565 -> SPIWrite Sample 47 Time Sat May  2 17:52:18 2020
19:54:32.565 ->  T 23.010 H 65.697 P 1004.175
19:54:32.598 -> SPIWrite Sample 48 Time Sat May  2 17:52:19 2020
19:54:32.598 ->  T 23.021 H 65.554 P 1004.217
19:54:32.598 -> SPIWrite Sample 49 Time Sat May  2 17:52:20 2020
19:54:32.598 ->  T 23.005 H 65.663 P 1004.218
19:54:32.598 -> SPIWrite Sample 50 Time Sat May  2 17:52:21 2020
19:54:32.598 ->  T 23.010 H 65.686 P 1004.279
19:54:32.598 -> SPIWrite Sample 51 Time Sat May  2 17:52:22 2020
19:54:32.598 ->  T 23.005 H 65.647 P 1004.218
19:54:32.598 -> SPIWrite Sample 52 Time Sat May  2 17:52:23 2020
19:54:32.598 ->  T 23.015 H 65.802 P 1004.209
19:54:32.631 -> SPIWrite Sample 53 Time Sat May  2 17:52:24 2020
19:54:32.631 ->  T 23.000 H 65.751 P 1004.210
19:54:32.631 -> SPIWrite Sample 54 Time Sat May  2 17:52:25 2020
19:54:32.631 ->  T 23.010 H 65.846 P 1004.175
19:54:32.631 -> SPIWrite Sample 55 Time Sat May  2 17:52:26 2020
19:54:32.631 ->  T 23.000 H 65.939 P 1004.236
19:54:32.631 -> SPIWrite Sample 56 Time Sat May  2 17:52:27 2020
19:54:32.631 ->  T 23.021 H 65.819 P 1004.191
19:54:32.631 -> SPIWrite Sample 57 Time Sat May  2 17:52:28 2020
19:54:32.665 ->  T 23.000 H 65.602 P 1004.236
19:54:32.665 -> SPIWrite Sample 58 Time Sat May  2 17:52:29 2020
19:54:32.665 ->  T 23.010 H 65.653 P 1004.149
19:54:32.665 -> SPIWrite Sample 59 Time Sat May  2 17:52:30 2020
19:54:32.665 ->  T 23.010 H 65.697 P 1004.201
19:54:32.665 -> SPIWrite Sample 60 Time Sat May  2 17:52:31 2020
19:54:32.665 ->  T 23.010 H 66.171 P 1004.175
19:54:32.665 -> SPIWrite Sample 61 Time Sat May  2 17:52:32 2020
19:54:32.665 ->  T 23.005 H 65.873 P 1004.166
19:54:32.665 -> SPIWrite Sample 62 Time Sat May  2 17:52:33 2020
19:54:32.699 ->  T 23.010 H 66.089 P 1004.201
19:54:32.699 -> SPIWrite Sample 63 Time Sat May  2 17:52:34 2020
19:54:32.699 ->  T 23.010 H 65.862 P 1004.149
19:54:32.699 -> SPIWrite Sample 64 Time Sat May  2 17:52:35 2020
19:54:32.699 ->  T 23.005 H 65.526 P 1004.192
19:54:32.699 -> SPIWrite Sample 65 Time Sat May  2 17:52:36 2020
19:54:32.699 ->  T 23.005 H 65.752 P 1004.192
19:54:32.699 -> SPIWrite Sample 66 Time Sat May  2 17:52:38 2020		// TIME DRIFT 1 SEC!!
19:54:32.699 ->  T 23.000 H 65.873 P 1004.184
19:54:32.699 -> SPIWrite Sample 67 Time Sat May  2 17:52:39 2020
19:54:32.699 ->  T 23.005 H 65.658 P 1004.140
19:54:32.732 -> SPIWrite Sample 68 Time Sat May  2 17:52:40 2020
19:54:32.732 ->  T 23.000 H 65.387 P 1004.210
19:54:32.732 -> SPIWrite Sample 69 Time Sat May  2 17:52:41 2020
19:54:32.732 ->  T 23.005 H 65.355 P 1004.166
19:54:32.732 -> SPIWrite Sample 70 Time Sat May  2 17:52:42 2020
19:54:32.732 ->  T 23.005 H 65.355 P 1004.192
19:54:32.732 -> SPIWrite Sample 71 Time Sat May  2 17:52:43 2020
19:54:32.732 ->  T 23.010 H 65.167 P 1004.201
19:54:32.732 -> SPIWrite Sample 72 Time Sat May  2 17:52:44 2020
19:54:32.766 ->  T 23.010 H 65.234 P 1004.149
19:54:32.766 -> SPIWrite Sample 73 Time Sat May  2 17:52:45 2020
19:54:32.766 ->  T 23.005 H 65.344 P 1004.140
19:54:32.766 -> SPIWrite Sample 74 Time Sat May  2 17:52:46 2020
19:54:32.766 ->  T 23.010 H 65.300 P 1004.175
19:54:32.766 -> SPIWrite Sample 75 Time Sat May  2 17:52:47 2020
19:54:32.766 ->  T 23.015 H 65.587 P 1004.209
19:54:32.766 -> SPIWrite Sample 76 Time Sat May  2 17:52:48 2020
19:54:32.766 ->  T 22.995 H 65.100 P 1004.228
19:54:32.766 -> SPIWrite Sample 77 Time Sat May  2 17:52:49 2020
19:54:32.799 ->  T 23.010 H 65.151 P 1004.227
19:54:32.799 -> SPIWrite Sample 78 Time Sat May  2 17:52:50 2020
19:54:32.799 ->  T 23.010 H 65.465 P 1004.175
19:54:32.799 -> SPIWrite Sample 79 Time Sat May  2 17:52:51 2020
19:54:32.799 ->  T 23.015 H 65.532 P 1004.209
19:54:32.799 -> SPIWrite Sample 80 Time Sat May  2 17:52:52 2020
19:54:32.799 ->  T 23.010 H 65.234 P 1004.201
19:54:32.799 -> SPIWrite Sample 81 Time Sat May  2 17:52:53 2020
19:54:32.799 ->  T 23.000 H 65.332 P 1004.236
19:54:32.833 -> SPIWrite Sample 82 Time Sat May  2 17:52:54 2020
19:54:32.833 ->  T 23.010 H 65.068 P 1004.201
19:54:32.833 -> SPIWrite Sample 83 Time Sat May  2 17:52:55 2020
19:54:32.833 ->  T 23.005 H 65.448 P 1004.192
19:54:32.833 -> SPIWrite Sample 84 Time Sat May  2 17:52:56 2020
19:54:32.833 ->  T 23.010 H 65.002 P 1004.227
19:54:32.833 -> SPIWrite Sample 85 Time Sat May  2 17:52:57 2020
19:54:32.833 ->  T 23.010 H 65.002 P 1004.201
19:54:32.833 -> SPIWrite Sample 86 Time Sat May  2 17:52:58 2020
19:54:32.833 ->  T 23.010 H 65.046 P 1004.253
19:54:32.833 -> SPIWrite Sample 87 Time Sat May  2 17:52:59 2020
19:54:32.867 ->  T 23.015 H 65.217 P 1004.235
19:54:32.867 -> SPIWrite Sample 88 Time Sat May  2 17:53:00 2020
19:54:32.867 ->  T 23.005 H 65.139 P 1004.192
19:54:32.867 -> SPIWrite Sample 89 Time Sat May  2 17:53:01 2020
19:54:32.867 ->  T 23.005 H 65.244 P 1004.218
19:54:32.867 -> SPIWrite Sample 90 Time Sat May  2 17:53:02 2020
19:54:32.867 ->  T 23.010 H 65.454 P 1004.201
19:54:32.867 -> SPIWrite Sample 91 Time Sat May  2 17:53:03 2020
19:54:32.867 ->  T 23.021 H 65.648 P 1004.165
19:54:32.901 -> SPIWrite Sample 92 Time Sat May  2 17:53:04 2020
19:54:32.901 ->  T 23.010 H 65.664 P 1004.201
19:54:32.901 -> SPIWrite Sample 93 Time Sat May  2 17:53:05 2020
19:54:32.901 ->  T 23.021 H 65.383 P 1004.165
19:54:32.901 -> SPIWrite Sample 94 Time Sat May  2 17:53:06 2020
19:54:32.901 ->  T 23.005 H 65.487 P 1004.088
19:54:32.901 -> SPIWrite Sample 95 Time Sat May  2 17:53:07 2020
19:54:32.901 ->  T 23.000 H 65.608 P 1004.158
19:54:32.901 -> SPIWrite Sample 96 Time Sat May  2 17:53:08 2020
19:54:32.901 ->  T 23.005 H 65.796 P 1004.192
19:54:32.935 -> SPIWrite Sample 97 Time Sat May  2 17:53:09 2020
19:54:32.935 ->  T 23.010 H 65.796 P 1004.175
19:54:32.935 -> SPIWrite Sample 98 Time Sat May  2 17:53:10 2020
19:54:32.935 ->  T 23.010 H 65.509 P 1004.201
19:54:32.935 -> SPIWrite Sample 99 Time Sat May  2 17:53:11 2020
19:54:32.935 ->  T 23.015 H 65.587 P 1004.183
19:54:32.935 -> SPIWrite Sample 100 Time Sat May  2 17:53:12 2020
19:54:32.935 ->  T 23.015 H 65.719 P 1004.209
19:54:32.935 -> SPIWrite Sample 101 Time Sat May  2 17:53:13 2020
19:54:32.935 ->  T 23.010 H 65.868 P 1004.175
19:54:32.969 -> SPIWrite Sample 102 Time Sat May  2 17:53:14 2020
19:54:32.969 ->  T 23.010 H 65.465 P 1004.201
19:54:32.969 -> SPIWrite Sample 103 Time Sat May  2 17:53:15 2020
19:54:32.969 ->  T 23.010 H 65.526 P 1004.201
19:54:32.969 -> SPIWrite Sample 104 Time Sat May  2 17:53:16 2020
19:54:32.969 ->  T 23.010 H 65.851 P 1004.149
19:54:32.969 -> SPIWrite Sample 105 Time Sat May  2 17:53:17 2020
19:54:32.969 ->  T 23.000 H 65.487 P 1004.236
19:54:32.969 -> SPIWrite Sample 106 Time Sat May  2 17:53:18 2020
19:54:32.969 ->  T 23.005 H 65.481 P 1004.140
19:54:33.003 -> SPIWrite Sample 107 Time Sat May  2 17:53:19 2020
19:54:33.003 ->  T 23.010 H 65.664 P 1004.201
19:54:33.003 -> SPIWrite Sample 108 Time Sat May  2 17:53:20 2020
19:54:33.003 ->  T 23.021 H 65.675 P 1004.217
19:54:33.003 -> SPIWrite Sample 109 Time Sat May  2 17:53:21 2020
19:54:33.003 ->  T 23.010 H 65.741 P 1004.149
19:54:33.003 -> SPIWrite Sample 110 Time Sat May  2 17:53:22 2020
19:54:33.003 ->  T 23.010 H 65.625 P 1004.149
19:54:33.003 -> SPIWrite Sample 111 Time Sat May  2 17:53:23 2020
19:54:33.003 ->  T 23.005 H 65.906 P 1004.192
19:54:33.038 -> SPIWrite Sample 112 Time Sat May  2 17:53:24 2020
19:54:33.038 ->  T 23.010 H 65.438 P 1004.201
19:54:33.038 -> SPIWrite Sample 113 Time Sat May  2 17:53:25 2020
19:54:33.038 ->  T 23.010 H 65.614 P 1004.149
19:54:33.038 -> SPIWrite Sample 114 Time Sat May  2 17:53:26 2020
19:54:33.038 ->  T 23.010 H 65.267 P 1004.149
19:54:33.038 -> SPIWrite Sample 115 Time Sat May  2 17:53:27 2020
19:54:33.038 ->  T 23.010 H 65.399 P 1004.201
19:54:33.038 -> SPIWrite Sample 116 Time Sat May  2 17:53:28 2020
19:54:33.038 ->  T 23.005 H 65.492 P 1004.166
19:54:33.071 -> SPIWrite Sample 117 Time Sat May  2 17:53:29 2020
19:54:33.071 ->  T 23.010 H 65.857 P 1004.149
19:54:33.071 -> SPIWrite Sample 118 Time Sat May  2 17:53:30 2020
19:54:33.071 ->  T 23.010 H 65.702 P 1004.096
19:54:33.071 -> SPIWrite Sample 119 Time Sat May  2 17:53:31 2020
19:54:33.071 ->  T 23.000 H 65.244 P 1004.184
19:54:33.071 -> SPIWrite Sample 120 Time Sat May  2 17:53:32 2020
19:54:33.071 ->  T 23.000 H 65.465 P 1004.184
19:54:33.071 -> SPIWrite Sample 121 Time Sat May  2 17:53:33 2020
19:54:33.071 ->  T 23.000 H 65.696 P 1004.132
19:54:33.104 -> SPIWrite Sample 122 Time Sat May  2 17:53:34 2020
19:54:33.104 ->  T 23.005 H 65.724 P 1004.192
19:54:33.104 -> SPIWrite Sample 123 Time Sat May  2 17:53:35 2020
19:54:33.104 ->  T 23.010 H 65.427 P 1004.149
19:54:33.104 -> SPIWrite Sample 124 Time Sat May  2 17:53:36 2020
19:54:33.104 ->  T 23.015 H 65.460 P 1004.157
19:54:33.104 -> SPIWrite Sample 125 Time Sat May  2 17:53:37 2020
19:54:33.104 ->  T 23.015 H 65.234 P 1004.157
19:54:33.104 -> SPIWrite Sample 126 Time Sat May  2 17:53:38 2020
19:54:33.141 ->  T 23.005 H 65.106 P 1004.192
19:54:33.141 -> SPIWrite Sample 127 Time Sat May  2 17:53:39 2020
19:54:33.141 ->  T 23.015 H 65.532 P 1004.157
19:54:33.141 -> SPIWrite Sample 128 Time Sat May  2 17:53:40 2020
19:54:33.141 ->  T 23.015 H 64.925 P 1004.183
19:54:33.141 -> SPIWrite Sample 129 Time Sat May  2 17:53:41 2020
19:54:33.141 ->  T 23.010 H 65.785 P 1004.175
19:54:33.141 -> SPIWrite Sample 130 Time Sat May  2 17:53:42 2020
19:54:33.141 ->  T 23.010 H 65.393 P 1004.201
19:54:33.141 -> SPIWrite Sample 131 Time Sat May  2 17:53:44 2020
19:54:33.174 ->  T 23.010 H 65.581 P 1004.096
19:54:33.174 -> SPIWrite Sample 132 Time Sat May  2 17:53:45 2020
19:54:33.174 ->  T 23.015 H 65.675 P 1004.183
19:54:33.174 -> SPIWrite Sample 133 Time Sat May  2 17:53:46 2020
19:54:33.174 ->  T 23.010 H 65.929 P 1004.227
19:54:33.174 -> SPIWrite Sample 134 Time Sat May  2 17:53:47 2020
19:54:33.174 ->  T 23.010 H 65.504 P 1004.149
19:54:33.174 -> SPIWrite Sample 135 Time Sat May  2 17:53:48 2020
19:54:33.174 ->  T 23.010 H 65.493 P 1004.149
19:54:33.174 -> SPIWrite Sample 136 Time Sat May  2 17:53:49 2020
19:54:33.209 ->  T 23.010 H 65.344 P 1004.149
19:54:33.209 -> SPIWrite Sample 137 Time Sat May  2 17:53:50 2020
19:54:33.209 ->  T 23.021 H 65.554 P 1004.113
19:54:33.209 -> SPIWrite Sample 138 Time Sat May  2 17:53:51 2020
19:54:33.209 ->  T 23.015 H 65.995 P 1004.183
19:54:33.209 -> SPIWrite Sample 139 Time Sat May  2 17:53:52 2020
19:54:33.209 ->  T 23.010 H 65.576 P 1004.149
19:54:33.209 -> SPIWrite Sample 140 Time Sat May  2 17:53:53 2020
19:54:33.209 ->  T 23.010 H 65.884 P 1004.149
19:54:33.209 -> SPIWrite Sample 141 Time Sat May  2 17:53:54 2020
19:54:33.242 ->  T 23.010 H 66.061 P 1004.149
19:54:33.242 -> SPIWrite Sample 142 Time Sat May  2 17:53:55 2020
19:54:33.242 ->  T 23.010 H 65.857 P 1004.149
19:54:33.242 -> SPIWrite Sample 143 Time Sat May  2 17:53:56 2020
19:54:33.242 ->  T 23.010 H 66.105 P 1004.201
19:54:33.242 -> SPIWrite Sample 144 Time Sat May  2 17:53:57 2020
19:54:33.242 ->  T 23.010 H 65.818 P 1004.175
19:54:33.242 -> SPIWrite Sample 145 Time Sat May  2 17:53:58 2020
19:54:33.242 ->  T 23.010 H 65.531 P 1004.149
19:54:33.242 -> SPIWrite Sample 146 Time Sat May  2 17:53:59 2020
19:54:33.276 ->  T 23.021 H 65.460 P 1004.217
19:54:33.276 -> SPIWrite Sample 147 Time Sat May  2 17:54:00 2020
19:54:33.276 ->  T 23.010 H 65.576 P 1004.149
19:54:33.276 -> SPIWrite Sample 148 Time Sat May  2 17:54:01 2020
19:54:33.276 ->  T 23.005 H 65.509 P 1004.192
19:54:33.276 -> SPIWrite Sample 149 Time Sat May  2 17:54:02 2020
19:54:33.276 ->  T 23.015 H 65.587 P 1004.157
19:54:33.276 -> SPIWrite Sample 150 Time Sat May  2 17:54:03 2020
19:54:33.276 ->  T 23.010 H 66.105 P 1004.149
19:54:33.309 -> SPIWrite Sample 151 Time Sat May  2 17:54:04 2020
19:54:33.309 ->  T 23.015 H 65.907 P 1004.157
19:54:33.309 -> SPIWrite Sample 152 Time Sat May  2 17:54:05 2020
19:54:33.309 ->  T 23.010 H 65.758 P 1004.123
19:54:33.309 -> SPIWrite Sample 153 Time Sat May  2 17:54:06 2020
19:54:33.309 ->  T 23.010 H 65.542 P 1004.149
19:54:33.309 -> SPIWrite Sample 154 Time Sat May  2 17:54:07 2020
19:54:33.309 ->  T 23.021 H 65.350 P 1004.165
19:54:33.309 -> SPIWrite Sample 155 Time Sat May  2 17:54:08 2020
19:54:33.309 ->  T 23.031 H 65.533 P 1004.156
19:54:33.342 -> SPIWrite Sample 156 Time Sat May  2 17:54:09 2020
19:54:33.342 ->  T 23.010 H 66.033 P 1004.149
19:54:33.342 -> SPIWrite Sample 157 Time Sat May  2 17:54:10 2020
19:54:33.342 ->  T 23.021 H 65.444 P 1004.113
19:54:33.342 -> SPIWrite Sample 158 Time Sat May  2 17:54:11 2020
19:54:33.342 ->  T 23.010 H 65.520 P 1004.123
19:54:33.342 -> SPIWrite Sample 159 Time Sat May  2 17:54:12 2020
19:54:33.342 ->  T 23.021 H 65.444 P 1004.035
19:54:33.342 -> SPIWrite Sample 160 Time Sat May  2 17:54:13 2020
19:54:33.376 ->  T 23.021 H 66.106 P 1004.217
19:54:33.376 -> SPIWrite Sample 161 Time Sat May  2 17:54:14 2020
19:54:33.376 ->  T 23.021 H 65.929 P 1004.165
19:54:33.376 -> SPIWrite Sample 162 Time Sat May  2 17:54:15 2020
19:54:33.376 ->  T 23.010 H 65.576 P 1004.123
19:54:33.376 -> SPIWrite Sample 163 Time Sat May  2 17:54:16 2020
19:54:33.376 ->  T 23.010 H 65.752 P 1004.149
19:54:33.376 -> SPIWrite Sample 164 Time Sat May  2 17:54:17 2020
19:54:33.376 ->  T 23.021 H 65.725 P 1004.191
19:54:33.376 -> SPIWrite Sample 165 Time Sat May  2 17:54:18 2020
19:54:33.411 ->  T 23.010 H 65.526 P 1004.123
19:54:33.411 -> SPIWrite Sample 166 Time Sat May  2 17:54:19 2020
19:54:33.411 ->  T 23.021 H 65.449 P 1004.139
19:54:33.411 -> SPIWrite Sample 167 Time Sat May  2 17:54:20 2020
19:54:33.411 ->  T 23.005 H 65.332 P 1004.088
19:54:33.411 -> SPIWrite Sample 168 Time Sat May  2 17:54:21 2020
19:54:33.411 ->  T 23.010 H 65.598 P 1004.175
19:54:33.411 -> SPIWrite Sample 169 Time Sat May  2 17:54:22 2020
19:54:33.411 ->  T 23.010 H 65.796 P 1004.096
19:54:33.411 -> SPIWrite Sample 170 Time Sat May  2 17:54:23 2020
19:54:33.444 ->  T 23.005 H 66.215 P 1004.088
19:54:33.444 -> SPIWrite Sample 171 Time Sat May  2 17:54:24 2020
19:54:33.444 ->  T 23.015 H 66.149 P 1004.157
19:54:33.444 -> SPIWrite Sample 172 Time Sat May  2 17:54:25 2020
19:54:33.444 ->  T 23.010 H 65.708 P 1004.044
19:54:33.444 -> SPIWrite Sample 173 Time Sat May  2 17:54:26 2020
19:54:33.444 ->  T 23.010 H 66.072 P 1004.044
19:54:33.444 -> SPIWrite Sample 174 Time Sat May  2 17:54:27 2020
19:54:33.444 ->  T 23.021 H 65.984 P 1004.113
19:54:33.444 -> SPIWrite Sample 175 Time Sat May  2 17:54:28 2020
19:54:33.478 ->  T 23.015 H 65.598 P 1004.052
19:54:33.478 -> SPIWrite Sample 176 Time Sat May  2 17:54:29 2020
19:54:33.478 ->  T 23.010 H 65.763 P 1004.096
19:54:33.478 -> SPIWrite Sample 177 Time Sat May  2 17:54:30 2020
19:54:33.478 ->  T 23.031 H 65.637 P 1004.182
19:54:33.478 -> SPIWrite Sample 178 Time Sat May  2 17:54:31 2020
19:54:33.478 ->  T 23.021 H 65.885 P 1004.113
19:54:33.478 -> SPIWrite Sample 179 Time Sat May  2 17:54:32 2020
19:54:33.478 ->  T 23.005 H 65.487 P 1004.114
19:54:33.478 -> Written to SPI 180 Samples FileLen 279360
19:54:33.512 -> AppendToSPIFFS ends Sat May  2 17:54:34 2020

boarchuz · Postby **boarchuz** » Sat May 02, 2020 10:53 pm

Possibly because you're not compensating for ULP program run time.

If it's rounding up after 67 loops, and we know that means it's accumulated an additional second, then that's about 15ms per loop. That's possible given that you're doing I2C stuff.

It would also mean that it should 'skip' another second after another 67 loops. Indeed, you can see it does at 17:53:44.

Suggest either ditching the timestamps altogether and assuming one-second intervals or adjusting ULP wakeup interval to compensate for average runtime.

fededim · Postby **fededim** » Sun May 03, 2020 2:55 pm

Thanks for the observation I did not notice it. It seems that the execution time of my code containing some I2C reads/write takes up 15ms on each schedule and this summing up in the long run makes my ULP schedule drift. The problem is that the number of samples where the drift occurs is not fixed. In this run it verifies firstly every 81 samples and it changes in the next runs (in the second run happens at 151th sample). Moreover I have to say that also RTC clock by itself drifts a lot with default clock source, in fact in the log below at rows containing AppendToSPIFFS we can see the drift comparing Arduino timestamp on the left and timestamp of unix time function on the right, starting from a perfect ntp time synchronization at row containing "Successfully set time".

16:16:52.660 -> Successfully set time to Sun May 3 14:16:52 2020
16:19:53.250 -> AppendToSPIFFS starts Sun May 3 14:19:53 2020
16:19:54.925 -> AppendToSPIFFS ends Sun May 3 14:19:55 2020
16:22:54.452 -> AppendToSPIFFS starts Sun May 3 14:22:56 2020 (1,5s drift)
16:22:56.122 -> AppendToSPIFFS ends Sun May 3 14:22:57 2020 (probably the same)
16:25:55.612 -> AppendToSPIFFS starts Sun May 3 14:25:58 2020 (at least 2,4s drift)
16:25:57.279 -> AppendToSPIFFS ends Sun May 3 14:26:00 2020 (at least 2,8s drift)
16:28:56.811 -> AppendToSPIFFS starts Sun May 3 14:29:00 2020 (at least 3,2s drift)
16:28:58.484 -> AppendToSPIFFS ends Sun May 3 14:29:02 2020 (at least 3,6s drift)

We can see that the RTC skips 2.8s seconds just after 9 minute deep sleep and this is unacceptable. Unluckily I am using Arduino development framework and there seems not to be a way to change the RTC clock source as in ESP-IDF. It seems not an an easy problem for me to solve. Last but not the least I apologize to the forum's users, I believed that ADF meant Arduino Development Framework and today I discovered that it means Audio Development Framework. Sorry again for posting to the wrong section

Log file
https://easyupload.io/dk8si8

fededim · Postby **fededim** » Wed May 13, 2020 7:07 pm

Final post: I did some tests with an external 32Khz crystal and the clock behaves much better. In 6 hours time the drift is only 160ms compared to a computer, probably it can be further tuned by adjusting the capacitors (unluckily no datasheet came with my crystal so I had to try with a predefined capacitance). I also tuned the NTP synchronization to take into account also the decimal part and now all timestamps include also milliseconds. It can be easily seen that the ULP code takes around 14-15 ms to execute and this summed up for 180 samples gives a drift of 2 seconds in sample time (I will change the ULP sleep period to take into account this 15ms period). I would definitive say that the external crystal is the way to go to reduce the drift.

File log: https://gofile.io/d/w9V3n5

Esp32 ULP/RTC time drift

Esp32 ULP/RTC time drift

Re: Esp32 ULP/RTC time drift

Re: Esp32 ULP/RTC time drift

Re: Esp32 ULP/RTC time drift

Who is online

About Us

Extra

Information