Skip to content
This repository has been archived by the owner on Apr 22, 2023. It is now read-only.

setTimeout can’t work well after the process is blocked #15447

Closed
ilc-opensource opened this issue Apr 15, 2015 · 6 comments
Closed

setTimeout can’t work well after the process is blocked #15447

ilc-opensource opened this issue Apr 15, 2015 · 6 comments

Comments

@ilc-opensource
Copy link

node.js version: 4d9c81b (latest version), v0.10.33, node-v0.12.2
Platform: Ubuntu 14.04.1 LTS
Architecture: x86_64

var block = require('bindings')('hello'); // c++ addon
var a = function() {
  var timer = (new Date()).getTime();
  console.log('before block:'+timer);

  block.hello(); // will be block at some time

  timer = (new Date()).getTime();
  console.log('after block:'+timer);

  setTimeout(a, 5000);
};
a();

In the above script, function a will be executed very 5000 milliseconds if the block.hello is not blocked; But if the block.hello is blocked in c++ code, the time point which function a will be executed again is much larger than 5000 milliseconds after block.hello is unblocked. The following is the output of the above script:
1 before block:1429079335210
2 after block:1429079335210
3 before block:1429079340215
4 after block:1429079366741
5 before block:1429079398298
6 after block:1429079398299
7 before block:1429079403304
8 after block:1429079403304
Time interval between line2 and line 3 is 5005;
Time interval between line4 and line 5 is 31557;
Time interval between line6 and line 7 is 5005;

block.hello is blocked and unblocked between line 3 and line 4.

How to reproduce the issue?

  1. Download the tar file and decompress; https://www.dropbox.com/s/1y299n1y1uy69ij/node_js_debug.tar?dl=0
  2. cd node_js_debug;
  3. sh build.sh;
  4. node a.js;
  5. In another terminal, ./setFrontEndApp 123456; after a while, ./setFrontEndApp 0

How to fix?

I find we should recalculate now each time when processing the pending time events.

