clock_gettime seems random after deep sleep with flash encryption enabled (IDFGH-12957)

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.

Apache License 2.0

12.98k stars 7.12k forks source link

clock_gettime seems random after deep sleep with flash encryption enabled (IDFGH-12957) #13912

Open NotMick opened 1 month ago

NotMick commented 1 month ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

I have an ESP32-C6 with idf v5.2.1 (also tested with v5.2.2) that needs to be in deep sleep and wake up every now and then. When its woken up it needs to know how long it slept. For that I use clock_gettime(). But when I wake the esp up the return value seems wrong. I got the following results with 5 seconds of deep sleep between them:

These are the seconds since the first boot but they go up and down with large jumps.

I'm not experiencing this issue when flash encryption is disabled. And when I give the esp an hard reset (power off and on) the time is right for a couple of hours but eventually they are wrong again.

0xjakob commented 1 month ago

@NotMick I just tested this and clock_gettime seems to work well, but without encryption. Do you use flash encryption in development mode or in release mode? From your description, I understand that clock_gettime() works for the first few hours, but then begins to show deviations of several thousand seconds; is this correct?

NotMick commented 1 month ago

I use flash encryption in release mode. And you are correct. It works for the first few hours before starting to show deviations. The deviations can range from going a couple of seconds back and jumping a few thousand. The time i get back does seems to stay in range of a number, (with a few thousand seconds range). But is doesn't seem to be completely random. It hasnt jumped from 80000 to 200000.

KonstantinKondrashov commented 1 month ago

Hi @NotMick, I am pretty much sure that Flash encryption does not affect this issue. This issue appears to be related to deep sleep and wake-up cycles. Could you help us by providing a reproducible example? Time-related issues can be tricky to diagnose and resolve, so having it would be good. Please share the following:

sdkconfig file
Deep sleep/wake-up frequency: How often does your application enter and exit deep sleep?
Application features: Describe any functionalities that might be affected during the deep sleep/wake-up cycles, particularly those that are related to time, and power savings. With this information, we can better pinpoint the issue and find a solution. Thank you!

NotMick commented 1 month ago

sdkconfig.txt With normal behavior it wakes up every hour send some stuff over Wi-Fi and goes back to deep sleep. The ulp core is always running even when the appliance is awake. It does some measurements and if the measurements are a certain value it will wake itself up. Its also possible to wake the appliance up with an button press. If you wake up the appliance early it will gets its boot time and calculate how long it was sleeping. So that it can complete its hour cycle.

I personally have not encountered this issue on devices without flash encryption

KonstantinKondrashov commented 1 month ago

Do you use only deepsleep or light sleep as well?

NotMick commented 1 month ago

Only deep sleep

KonstantinKondrashov commented 1 month ago

@NotMick How do you call the clock_gettime()? with CLOCK_MONOTONIC or CLOCK_REALTIME?

    struct timespec tp;
    ESP_LOGI(TAG, "CLOCK_REALTIME= %lld seconds", tp.tv_sec);
    clock_gettime(CLOCK_REALTIME, &tp);

Do you set timestamp? using this settimeofday().

I still can not reproduce this issue. I run the app for a long time (about 6 hours) and I do not see such a behavior.

NotMick commented 1 month ago

I use CLOCK_REALTIME I dont use settimeofday()

NotMick commented 1 month ago

I want to thank you for trying to reproduce the issue.

I'll try to make a small example in which I can reproduce the bug next week.

NotMick commented 4 weeks ago

clock_gettime_example.zip I made a minimal example in which the issue occurred. After an hour the time could go back a few seconds but after half a day the time could go back a hundred seconds.

KonstantinKondrashov commented 4 weeks ago

@NotMick! Thanks for the example. I will check it out and find the root cause.

KonstantinKondrashov commented 3 weeks ago

Hi @NotMick! I took ESP-IDF version - v5.2.2 (you said that you observed it on this version too) and ran this example for ~22 hours. I confirm that "After an hour the time could go back a few seconds" - it is possible. I observe it, it is ok.

but after half a day the time could go back a hundred seconds.

I do not see it. I do not have an AHT20 sensor (the ulp core does nothing), but it does not matter for this issue.

Here is my log. Which says that it was run for about 22 hours and "Time now" is intolerance (79204 and 79109). I pressed the BUTTON0 a few times as well:

2024-06-26 09:31:50 I (199) main_task: Calling app_main()
2024-06-26 09:31:50 I (199) MAIN: Time now: 79204
2024-06-26 09:31:50 I (209) MAIN: Going to sleep
2024-06-26 09:31:50 INFO time from the start test = 21:58:29.586681 | 79109 sec

NotMick commented 3 weeks ago

Just to make sure, are you using flash encryption and secure boot? Cause I have two examples running, one with flash encryption and one without. Only the one with flash encryption has the problem.