From be8b3f5e9d4b91ec8dfcf028dddc6507bb4c0c2d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jo=C3=A3o=20Reis?= Date: Tue, 2 Jun 2015 20:02:55 +0100 Subject: [PATCH] win: wait for full timeout duration uv_poll should wait for at least the full timeout duration when there is nothing else to do. This was not happening because GetQueuedCompletionStatus can occasionally return up to 15ms early. The added test reproduces https://github.com/joyent/node/blob/d13d7f74d794340ac5e126cfb4ce507fe0f803d5/test/simple/test-timers-first-fire.js on libuv, being flaky before this fix. Fix: https://github.com/joyent/node/issues/8960 --- src/win/core.c | 130 +++++++++++++++++++++++++++++---------------- src/win/internal.h | 1 - src/win/timer.c | 9 +--- test/test-list.h | 2 + test/test-timer.c | 27 ++++++++++ 5 files changed, 114 insertions(+), 55 deletions(-) diff --git a/src/win/core.c b/src/win/core.c index de0483e1023..ba306ebc083 100644 --- a/src/win/core.c +++ b/src/win/core.c @@ -256,30 +256,48 @@ static void uv_poll(uv_loop_t* loop, DWORD timeout) { ULONG_PTR key; OVERLAPPED* overlapped; uv_req_t* req; + int repeat; + uint64_t timeout_time; - GetQueuedCompletionStatus(loop->iocp, - &bytes, - &key, - &overlapped, - timeout); + timeout_time = loop->time + timeout; - if (overlapped) { - /* Package was dequeued */ - req = uv_overlapped_to_req(overlapped); - uv_insert_pending_req(loop, req); + for (repeat = 0; ; repeat++) { + GetQueuedCompletionStatus(loop->iocp, + &bytes, + &key, + &overlapped, + timeout); - /* Some time might have passed waiting for I/O, - * so update the loop time here. - */ - uv_update_time(loop); - } else if (GetLastError() != WAIT_TIMEOUT) { - /* Serious error */ - uv_fatal_error(GetLastError(), "GetQueuedCompletionStatus"); - } else if (timeout > 0) { - /* GetQueuedCompletionStatus can occasionally return a little early. - * Make sure that the desired timeout is reflected in the loop time. - */ - uv__time_forward(loop, timeout); + if (overlapped) { + /* Package was dequeued */ + req = uv_overlapped_to_req(overlapped); + uv_insert_pending_req(loop, req); + + /* Some time might have passed waiting for I/O, + * so update the loop time here. + */ + uv_update_time(loop); + } else if (GetLastError() != WAIT_TIMEOUT) { + /* Serious error */ + uv_fatal_error(GetLastError(), "GetQueuedCompletionStatus"); + } else if (timeout > 0) { + /* GetQueuedCompletionStatus can occasionally return a little early. + * Make sure that the desired timeout target time is reached. + */ + uv_update_time(loop); + if (timeout_time > loop->time) { + timeout = (DWORD)(timeout_time - loop->time); + /* The first call to GetQueuedCompletionStatus should return very + * close to the target time and the second should reach it, but + * this is not stated in the documentation. To make sure a busy + * loop cannot happen, the timeout is increased exponentially + * starting on the third round. + */ + timeout += repeat ? (1 << (repeat - 1)) : 0; + continue; + } + } + break; } } @@ -290,33 +308,51 @@ static void uv_poll_ex(uv_loop_t* loop, DWORD timeout) { OVERLAPPED_ENTRY overlappeds[128]; ULONG count; ULONG i; - - success = pGetQueuedCompletionStatusEx(loop->iocp, - overlappeds, - ARRAY_SIZE(overlappeds), - &count, - timeout, - FALSE); - - if (success) { - for (i = 0; i < count; i++) { - /* Package was dequeued */ - req = uv_overlapped_to_req(overlappeds[i].lpOverlapped); - uv_insert_pending_req(loop, req); + int repeat; + uint64_t timeout_time; + + timeout_time = loop->time + timeout; + + for (repeat = 0; ; repeat++) { + success = pGetQueuedCompletionStatusEx(loop->iocp, + overlappeds, + ARRAY_SIZE(overlappeds), + &count, + timeout, + FALSE); + + if (success) { + for (i = 0; i < count; i++) { + /* Package was dequeued */ + req = uv_overlapped_to_req(overlappeds[i].lpOverlapped); + uv_insert_pending_req(loop, req); + } + + /* Some time might have passed waiting for I/O, + * so update the loop time here. + */ + uv_update_time(loop); + } else if (GetLastError() != WAIT_TIMEOUT) { + /* Serious error */ + uv_fatal_error(GetLastError(), "GetQueuedCompletionStatusEx"); + } else if (timeout > 0) { + /* GetQueuedCompletionStatus can occasionally return a little early. + * Make sure that the desired timeout target time is reached. + */ + uv_update_time(loop); + if (timeout_time > loop->time) { + timeout = (DWORD)(timeout_time - loop->time); + /* The first call to GetQueuedCompletionStatus should return very + * close to the target time and the second should reach it, but + * this is not stated in the documentation. To make sure a busy + * loop cannot happen, the timeout is increased exponentially + * starting on the third round. + */ + timeout += repeat ? (1 << (repeat - 1)) : 0; + continue; + } } - - /* Some time might have passed waiting for I/O, - * so update the loop time here. - */ - uv_update_time(loop); - } else if (GetLastError() != WAIT_TIMEOUT) { - /* Serious error */ - uv_fatal_error(GetLastError(), "GetQueuedCompletionStatusEx"); - } else if (timeout > 0) { - /* GetQueuedCompletionStatus can occasionally return a little early. - * Make sure that the desired timeout is reflected in the loop time. - */ - uv__time_forward(loop, timeout); + break; } } diff --git a/src/win/internal.h b/src/win/internal.h index 783f21af0fe..b2b929be53a 100644 --- a/src/win/internal.h +++ b/src/win/internal.h @@ -246,7 +246,6 @@ void uv_poll_endgame(uv_loop_t* loop, uv_poll_t* handle); void uv_timer_endgame(uv_loop_t* loop, uv_timer_t* handle); DWORD uv__next_timeout(const uv_loop_t* loop); -void uv__time_forward(uv_loop_t* loop, uint64_t msecs); void uv_process_timers(uv_loop_t* loop); diff --git a/src/win/timer.c b/src/win/timer.c index 0da541a2c86..27ca7716af6 100644 --- a/src/win/timer.c +++ b/src/win/timer.c @@ -34,13 +34,8 @@ void uv_update_time(uv_loop_t* loop) { uint64_t new_time = uv__hrtime(UV__MILLISEC); - if (new_time > loop->time) { - loop->time = new_time; - } -} - -void uv__time_forward(uv_loop_t* loop, uint64_t msecs) { - loop->time += msecs; + assert(new_time >= loop->time); + loop->time = new_time; } diff --git a/test/test-list.h b/test/test-list.h index 858a20af49c..d1eaf2ac920 100644 --- a/test/test-list.h +++ b/test/test-list.h @@ -154,6 +154,7 @@ TEST_DECLARE (timer_huge_repeat) TEST_DECLARE (timer_run_once) TEST_DECLARE (timer_from_check) TEST_DECLARE (timer_null_callback) +TEST_DECLARE (timer_early_check) TEST_DECLARE (idle_starvation) TEST_DECLARE (loop_handles) TEST_DECLARE (get_loadavg) @@ -522,6 +523,7 @@ TASK_LIST_START TEST_ENTRY (timer_run_once) TEST_ENTRY (timer_from_check) TEST_ENTRY (timer_null_callback) + TEST_ENTRY (timer_early_check) TEST_ENTRY (idle_starvation) diff --git a/test/test-timer.c b/test/test-timer.c index aba050fd64c..433aa1d0757 100644 --- a/test/test-timer.c +++ b/test/test-timer.c @@ -301,3 +301,30 @@ TEST_IMPL(timer_null_callback) { MAKE_VALGRIND_HAPPY(); return 0; } + + +static uint64_t timer_early_check_expected_time; + + +static void timer_early_check_cb(uv_timer_t* handle) { + uint64_t hrtime = uv_hrtime() / 1000000; + ASSERT(hrtime >= timer_early_check_expected_time); +} + + +TEST_IMPL(timer_early_check) { + uv_timer_t timer_handle; + const uint64_t timeout_ms = 10; + + timer_early_check_expected_time = uv_now(uv_default_loop()) + timeout_ms; + + ASSERT(0 == uv_timer_init(uv_default_loop(), &timer_handle)); + ASSERT(0 == uv_timer_start(&timer_handle, timer_early_check_cb, timeout_ms, 0)); + ASSERT(0 == uv_run(uv_default_loop(), UV_RUN_DEFAULT)); + + uv_close((uv_handle_t*) &timer_handle, NULL); + ASSERT(0 == uv_run(uv_default_loop(), UV_RUN_DEFAULT)); + + MAKE_VALGRIND_HAPPY(); + return 0; +}