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.

Fixes: nodejs/node-v0.x-archive#8960
PR-URL: #385
Reviewed-By: Alexis Campailla <alexis@janeasystems.com>
Reviewed-by: Bert Belder <bertbelder@gmail.com>

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;
   }
 }
 

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);
 
 

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;
 }
 
 

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)
 

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;
+}