[Bug libgcc/113850] New: condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[Bug libgcc/113850] New: condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[matteo at mitalia dot net]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=113850

            Bug ID: 113850
           Summary: condition variables timed wait does a lot of spurious
                    wakeups on Win32 threading implementation
           Product: gcc
           Version: 13.1.0
            Status: UNCONFIRMED
          Severity: normal
          Priority: P3
         Component: libgcc
          Assignee: unassigned at gcc dot gnu.org
          Reporter: matteo at mitalia dot net
  Target Milestone: ---

Created attachment 57371
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=57371&action=edit
Test program to reproduce the bug

Sample program:
```
#include <condition_variable>
#include <chrono>
#include <thread>
#include <stdio.h>

int main() {
    std::condition_variable cv;
    std::mutex mx;
    bool pass = false;

    auto thread_fn = [&](bool timed) {
        int wakeups = 0;
        using sc = std::chrono::system_clock;
        auto before = sc::now();
        std::unique_lock<std::mutex> ml(mx);
        if (timed) {
            cv.wait_for(ml, std::chrono::seconds(2), [&]{
                ++wakeups;
                return pass;
            });
        } else {
            cv.wait(ml, [&]{
                ++wakeups;
                return pass;
            });
        }
        printf("pass: %d; wakeups: %d; elapsed: %d ms\n", pass, wakeups,
                int((sc::now() - before) / std::chrono::milliseconds(1)));
        pass = false;
    };

    {
        // timed wait, let expire
        std::thread t(thread_fn, true);
        t.join();
    }

    {
        // timed wait, wake up explicitly after 1 second
        std::thread t(thread_fn, true);
        std::this_thread::sleep_for(std::chrono::seconds(1));
        {
            std::unique_lock<std::mutex> ml(mx);
            pass = true;
        }
        cv.notify_all();
        t.join();
    }

    {
        // non-timed wait, wake up explicitly after 1 second
        std::thread t(thread_fn, false);
        std::this_thread::sleep_for(std::chrono::seconds(1));
        {
            std::unique_lock<std::mutex> ml(mx);
            pass = true;
        }
        cv.notify_all();
        t.join();
    }
    return 0;
}
```

On Linux or on Win32 with the MCF threading model the output looks like
```
pass: 0; wakeups: 2; elapsed: 2000 ms
pass: 1; wakeups: 2; elapsed: 991 ms
pass: 1; wakeups: 2; elapsed: 996 ms
```

but with the Win32 "regular" threading model
```
pass: 0; wakeups: 1418; elapsed: 2000 ms
pass: 1; wakeups: 479; elapsed: 988 ms
pass: 1; wakeups: 2; elapsed: 992 ms
```

As can be seen here, there's a huge number of spurious wakeups, but only for
the timed waits; ultimately, I traced the problem to
`__gthr_win32_abs_to_rel_time`, that is used to convert from the absolute
`timespec` value (used internally through the gthread abstraction layer) to the
relative milliseconds to be passed to `SleepConditionVariableCS`:

```
/* Convert absolute thread time to relative time in millisecond.  */

DWORD
__gthr_win32_abs_to_rel_time (const __gthread_time_t *abs_time)
{
  union {
    ULONGLONG nsec100;
    FILETIME ft;
  } now;
  ULONGLONG abs_time_nsec100;

  /* The Windows epoch is 1/1/1601 while the Unix epoch is 1/1/1970.  */
  GetSystemTimeAsFileTime (&now.ft);
  now.nsec100 -= FILETIME_1970;

  abs_time_nsec100
    = (ULONGLONG) abs_time->tv_sec * NSEC100_PER_SEC
        + CEIL_DIV (abs_time->tv_nsec, 100);

  if (abs_time_nsec100 < now.nsec100)
    return 0;

  return (DWORD) CEIL_DIV (abs_time_nsec100 - now.nsec100, NSEC100_PER_SEC);
}
```

the final line has a typo: as the return value is in milliseconds, it should
divide by the constant NSEC100_PER_MSEC; as it is, it returns the value in
seconds, so it's going to be 1000 times smaller than it should, which results
in ~1000× spurious wakeups. I suppose that was a typo or some
rebase/refactoring mishap, as the correct constant was already defined above
(and wasn't used for anything else). The patch of course is trivial, and
applying it makes the test program return to its "normal" wakeups count.

[Bug libgcc/113850] condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[matteo at mitalia dot net]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=113850

--- Comment #1 from Matteo Italia <matteo at mitalia dot net> ---
Created attachment 57372
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=57372&action=edit
Proposed patch

[Bug libgcc/113850] condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[ebotcazou at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=113850

Eric Botcazou <ebotcazou at gcc dot gnu.org> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Last reconfirmed|                            |2024-02-09
     Ever confirmed|0                           |1
             Status|UNCONFIRMED                 |NEW
   Target Milestone|---                         |13.3

--- Comment #2 from Eric Botcazou <ebotcazou at gcc dot gnu.org> ---
Ouch.  Thanks for catching this (possibly auto-completion induced) typo!

[Bug libgcc/113850] condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[matteo at mitalia dot net]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=113850

Matteo Italia <matteo at mitalia dot net> changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
  Attachment #57372|0                           |1
        is obsolete|                            |

--- Comment #3 from Matteo Italia <matteo at mitalia dot net> ---
Created attachment 57391
  --> https://gcc.gnu.org/bugzilla/attachment.cgi?id=57391&action=edit
Proposed patch

(In reply to Eric Botcazou from comment #2)
> Ouch.  Thanks for catching this (possibly auto-completion induced) typo!

The fun part is that I noticed because in our codebase there's a point with the
typical mistake of a timed wait without a predicate to check, so at each
spurious wakeup we ended up sending a network request. A 10 seconds
long-polling turned out to be an almost free-run of HTTP requests (1 every 10
ms) which is not ideal. :-D

Anyhow, I sent my patch to gcc-patches
https://gcc.gnu.org/pipermail/gcc-patches/2024-February/645325.html , let's
hope it gets merged and backported before the next releases.

[Bug libgcc/113850] condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[cvs-commit at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=113850

--- Comment #4 from GCC Commits <cvs-commit at gcc dot gnu.org> ---
The master branch has been updated by Jonathan Yong <jyong@gcc.gnu.org>:

https://gcc.gnu.org/g:05ad8fb55a55f1e201fd781c84682a7c0bbd4d97

commit r14-9042-g05ad8fb55a55f1e201fd781c84682a7c0bbd4d97
Author: Matteo Italia <matteo@mitalia.net>
Date:   Fri Feb 9 15:04:20 2024 +0100

    libgcc: fix Win32 CV abnormal spurious wakeups in timed wait [PR113850]

    Fix a typo in __gthr_win32_abs_to_rel_time that caused it to return a
    relative time in seconds instead of milliseconds. As a consequence,
    __gthr_win32_cond_timedwait called SleepConditionVariableCS with a
    1000x shorter timeout; this caused ~1000x more spurious wakeups in
    CV timed waits such as std::condition_variable::wait_for or wait_until,
    resulting generally in much higher CPU usage.

    This can be demonstrated by this sample program:

    ```

    int main() {
        std::condition_variable cv;
        std::mutex mx;
        bool pass = false;

        auto thread_fn = [&](bool timed) {
            int wakeups = 0;
            using sc = std::chrono::system_clock;
            auto before = sc::now();
            std::unique_lock<std::mutex> ml(mx);
            if (timed) {
                cv.wait_for(ml, std::chrono::seconds(2), [&]{
                    ++wakeups;
                    return pass;
                });
            } else {
                cv.wait(ml, [&]{
                    ++wakeups;
                    return pass;
                });
            }
            printf("pass: %d; wakeups: %d; elapsed: %d ms\n", pass, wakeups,
                    int((sc::now() - before) / std::chrono::milliseconds(1)));
            pass = false;
        };

        {
            // timed wait, let expire
            std::thread t(thread_fn, true);
            t.join();
        }

        {
            // timed wait, wake up explicitly after 1 second
            std::thread t(thread_fn, true);
            std::this_thread::sleep_for(std::chrono::seconds(1));
            {
                std::unique_lock<std::mutex> ml(mx);
                pass = true;
            }
            cv.notify_all();
            t.join();
        }

        {
            // non-timed wait, wake up explicitly after 1 second
            std::thread t(thread_fn, false);
            std::this_thread::sleep_for(std::chrono::seconds(1));
            {
                std::unique_lock<std::mutex> ml(mx);
                pass = true;
            }
            cv.notify_all();
            t.join();
        }
        return 0;
    }
    ```

    On builds based on non-affected threading models (e.g. POSIX on Linux,
    or winpthreads or MCF on Win32) the output is something like
    ```
    pass: 0; wakeups: 2; elapsed: 2000 ms
    pass: 1; wakeups: 2; elapsed: 991 ms
    pass: 1; wakeups: 2; elapsed: 996 ms
    ```

    while with the Win32 threading model we get
    ```
    pass: 0; wakeups: 1418; elapsed: 2000 ms
    pass: 1; wakeups: 479; elapsed: 988 ms
    pass: 1; wakeups: 2; elapsed: 992 ms
    ```
    (notice the huge number of wakeups in the timed wait cases only).

    This commit fixes the conversion, adjusting the final division by
    NSEC100_PER_SEC to use NSEC100_PER_MSEC instead (already defined in the
    file and not used in any other place, so probably just a typo).

    libgcc/ChangeLog:

            PR libgcc/113850
            * config/i386/gthr-win32-cond.c (__gthr_win32_abs_to_rel_time):
            fix absolute timespec to relative milliseconds count
            conversion (it incorrectly returned seconds instead of
            milliseconds); this avoids spurious wakeups in
            __gthr_win32_cond_timedwait

[Bug libgcc/113850] condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[cvs-commit at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=113850

--- Comment #5 from GCC Commits <cvs-commit at gcc dot gnu.org> ---
The releases/gcc-13 branch has been updated by Jonathan Yong
<jyong@gcc.gnu.org>:

https://gcc.gnu.org/g:b5def8fd08976fc2514426ecb1f263f13ba3e2af

commit r13-8337-gb5def8fd08976fc2514426ecb1f263f13ba3e2af
Author: Matteo Italia <matteo@mitalia.net>
Date:   Fri Feb 9 15:04:20 2024 +0100

    libgcc: fix Win32 CV abnormal spurious wakeups in timed wait [PR113850]

    Fix a typo in __gthr_win32_abs_to_rel_time that caused it to return a
    relative time in seconds instead of milliseconds. As a consequence,
    __gthr_win32_cond_timedwait called SleepConditionVariableCS with a
    1000x shorter timeout; this caused ~1000x more spurious wakeups in
    CV timed waits such as std::condition_variable::wait_for or wait_until,
    resulting generally in much higher CPU usage.

    This can be demonstrated by this sample program:

    ```

    int main() {
        std::condition_variable cv;
        std::mutex mx;
        bool pass = false;

        auto thread_fn = [&](bool timed) {
            int wakeups = 0;
            using sc = std::chrono::system_clock;
            auto before = sc::now();
            std::unique_lock<std::mutex> ml(mx);
            if (timed) {
                cv.wait_for(ml, std::chrono::seconds(2), [&]{
                    ++wakeups;
                    return pass;
                });
            } else {
                cv.wait(ml, [&]{
                    ++wakeups;
                    return pass;
                });
            }
            printf("pass: %d; wakeups: %d; elapsed: %d ms\n", pass, wakeups,
                    int((sc::now() - before) / std::chrono::milliseconds(1)));
            pass = false;
        };

        {
            // timed wait, let expire
            std::thread t(thread_fn, true);
            t.join();
        }

        {
            // timed wait, wake up explicitly after 1 second
            std::thread t(thread_fn, true);
            std::this_thread::sleep_for(std::chrono::seconds(1));
            {
                std::unique_lock<std::mutex> ml(mx);
                pass = true;
            }
            cv.notify_all();
            t.join();
        }

        {
            // non-timed wait, wake up explicitly after 1 second
            std::thread t(thread_fn, false);
            std::this_thread::sleep_for(std::chrono::seconds(1));
            {
                std::unique_lock<std::mutex> ml(mx);
                pass = true;
            }
            cv.notify_all();
            t.join();
        }
        return 0;
    }
    ```

    On builds based on non-affected threading models (e.g. POSIX on Linux,
    or winpthreads or MCF on Win32) the output is something like
    ```
    pass: 0; wakeups: 2; elapsed: 2000 ms
    pass: 1; wakeups: 2; elapsed: 991 ms
    pass: 1; wakeups: 2; elapsed: 996 ms
    ```

    while with the Win32 threading model we get
    ```
    pass: 0; wakeups: 1418; elapsed: 2000 ms
    pass: 1; wakeups: 479; elapsed: 988 ms
    pass: 1; wakeups: 2; elapsed: 992 ms
    ```
    (notice the huge number of wakeups in the timed wait cases only).

    This commit fixes the conversion, adjusting the final division by
    NSEC100_PER_SEC to use NSEC100_PER_MSEC instead (already defined in the
    file and not used in any other place, so probably just a typo).

    libgcc/ChangeLog:

            PR libgcc/113850
            * config/i386/gthr-win32-cond.c (__gthr_win32_abs_to_rel_time):
            fix absolute timespec to relative milliseconds count
            conversion (it incorrectly returned seconds instead of
            milliseconds); this avoids spurious wakeups in
            __gthr_win32_cond_timedwait

    (cherry picked from commit 05ad8fb55a55f1e201fd781c84682a7c0bbd4d97)

[Bug libgcc/113850] condition variables timed wait does a lot of spurious wakeups on Win32 threading implementation

[jyong at gcc dot gnu.org]

https://gcc.gnu.org/bugzilla/show_bug.cgi?id=113850

jyong at gcc dot gnu.org changed:

           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|---                         |FIXED
                 CC|                            |jyong at gcc dot gnu.org

--- Comment #6 from jyong at gcc dot gnu.org ---
Pushed the patch to master branch and 13.x.