pthread_cond_timedwait returns timeout too early (IDFGH-5119)

[jefftharris]

Environment

• Development Kit: none
• Kit version (for WroverKit/PicoKit/DevKitC): n/1
• Module or chip used: ESP32-WROVER-E
• IDF version (run git describe --tags to find it): 4.0
• Build System: CMake
• Compiler version (run xtensa-esp32-elf-gcc --version to find it): xtensa-esp32-elf-gcc (crosstool-NG esp-2019r2) 8.2.0
• Operating System: Linux
• (Windows only) environment type: n/a
• Using an IDE?: yes, Qt Creator
• Power Supply: external 3.3V

Problem Description

In looking to add CLOCK_MONOTONIC support to pthread condition variables, I noticed that pthread_cond_timedwait is returning an ETIMEDOUT error before the time actually expires. If the current time is retrieved after the function returns an ETIMEDOUT error, the time will likely be before the timeout passed to the function.

Should the conversion of the time difference from the passed time to the current gettimeofday round up in pthread_cond_var.c? I.e. should the conversions from diff_time to timeout_msec and them timeout_msec to timeout_ticks round to the next time if there is a remainder?

Additionally, there looks to need to be one extra timeout_ticks added to get the xSemaphoreTake call to return after the time has expired.

Expected Behavior

pthread_cond_timedwait returns ETIMEDOUT only if the timeout has actually passed.

Actual Behavior

pthread_cond_timeout returns the error code too early.

Steps to reproduce

Running the code below produces output similar to the following. The extra time should be positive when the timeout occurs.

Extra time: -1786000, status: timeout
Extra time: -618000, status: timeout
Extra time: -123000, status: timeout
Extra time: -79000, status: timeout
Extra time: -160000, status: timeout
Extra time: -83000, status: timeout
Extra time: -82000, status: timeout

Code to reproduce this issue

    using ClockT = std::chrono::system_clock;
    std::mutex mutex;
    std::condition_variable cond;

    std::unique_lock lock(mutex);
    for (int i = 0; i < 20; ++i) {
        auto timeout = ClockT::now() + std::chrono::seconds(1);

        auto secs = std::chrono::time_point_cast<std::chrono::seconds>(timeout);
        auto nsecs = std::chrono::duration_cast<std::chrono::nanoseconds>
                (timeout - secs);
        struct timespec ts = {
                .tv_sec = static_cast<time_t>(secs.time_since_epoch().count()),
                .tv_nsec = static_cast<long>(nsecs.count())};
        int rc = ::pthread_cond_timedwait(cond.native_handle(),
                                          lock.mutex()->native_handle(), &ts);
        auto status = (rc == ETIMEDOUT) ? std::cv_status::timeout :
                                          std::cv_status::no_timeout;
        auto end = ClockT::now();
        auto extra = end - timeout;
        printf("Extra time: %lld, status: %s\n", extra.count(),
               (status == std::cv_status::timeout) ? "timeout" : "no timeout");
    }

Potential Fix

This patch seems to resolve the issue with a consistent return of ETIMEDOUT and a positive extra time after the timeout.

diff --git a/esp-idf/components/pthread/pthread_cond_var.c b/esp-idf/components/pthread/pthread_cond_var.c
index 8db28ae5..528d3ab1 100644
--- a/esp-idf/components/pthread/pthread_cond_var.c
+++ b/esp-idf/components/pthread/pthread_cond_var.c
@@ -115,14 +115,16 @@ int pthread_cond_timedwait(pthread_cond_t *cv, pthread_mutex_t *mut, const struc
             timeout_msec = 0;
         } else {
             timersub(&abs_time, &cur_time, &diff_time);
-            timeout_msec = (diff_time.tv_sec * 1000) + (diff_time.tv_usec / 1000);
+            timeout_msec = (diff_time.tv_sec * 1000) +
+                ((diff_time.tv_usec + 1000 - 1) / 1000);
         }
 
         if (timeout_msec <= 0) {
             return ETIMEDOUT;
         }
 
-        timeout_ticks = timeout_msec / portTICK_PERIOD_MS;
+        timeout_ticks = (timeout_msec + portTICK_PERIOD_MS - 1) / portTICK_PERIOD_MS;
+        timeout_ticks += 1;
     }
 
     esp_pthread_cond_waiter_t w;

[projectgus]

Hi @jefftharris,

Thanks for the very clear bug report, test code, and patch. Agree with you that the timeout should be rounded up in the way you describe.

We'll submit a patch and add a unit test for this behaviour ASAP, the issue will be updated when it merges.

[projectgus]

Hi @jefftharris,

The code change and a test (both based very closely on your submissions) have been submitted for merging internally. Thanks again for the clear report.

Additionally, there looks to need to be one extra timeout_ticks added to get the xSemaphoreTake call to return after the time has expired.

The reason for this is that FreeRTOS delays are only accurate to the tick period. Specifically, vTaskDelay(1) delays for an amount of time greater than zero and less than the tick period - because (in an idle system) the task will resume immediately after the next tick interrupt (start of time quantum), but it could have gone to sleep at any point during the previous time quantum. So in order to ensure we wait for at least 1 tick period, it's necessary to vTaskDelay(2).