diff --git a/lib/timers.js b/lib/timers.js index 494c599b3cdfa1..4ae6cf4b8c7997 100644 --- a/lib/timers.js +++ b/lib/timers.js @@ -57,10 +57,19 @@ function listOnTimeout() { debug('timeout callback %d', msecs); var now = Timer.now(); - debug('now: %s', now); + debug('now: %d', now); var diff, first, threw; while (first = L.peek(list)) { + // If the previous iteration caused a timer to be added, + // update the value of "now" so that timing computations are + // done correctly. See test/parallel/test-timers-blocking-callback.js + // for more information. + if (now < first._idleStart) { + now = Timer.now(); + debug('now: %d', now); + } + diff = now - first._idleStart; if (diff < msecs) { list.start(msecs - diff, 0); diff --git a/test/common.js b/test/common.js index 1a56449917be9c..1ee3d29e79b280 100644 --- a/test/common.js +++ b/test/common.js @@ -453,3 +453,9 @@ exports.fileExists = function(pathname) { return false; } }; + +exports.busyLoop = function busyLoop(time) { + var startTime = Date.now(); + var stopTime = startTime + time; + while (Date.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..72ce4b3bd3ebe8 --- /dev/null +++ b/test/parallel/test-timers-blocking-callback.js @@ -0,0 +1,80 @@ +'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 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 = Date.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/joyent/node/issues/15447 and + // https://github.com/joyent/node/issues/9333. + assert(latestDelay < TIMEOUT * 1.5); + if (callback) + return callback(); + } else { + // block by busy-looping to trigger the issue + common.busyLoop(TIMEOUT); + + timeCallbackScheduled = Date.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);