diff --git a/lib/timers.js b/lib/timers.js
index 68f87d7..c6af7f9 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -80,11 +80,10 @@ function listOnTimeout() {

   debug('timeout callback %d', msecs);

-  var now = Timer.now();
-  debug('now: %s', now);
-
   var diff, first, threw;
   while (first = L.peek(list)) {
+    var now = Timer.now();
+    debug('now: %s', now);
     diff = now - first._idleStart;
     if (diff < msecs) {
       list.start(msecs - diff, 0);
@obastemur
Copy link

@ilc-opensource It looks like a very good catch. After inspecting your scenario, I saw some other possible issues this patch might take care of.

Wondering how this patch will affect some existing applications. I'm going to further investigate on this.

@obastemur
Copy link

After spending some time on this issue, I didn't see any side effect because of the suggested fix. It's possible to implement a version of this suggested fix that doesn't call Timer.now on each loop. However, Timer.now call costs almost nothing comparing to look&feel and complexity of alternative implementation.

@ilc-opensource
Copy link
Author

Is it possible to put this patch to node.js repository? Then my partners and I don't need to patch node.js in our project.

@misterdjules
Copy link

This is also the same issue as #9333.

misterdjules pushed a commit to misterdjules/node that referenced this issue Apr 21, 2015
When a timer is added in another timer's callback, its underlying timer
handle will be started with a timeout that is actually incorrect.

The reason is that  the value that represents the current time is not
updated between the time the original callback is called and the time
the added timer is processed by timers.listOnTimeout. That leads the
logic in timers.listOnTimeout to do an incorrect computation that makes
the added timer fire with a timeout of scheduledTimeout +
timeSpentInCallback.

This change fixes that and make timers scheduled within other timers'
callbacks fire as expected.

Fixes nodejs#9333 and nodejs#15447.
@misterdjules
Copy link

Created a PR that fixes the issue: #17203. Thank you very much @ilc-opensource and @obastemur!

misterdjules pushed a commit to misterdjules/node that referenced this issue Apr 21, 2015
When a timer is added in another timer's callback, its underlying timer
handle will be started with a timeout that is actually incorrect.

The reason is that  the value that represents the current time is not
updated between the time the original callback is called and the time
the added timer is processed by timers.listOnTimeout. That leads the
logic in timers.listOnTimeout to do an incorrect computation that makes
the added timer fire with a timeout of scheduledTimeout +
timeSpentInCallback.

This change fixes that and make timers scheduled within other timers'
callbacks fire as expected.

Fixes nodejs#9333 and nodejs#15447.
misterdjules pushed a commit to misterdjules/node that referenced this issue Jun 17, 2015
When a timer is added in another timer's callback, its underlying timer
handle will be started with a timeout that is actually incorrect.

The reason is that  the value that represents the current time is not
updated between the time the original callback is called and the time
the added timer is processed by timers.listOnTimeout. That leads the
logic in timers.listOnTimeout to do an incorrect computation that makes
the added timer fire with a timeout of scheduledTimeout +
timeSpentInCallback.

This change fixes that and make timers scheduled within other timers'
callbacks fire as expected.

Fixes nodejs#9333 and nodejs#15447.
misterdjules pushed a commit to misterdjules/node that referenced this issue Jun 17, 2015
When a timer is added in another timer's callback, its underlying timer
handle will be started with a timeout that is actually incorrect.

The reason is that  the value that represents the current time is not
updated between the time the original callback is called and the time
the added timer is processed by timers.listOnTimeout. That leads the
logic in timers.listOnTimeout to do an incorrect computation that makes
the added timer fire with a timeout of scheduledTimeout +
timeSpentInCallback.

This change fixes that and make timers scheduled within other timers'
callbacks fire as expected.

Fixes nodejs#9333 and nodejs#15447.

PR: nodejs#17203
PR-URL: nodejs#17203
Reviewed-By: Fedor Indutny <fedor@indutny.com>
@misterdjules
Copy link

Fixed by d38e865, which will be available in the upcoming v0.10.39 and v0.12.5 releases.

Fishrock123 pushed a commit to Fishrock123/node that referenced this issue Jul 24, 2015
When a timer is added in another timer's callback, its underlying timer
handle will be started with a timeout that is actually incorrect.

The reason is that  the value that represents the current time is not
updated between the time the original callback is called and the time
the added timer is processed by timers.listOnTimeout. That leads the
logic in timers.listOnTimeout to do an incorrect computation that makes
the added timer fire with a timeout of scheduledTimeout +
timeSpentInCallback.

This change fixes that and make timers scheduled within other timers'
callbacks fire as expected.

Fixes: nodejs/node-v0.x-archive#9333
Fixes: nodejs/node-v0.x-archive#15447

PR: nodejs/node-v0.x-archive#17203
PR-URL: nodejs/node-v0.x-archive#17203
Reviewed-By: Fedor Indutny <fedor@indutny.com>

Conflicts:
	lib/timers.js
	test/common.js
whitlockjc added a commit to whitlockjc/node that referenced this issue Jul 15, 2016
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: nodejs#5426
PR-URL: nodejs#3063
whitlockjc added a commit to nodejs/node that referenced this issue Jul 15, 2016
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
evanlucas pushed a commit to nodejs/node that referenced this issue Jul 19, 2016
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
evanlucas pushed a commit to nodejs/node that referenced this issue Jul 20, 2016
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
jBarz pushed a commit to ibmruntimes/node that referenced this issue Nov 4, 2016
When a timer is added in another timer's callback, its underlying timer
handle will be started with a timeout that is actually incorrect.

The reason is that  the value that represents the current time is not
updated between the time the original callback is called and the time
the added timer is processed by timers.listOnTimeout. That leads the
logic in timers.listOnTimeout to do an incorrect computation that makes
the added timer fire with a timeout of scheduledTimeout +
timeSpentInCallback.

This change fixes that and make timers scheduled within other timers'
callbacks fire as expected.

Fixes nodejs#9333 and nodejs#15447.

PR: nodejs#17203
PR-URL: nodejs#17203
Reviewed-By: Fedor Indutny <fedor@indutny.com>
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants