From 8ae52923dee615fd6fb0b9db791b425129402428 Mon Sep 17 00:00:00 2001 From: Julien Gilli Date: Wed, 20 Aug 2014 00:08:32 -0700 Subject: [PATCH 1/3] timers: Avoid linear scan in _unrefActive. Before this change, _unrefActive would keep the unrefList sorted when adding a new timer. Because _unrefActive is called extremely frequently, this linear scan (O(n) at worse) would make _unrefActive show high in the list of contributors when profiling CPU usage. This commit changes _unrefActive so that it doesn't try to keep the unrefList sorted. The insertion thus happens in constant time. However, when a timer expires, unrefTimeout has to go through the whole unrefList because it's not ordered anymore. It is usually not large enough to have a significant impact on performance because: - Most of the time, the timers will be removed before unrefTimeout is called because their users (sockets mainly) cancel them when an I/O operation takes place. - If they're not, it means that some I/O took a long time to happen, and the initiator of subsequents I/O operations that would add more timers has to wait for them to complete. With this change, _unrefActive does not show as a significant contributor in CPU profiling reports anymore. Fixes: https://github.com/joyent/node/issues/8160 PR-URL: https://github.com/joyent/node/pull/8751 Signed-off-by: Timothy J Fontaine Conflicts: lib/timers.js --- lib/timers.js | 119 +++++++++++++--------- test/parallel/test-timers-unref-active.js | 51 ++++++++++ 2 files changed, 123 insertions(+), 47 deletions(-) create mode 100644 test/parallel/test-timers-unref-active.js diff --git a/lib/timers.js b/lib/timers.js index 494c599b3cdfa1..7ae1879b141664 100644 --- a/lib/timers.js +++ b/lib/timers.js @@ -483,32 +483,74 @@ function unrefTimeout() { debug('unrefTimer fired'); - var diff, domain, first, threw; - while (first = L.peek(unrefList)) { - diff = now - first._idleStart; + var timeSinceLastActive; + var nextTimeoutTime; + var nextTimeoutDuration; + var minNextTimeoutTime; + var itemToDelete; + + // The actual timer fired and has not yet been rearmed, + // let's consider its next firing time is invalid for now. + // It may be set to a relevant time in the future once + // we scanned through the whole list of timeouts and if + // we find a timeout that needs to expire. + unrefTimer.when = -1; - if (diff < first._idleTimeout) { - diff = first._idleTimeout - diff; - unrefTimer.start(diff, 0); - unrefTimer.when = now + diff; - debug('unrefTimer rescheudling for later'); - return; + // Iterate over the list of timeouts, + // call the onTimeout callback for those expired, + // and rearm the actual timer if the next timeout to expire + // will expire before the current actual timer. + var cur = unrefList._idlePrev; + while (cur != unrefList) { + timeSinceLastActive = now - cur._idleStart; + + if (timeSinceLastActive < cur._idleTimeout) { + // This timer hasn't expired yet, but check if its expiring time is + // earlier than the actual timer's expiring time + + nextTimeoutDuration = cur._idleTimeout - timeSinceLastActive; + nextTimeoutTime = now + nextTimeoutDuration; + if (minNextTimeoutTime == null || + (nextTimeoutTime < minNextTimeoutTime)) { + // We found a timeout that will expire earlier, + // store its next timeout time now so that we + // can rearm the actual timer accordingly when + // we scanned through the whole list. + minNextTimeoutTime = nextTimeoutTime; + } + + // This timer hasn't expired yet, skipping + cur = cur._idlePrev; + continue; } - L.remove(first); + // We found a timer that expired + var domain = cur.domain; - domain = first.domain; + if (!cur._onTimeout) continue; - if (!first._onTimeout) continue; - if (domain && domain._disposed) continue; + if (domain && domain._disposed) + continue; try { + var threw = true; + if (domain) domain.enter(); - threw = true; + + itemToDelete = cur; + // Move to the previous item before calling the _onTimeout callback, + // as it can mutate the list. + cur = cur._idlePrev; + + // Remove the timeout from the list because it expired. + L.remove(itemToDelete); + debug('unreftimer firing timeout'); - first._called = true; - first._onTimeout(); + itemToDelete._called = true; + itemToDelete._onTimeout(); + threw = false; + if (domain) domain.exit(); } finally { @@ -516,8 +558,15 @@ function unrefTimeout() { } } - debug('unrefList is empty'); - unrefTimer.when = -1; + // Rearm the actual timer with the timeout delay + // of the earliest timeout found. + if (minNextTimeoutTime != null) { + unrefTimer.start(minNextTimeoutTime - now, 0); + unrefTimer.when = minNextTimeoutTime; + debug('unrefTimer rescheduled'); + } else if (L.isEmpty(unrefList)) { + debug('unrefList is empty'); + } } @@ -543,38 +592,14 @@ exports._unrefActive = function(item) { var now = Timer.now(); item._idleStart = now; - if (L.isEmpty(unrefList)) { - debug('unrefList empty'); - L.append(unrefList, item); + var when = now + msecs; + // If the actual timer is set to fire too late, or not set to fire at all, + // we need to make it fire earlier + if (unrefTimer.when === -1 || unrefTimer.when > when) { unrefTimer.start(msecs, 0); - unrefTimer.when = now + msecs; + unrefTimer.when = when; debug('unrefTimer scheduled'); - return; - } - - var when = now + msecs; - - debug('unrefList find where we can insert'); - - var cur, them; - - for (cur = unrefList._idlePrev; cur != unrefList; cur = cur._idlePrev) { - them = cur._idleStart + cur._idleTimeout; - - if (when < them) { - debug('unrefList inserting into middle of list'); - - L.append(cur, item); - - if (unrefTimer.when > when) { - debug('unrefTimer is scheduled to fire too late, reschedule'); - unrefTimer.start(msecs, 0); - unrefTimer.when = when; - } - - return; - } } debug('unrefList append to end'); diff --git a/test/parallel/test-timers-unref-active.js b/test/parallel/test-timers-unref-active.js new file mode 100644 index 00000000000000..08f28b0153fecb --- /dev/null +++ b/test/parallel/test-timers-unref-active.js @@ -0,0 +1,51 @@ +'use strict'; + +/* + * This test is aimed at making sure that unref timers queued with + * timers._unrefActive work correctly. + * + * Basically, it queues one timer in the unref queue, and then queues + * it again each time its timeout callback is fired until the callback + * has been called ten times. + * + * At that point, it unenrolls the unref timer so that its timeout callback + * is not fired ever again. + * + * Finally, a ref timeout is used with a delay large enough to make sure that + * all 10 timeouts had the time to expire. + */ + +const common = require('../common'); +const timers = require('timers'); +const assert = require('assert'); + +var someObject = {}; +var nbTimeouts = 0; + +/* + * libuv 0.10.x uses GetTickCount on Windows to implement timers, which uses + * system's timers whose resolution is between 10 and 16ms. See + * http://msdn.microsoft.com/en-us/library/windows/desktop/ms724408.aspx + * for more information. That's the lowest resolution for timers across all + * supported platforms. We're using it as the lowest common denominator, + * and thus expect 5 timers to be able to fire in under 100 ms. + */ +const N = 5; +const TEST_DURATION = 100; + +timers.unenroll(someObject); +timers.enroll(someObject, 1); + +someObject._onTimeout = function _onTimeout() { + ++nbTimeouts; + + if (nbTimeouts === N) timers.unenroll(someObject); + + timers._unrefActive(someObject); +}; + +timers._unrefActive(someObject); + +setTimeout(function() { + assert.equal(nbTimeouts, N); +}, TEST_DURATION); From 27b5b0e67eea7d761061ef706948433552c5c9a4 Mon Sep 17 00:00:00 2001 From: Julien Gilli Date: Thu, 18 Dec 2014 15:36:21 -0800 Subject: [PATCH 2/3] timers: don't mutate unref list while iterating it Commit 934bfe23a16556d05bfb1844ef4d53e8c9887c3d had introduced a regression where node would crash trying to access a null unref timer if a given unref timer's callback would remove other unref timers set to fire in the future. More generally, it makes the unrefTimeout function more solid by not mutating the unrefList while traversing it. Fixes: https://github.com/joyent/node/issues/8897 PR-URL: https://github.com/joyent/node/pull/8905 Reviewed-By: Timothy J Fontaine Reviewed-By: Colin Ihrig Conflicts: lib/timers.js --- lib/timers.js | 81 ++++++++++--------- ...imeout-removes-other-socket-unref-timer.js | 50 ++++++++++++ ...emove-other-unref-timers-only-one-fires.js | 41 ++++++++++ ...-timers-unref-remove-other-unref-timers.js | 33 ++++++++ 4 files changed, 169 insertions(+), 36 deletions(-) create mode 100644 test/parallel/test-timers-socket-timeout-removes-other-socket-unref-timer.js create mode 100644 test/parallel/test-timers-unref-remove-other-unref-timers-only-one-fires.js create mode 100644 test/parallel/test-timers-unref-remove-other-unref-timers.js diff --git a/lib/timers.js b/lib/timers.js index 7ae1879b141664..82ac15681642c4 100644 --- a/lib/timers.js +++ b/lib/timers.js @@ -477,6 +477,39 @@ exports.clearImmediate = function(immediate) { var unrefList, unrefTimer; +function _makeTimerTimeout(timer) { + var domain = timer.domain; + var msecs = timer._idleTimeout; + + // Timer has been unenrolled by another timer that fired at the same time, + // so don't make it timeout. + if (!msecs || msecs < 0) + return; + + if (!timer._onTimeout) + return; + + if (domain && domain._disposed) + return; + + try { + var threw = true; + + if (domain) domain.enter(); + + debug('unreftimer firing timeout'); + L.remove(timer); + timer._called = true; + timer._onTimeout(); + + threw = false; + + if (domain) + domain.exit(); + } finally { + if (threw) process.nextTick(unrefTimeout); + } +} function unrefTimeout() { var now = Timer.now(); @@ -487,7 +520,7 @@ function unrefTimeout() { var nextTimeoutTime; var nextTimeoutDuration; var minNextTimeoutTime; - var itemToDelete; + var timersToTimeout = []; // The actual timer fired and has not yet been rearmed, // let's consider its next firing time is invalid for now. @@ -518,45 +551,21 @@ function unrefTimeout() { // we scanned through the whole list. minNextTimeoutTime = nextTimeoutTime; } - - // This timer hasn't expired yet, skipping - cur = cur._idlePrev; - continue; + } else { + // We found a timer that expired. Do not call its _onTimeout callback + // right now, as it could mutate any item of the list (including itself). + // Instead, add it to another list that will be processed once the list + // of current timers has been fully traversed. + timersToTimeout.push(cur); } - // We found a timer that expired - var domain = cur.domain; - - if (!cur._onTimeout) continue; - - if (domain && domain._disposed) - continue; - - try { - var threw = true; - - if (domain) domain.enter(); - - itemToDelete = cur; - // Move to the previous item before calling the _onTimeout callback, - // as it can mutate the list. - cur = cur._idlePrev; - - // Remove the timeout from the list because it expired. - L.remove(itemToDelete); - - debug('unreftimer firing timeout'); - itemToDelete._called = true; - itemToDelete._onTimeout(); + cur = cur._idlePrev; + } - threw = false; + var nbTimersToTimeout = timersToTimeout.length; + for (var timerIdx = 0; timerIdx < nbTimersToTimeout; ++timerIdx) + _makeTimerTimeout(timersToTimeout[timerIdx]); - if (domain) - domain.exit(); - } finally { - if (threw) process.nextTick(unrefTimeout); - } - } // Rearm the actual timer with the timeout delay // of the earliest timeout found. diff --git a/test/parallel/test-timers-socket-timeout-removes-other-socket-unref-timer.js b/test/parallel/test-timers-socket-timeout-removes-other-socket-unref-timer.js new file mode 100644 index 00000000000000..081688cfa5e812 --- /dev/null +++ b/test/parallel/test-timers-socket-timeout-removes-other-socket-unref-timer.js @@ -0,0 +1,50 @@ +'use strict'; + +/* + * This test is a regression test for joyent/node#8897. + */ + +const common = require('../common'); +const assert = require('assert'); +const net = require('net'); + +const clients = []; + +const server = net.createServer(function onClient(client) { + clients.push(client); + + if (clients.length === 2) { + /* + * Enroll two timers, and make the one supposed to fire first + * unenroll the other one supposed to fire later. This mutates + * the list of unref timers when traversing it, and exposes the + * original issue in joyent/node#8897. + */ + clients[0].setTimeout(1, function onTimeout() { + clients[1].setTimeout(0); + clients[0].end(); + clients[1].end(); + }); + + // Use a delay that is higher than the lowest timer resolution accross all + // supported platforms, so that the two timers don't fire at the same time. + clients[1].setTimeout(50); + } +}); + +server.listen(common.PORT, common.localhostIPv4, function() { + var nbClientsEnded = 0; + + function addEndedClient(client) { + ++nbClientsEnded; + if (nbClientsEnded === 2) { + server.close(); + } + }; + + const client1 = net.connect({ port: common.PORT }); + client1.on('end', addEndedClient); + + const client2 = net.connect({ port: common.PORT }); + client2.on('end', addEndedClient); +}); diff --git a/test/parallel/test-timers-unref-remove-other-unref-timers-only-one-fires.js b/test/parallel/test-timers-unref-remove-other-unref-timers-only-one-fires.js new file mode 100644 index 00000000000000..aead4a4e7def64 --- /dev/null +++ b/test/parallel/test-timers-unref-remove-other-unref-timers-only-one-fires.js @@ -0,0 +1,41 @@ +'use strict'; + +/* + * The goal of this test is to make sure that, after the regression introduced + * by 934bfe23a16556d05bfb1844ef4d53e8c9887c3d, the fix preserves the following + * behavior of unref timers: if two timers are scheduled to fire at the same + * time, if one unenrolls the other one in its _onTimeout callback, the other + * one will *not* fire. + * + * This behavior is a private implementation detail and should not be + * considered public interface. + */ +const common = require('../common'); +const timers = require('timers'); +const assert = require('assert'); + +var nbTimersFired = 0; + +const foo = { + _onTimeout: function() { + ++nbTimersFired; + timers.unenroll(bar); + } +}; + +const bar = { + _onTimeout: function() { + ++nbTimersFired; + timers.unenroll(foo); + } +}; + +timers.enroll(bar, 1); +timers._unrefActive(bar); + +timers.enroll(foo, 1); +timers._unrefActive(foo); + +setTimeout(function() { + assert.notEqual(nbTimersFired, 2); +}, 20); diff --git a/test/parallel/test-timers-unref-remove-other-unref-timers.js b/test/parallel/test-timers-unref-remove-other-unref-timers.js new file mode 100644 index 00000000000000..f727d5f86fd7b3 --- /dev/null +++ b/test/parallel/test-timers-unref-remove-other-unref-timers.js @@ -0,0 +1,33 @@ +'use strict'; + +/* + * This test is a regression test for joyent/node#8897. + * + * It tests some private implementation details that should not be + * considered public interface. + */ +const common = require('../common'); +const assert = require('assert'); +const timers = require('timers'); + +const foo = { + _onTimeout: assert.fail +}; + +const bar = { + _onTimeout: common.mustCall(function() { + timers.unenroll(foo); + }) +}; + +// We use timers with expiration times that are sufficiently apart to make +// sure that they're not fired at the same time on platforms where the timer +// resolution is a bit coarse (e.g Windows with a default resolution of ~15ms). +timers.enroll(bar, 1); +timers._unrefActive(bar); + +timers.enroll(foo, 50); +timers._unrefActive(foo); + +// Keep the process open. +setTimeout(function() {}, 100); From 81047592f465d9471f770ac46043524fc6c6ce69 Mon Sep 17 00:00:00 2001 From: Jeremiah Senkpiel Date: Thu, 27 Aug 2015 15:56:46 -0400 Subject: [PATCH 3/3] timers: minor _unrefActive fixes and improvements This commit addresses most of the review comments in https://github.com/nodejs/node/pull/2540, which are kept in this separate commit so as to better preserve the prior two patches as they landed in 0.12. This commit: - Fixes a bug with unrefActive timers and disposed domains. - Fixes a bug with unrolling an unrefActive timer from another. - Adds a test for both above bugs. - Improves check logic, making it stricter, simpler, or both. - Optimizes nicer with a smaller, separate function for the try/catch. --- lib/timers.js | 39 +++++++++------- ...timers-unref-active-unenrolled-disposed.js | 46 +++++++++++++++++++ 2 files changed, 68 insertions(+), 17 deletions(-) create mode 100644 test/parallel/test-timers-unref-active-unenrolled-disposed.js diff --git a/lib/timers.js b/lib/timers.js index 82ac15681642c4..e3d0eb152490f9 100644 --- a/lib/timers.js +++ b/lib/timers.js @@ -481,31 +481,36 @@ function _makeTimerTimeout(timer) { var domain = timer.domain; var msecs = timer._idleTimeout; + L.remove(timer); + // Timer has been unenrolled by another timer that fired at the same time, // so don't make it timeout. - if (!msecs || msecs < 0) + if (msecs <= 0) return; if (!timer._onTimeout) return; - if (domain && domain._disposed) - return; + if (domain) { + if (domain._disposed) + return; - try { - var threw = true; + domain.enter(); + } - if (domain) domain.enter(); + debug('unreftimer firing timeout'); + timer._called = true; + _runOnTimeout(timer); - debug('unreftimer firing timeout'); - L.remove(timer); - timer._called = true; - timer._onTimeout(); + if (domain) + domain.exit(); +} +function _runOnTimeout(timer) { + var threw = true; + try { + timer._onTimeout(); threw = false; - - if (domain) - domain.exit(); } finally { if (threw) process.nextTick(unrefTimeout); } @@ -519,7 +524,7 @@ function unrefTimeout() { var timeSinceLastActive; var nextTimeoutTime; var nextTimeoutDuration; - var minNextTimeoutTime; + var minNextTimeoutTime = TIMEOUT_MAX; var timersToTimeout = []; // The actual timer fired and has not yet been rearmed, @@ -534,7 +539,7 @@ function unrefTimeout() { // and rearm the actual timer if the next timeout to expire // will expire before the current actual timer. var cur = unrefList._idlePrev; - while (cur != unrefList) { + while (cur !== unrefList) { timeSinceLastActive = now - cur._idleStart; if (timeSinceLastActive < cur._idleTimeout) { @@ -543,7 +548,7 @@ function unrefTimeout() { nextTimeoutDuration = cur._idleTimeout - timeSinceLastActive; nextTimeoutTime = now + nextTimeoutDuration; - if (minNextTimeoutTime == null || + if (minNextTimeoutTime === TIMEOUT_MAX || (nextTimeoutTime < minNextTimeoutTime)) { // We found a timeout that will expire earlier, // store its next timeout time now so that we @@ -569,7 +574,7 @@ function unrefTimeout() { // Rearm the actual timer with the timeout delay // of the earliest timeout found. - if (minNextTimeoutTime != null) { + if (minNextTimeoutTime !== TIMEOUT_MAX) { unrefTimer.start(minNextTimeoutTime - now, 0); unrefTimer.when = minNextTimeoutTime; debug('unrefTimer rescheduled'); diff --git a/test/parallel/test-timers-unref-active-unenrolled-disposed.js b/test/parallel/test-timers-unref-active-unenrolled-disposed.js new file mode 100644 index 00000000000000..ac22cd6e6a7144 --- /dev/null +++ b/test/parallel/test-timers-unref-active-unenrolled-disposed.js @@ -0,0 +1,46 @@ +'use strict'; + +// https://github.com/nodejs/node/pull/2540/files#r38231197 + +const common = require('../common'); +const timers = require('timers'); +const assert = require('assert'); +const domain = require('domain'); + +// Crazy stuff to keep the process open, +// then close it when we are actually done. +const TEST_DURATION = common.platformTimeout(100); +const keepOpen = setTimeout(function() { + throw new Error('Test timed out. keepOpen was not canceled.'); +}, TEST_DURATION); + +const endTest = makeTimer(2); + +const someTimer = makeTimer(1); +someTimer.domain = domain.create(); +someTimer.domain.dispose(); +someTimer._onTimeout = function() { + throw new Error('someTimer was not supposed to fire!'); +}; + +endTest._onTimeout = common.mustCall(function() { + assert.strictEqual(someTimer._idlePrev, null); + assert.strictEqual(someTimer._idleNext, null); + clearTimeout(keepOpen); +}); + +const cancelsTimer = makeTimer(1); +cancelsTimer._onTimeout = common.mustCall(function() { + someTimer._idleTimeout = 0; +}); + +timers._unrefActive(cancelsTimer); +timers._unrefActive(someTimer); +timers._unrefActive(endTest); + +function makeTimer(msecs) { + const timer = {}; + timers.unenroll(timer); + timers.enroll(timer, msecs); + return timer; +}