Skip to content

Commit

Permalink
timers: fix processing of nested timers
Browse files Browse the repository at this point in the history
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
nodejs/node-v0.x-archive#17203 and
nodejs/node-v0.x-archive#25763.

Fixes: nodejs/node-v0.x-archive#9333
Fixes: nodejs/node-v0.x-archive#15447
Fixes: nodejs/node-v0.x-archive#25607
Fixes: #5426
PR-URL: #3063
  • Loading branch information
whitlockjc committed Jul 15, 2016
1 parent 2fe277a commit 5aac4c4
Show file tree
Hide file tree
Showing 4 changed files with 133 additions and 2 deletions.
8 changes: 6 additions & 2 deletions lib/timers.js
Original file line number Diff line number Diff line change
Expand Up @@ -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)) {
Expand All @@ -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;
}
Expand Down
7 changes: 7 additions & 0 deletions test/common.js
Original file line number Diff line number Diff line change
Expand Up @@ -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));
Expand Down Expand Up @@ -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) {}
};
81 changes: 81 additions & 0 deletions test/parallel/test-timers-blocking-callback.js
Original file line number Diff line number Diff line change
@@ -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);
39 changes: 39 additions & 0 deletions test/parallel/test-timers-nested.js
Original file line number Diff line number Diff line change
@@ -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);
});

3 comments on commit 5aac4c4

@Fishrock123
Copy link
Contributor

@Fishrock123 Fishrock123 commented on 5aac4c4 Jul 15, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed-By: @misterdjules
Reviewed-By: Jeremiah Senkpiel @Fishrock123

(I used the GitHub handles because I don't have the full one for Julien off-hand.)

@whitlockjc
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @Fishrock123. I really apologize for forgetting this part.

@whitlockjc
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thankfully @evanlucas pointed me to this for next time: https://github.com/evanlucas/core-validate-commit

Please sign in to comment.