From 5aac4c42da104c30d8f701f1042d61c2f06b7e6c Mon Sep 17 00:00:00 2001 From: Jeremy Whitlock Date: Thu, 23 Jul 2015 18:09:21 -0600 Subject: [PATCH] timers: fix processing of nested timers Whenever a timer is scheduled within another timer, there are a few known issues that we are fixing: * Whenever the timer being scheduled has the same timeout value as the outer timer, the newly created timer can fire on the same tick of the event loop instead of during the next tick of the event loop * Whenever a timer is added in another timer's callback, its underlying timer handle will be started with a timeout that is actually incorrect This commit consists of https://github.com/nodejs/node-v0.x-archive/pull/17203 and https://github.com/nodejs/node-v0.x-archive/pull/25763. Fixes: https://github.com/nodejs/node-v0.x-archive/issues/9333 Fixes: https://github.com/nodejs/node-v0.x-archive/issues/15447 Fixes: https://github.com/nodejs/node-v0.x-archive/issues/25607 Fixes: https://github.com/nodejs/node/issues/5426 PR-URL: https://github.com/nodejs/node/pull/3063 --- lib/timers.js | 8 +- test/common.js | 7 ++ .../parallel/test-timers-blocking-callback.js | 81 +++++++++++++++++++ test/parallel/test-timers-nested.js | 39 +++++++++ 4 files changed, 133 insertions(+), 2 deletions(-) create mode 100644 test/parallel/test-timers-blocking-callback.js create mode 100644 test/parallel/test-timers-nested.js diff --git a/lib/timers.js b/lib/timers.js index 9dbae32405cf6e..7379cfe3591e02 100644 --- a/lib/timers.js +++ b/lib/timers.js @@ -160,7 +160,7 @@ function listOnTimeout() { debug('timeout callback %d', msecs); var now = TimerWrap.now(); - debug('now: %s', now); + debug('now: %d', now); var diff, timer; while (timer = L.peek(list)) { @@ -169,7 +169,11 @@ function listOnTimeout() { // Check if this loop iteration is too early for the next timer. // This happens if there are more timers scheduled for later in the list. if (diff < msecs) { - this.start(msecs - diff, 0); + var timeRemaining = msecs - (TimerWrap.now() - timer._idleStart); + if (timeRemaining < 0) { + timeRemaining = 0; + } + this.start(timeRemaining, 0); debug('%d list wait because diff is %d', msecs, diff); return; } diff --git a/test/common.js b/test/common.js index f9d80ff1490e42..308411a13d3427 100644 --- a/test/common.js +++ b/test/common.js @@ -7,6 +7,7 @@ var os = require('os'); var child_process = require('child_process'); const stream = require('stream'); const util = require('util'); +const Timer = process.binding('timer_wrap').Timer; const testRoot = path.resolve(process.env.NODE_TEST_DIR || path.dirname(__filename)); @@ -484,3 +485,9 @@ exports.nodeProcessAborted = function nodeProcessAborted(exitCode, signal) { return expectedExitCodes.indexOf(exitCode) > -1; } }; + +exports.busyLoop = function busyLoop(time) { + var startTime = Timer.now(); + var stopTime = startTime + time; + while (Timer.now() < stopTime) {} +}; diff --git a/test/parallel/test-timers-blocking-callback.js b/test/parallel/test-timers-blocking-callback.js new file mode 100644 index 00000000000000..114c435a6af726 --- /dev/null +++ b/test/parallel/test-timers-blocking-callback.js @@ -0,0 +1,81 @@ +'use strict'; + +/* + * This is a regression test for https://github.com/joyent/node/issues/15447 + * and https://github.com/joyent/node/issues/9333. + * + * When a timer is added in another timer's callback, its underlying timer + * handle was started with a timeout that was actually incorrect. + * + * The reason was that the value that represents the current time was not + * updated between the time the original callback was called and the time + * the added timer was processed by timers.listOnTimeout. That lead the + * logic in timers.listOnTimeout to do an incorrect computation that made + * the added timer fire with a timeout of scheduledTimeout + + * timeSpentInCallback. + * + * This test makes sure that a timer added by another timer's callback + * fire with the expected timeout. + * + * It makes sure that it works when the timers list for a given timeout is + * empty (see testAddingTimerToEmptyTimersList) and when the timers list + * is not empty (see testAddingTimerToNonEmptyTimersList). + */ + +const assert = require('assert'); +const common = require('../common'); +const Timer = process.binding('timer_wrap').Timer; + +const TIMEOUT = 100; + +var nbBlockingCallbackCalls = 0; +var latestDelay = 0; +var timeCallbackScheduled = 0; + +function initTest() { + nbBlockingCallbackCalls = 0; + latestDelay = 0; + timeCallbackScheduled = 0; +} + +function blockingCallback(callback) { + ++nbBlockingCallbackCalls; + + if (nbBlockingCallbackCalls > 1) { + latestDelay = Timer.now() - timeCallbackScheduled; + // Even if timers can fire later than when they've been scheduled + // to fire, they should more than 50% later with a timeout of + // 100ms. Firing later than that would mean that we hit the regression + // highlighted in + // https://github.com/nodejs/node-v0.x-archive/issues/15447 and + // https://github.com/nodejs/node-v0.x-archive/issues/9333.. + assert(latestDelay < TIMEOUT * 1.5); + if (callback) + return callback(); + } else { + // block by busy-looping to trigger the issue + common.busyLoop(TIMEOUT); + + timeCallbackScheduled = Timer.now(); + setTimeout(blockingCallback, TIMEOUT); + } +} + +function testAddingTimerToEmptyTimersList(callback) { + initTest(); + // Call setTimeout just once to make sure the timers list is + // empty when blockingCallback is called. + setTimeout(blockingCallback.bind(null, callback), TIMEOUT); +} + +function testAddingTimerToNonEmptyTimersList() { + initTest(); + // Call setTimeout twice with the same timeout to make + // sure the timers list is not empty when blockingCallback is called. + setTimeout(blockingCallback, TIMEOUT); + setTimeout(blockingCallback, TIMEOUT); +} + +// Run the test for the empty timers list case, and then for the non-empty +// timers list one +testAddingTimerToEmptyTimersList(testAddingTimerToNonEmptyTimersList); diff --git a/test/parallel/test-timers-nested.js b/test/parallel/test-timers-nested.js new file mode 100644 index 00000000000000..17b397d33cd860 --- /dev/null +++ b/test/parallel/test-timers-nested.js @@ -0,0 +1,39 @@ +'use strict'; + +const assert = require('assert'); +const common = require('../common'); + +// Make sure we test 0ms timers, since they would had always wanted to run on +// the current tick, and greater than 0ms timers, for scenarios where the +// outer timer takes longer to complete than the delay of the nested timer. +// Since the process of recreating this is identical regardless of the timer +// delay, these scenarios are in one test. +const scenarios = [0, 100]; + +scenarios.forEach(function(delay) { + var nestedCalled = false; + + setTimeout(function A() { + // Create the nested timer with the same delay as the outer timer so that it + // gets added to the current list of timers being processed by + // listOnTimeout. + setTimeout(function B() { + nestedCalled = true; + }, delay); + + // Busy loop for the same timeout used for the nested timer to ensure that + // we are in fact expiring the nested timer. + common.busyLoop(delay); + + // The purpose of running this assert in nextTick is to make sure it runs + // after A but before the next iteration of the libuv event loop. + process.nextTick(function() { + assert.ok(!nestedCalled); + }); + + // Ensure that the nested callback is indeed called prior to process exit. + process.on('exit', function onExit() { + assert.ok(nestedCalled); + }); + }, delay); +});