timers: run nextTicks + MTQ between timers / immediates by Fishrock123 · Pull Request #22316 · nodejs/node

Fishrock123 · 2018-08-14T15:01:32Z

This is semver-major because it changes significant timing guarentees. The tests do not pass because of the changes to Immediates.

Do not run the core tests, they will stall!

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
documentation is changed or added
commit message follows commit guidelines

Refs: nodejs#22257

nodejs-github-bot · 2018-08-14T15:01:33Z

@Fishrock123 build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/559/pipeline

Fishrock123 · 2018-08-14T15:02:59Z

Ugh, how do I stop those?

Fishrock123 · 2018-08-14T15:04:45Z

CITGM (I think I did this right): https://ci.nodejs.org/view/Node.js-citgm/job/citgm-smoker/1506/

devsnek · 2018-08-14T15:08:42Z

@Fishrock123 I cancelled the Travis CI

apapirovski · 2018-08-14T15:14:15Z

So, I think this might need to be slightly more complicated to account for proper error handling but I'll need to confirm (if next tick queue throws). Will review and test in more detail before tomorrow morning.

Fishrock123 · 2018-08-14T15:22:54Z

Hmm, CITGM builds seem to have failed? @nodejs/build

Fishrock123 · 2018-08-14T15:34:35Z

Ok well, this patch allows the tests to run but also causes many async_hooks segfaults:

diff --git a/lib/timers.js b/lib/timers.js
index 6e473456b9..090ae60ff4 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -613,7 +613,11 @@ function processImmediate() {
 
     emitAfter(asyncId);
 
-    runNextTicks();
+    try {
+      runNextTicks();
+    } catch (e) {
+
+    }
 
     immediate = immediate._idleNext;
   }

[04:53|% 100|+ 2356|- 9]: Done

=== release test-common ===
Path: parallel/test-common
foo
bar
baz
test
foo
bar
baz
test
Error: async hook stack has become corrupted (actual: 22, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
12: 0x2
Command: out/Release/node /Users/Jeremiah/Documents/node/test/parallel/test-common.js
=== release test-domain-error-types ===
Path: parallel/test-domain-error-types
Error: async hook stack has become corrupted (actual: 3, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
12: 0x2
Command: out/Release/node /Users/Jeremiah/Documents/node/test/parallel/test-domain-error-types.js
=== release test-domain-multiple-errors ===
Path: parallel/test-domain-multiple-errors
Error: async hook stack has become corrupted (actual: 3, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
12: 0x2
Command: out/Release/node /Users/Jeremiah/Documents/node/test/parallel/test-domain-multiple-errors.js
=== release test-domain-stack ===
Path: parallel/test-domain-stack
Error: async hook stack has become corrupted (actual: 3, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
Command: out/Release/node /Users/Jeremiah/Documents/node/test/parallel/test-domain-stack.js
=== release test-process-fatal-exception-tick ===
Path: parallel/test-process-fatal-exception-tick
Error: async hook stack has become corrupted (actual: 6, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
Command: out/Release/node /Users/Jeremiah/Documents/node/test/parallel/test-process-fatal-exception-tick.js
=== release test-process-next-tick ===
Path: parallel/test-process-next-tick
Error: async hook stack has become corrupted (actual: 3, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
12: 0x2
Command: out/Release/node /Users/Jeremiah/Documents/node/test/parallel/test-process-next-tick.js
=== release test-timers-immediate-queue ===                                   t
Path: parallel/test-timers-immediate-queue
hit 1
assert.js:84
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected inputs to be strictly equal:

1 !== 1000

    at process.<anonymous> (/Users/Jeremiah/Documents/node/test/parallel/test-timers-immediate-queue.js:53:10)
    at process.emit (events.js:187:15)
Command: out/Release/node /Users/Jeremiah/Documents/node/test/parallel/test-timers-immediate-queue.js
=== release test ===
Path: addons/make-callback-recurse/test
Error: async hook stack has become corrupted (actual: 15, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
12: 0x2
Command: out/Release/node /Users/Jeremiah/Documents/node/test/addons/make-callback-recurse/test.js
=== release test ===
Path: addons-napi/test_make_callback_recurse/test
Error: async hook stack has become corrupted (actual: 15, expected: 0)
 1: 0x100005432 node::Environment::AsyncHooks::pop_async_id(double) [/Users/Jeremiah/Documents/node/out/Release/node]
 2: 0x10000f9cf node::InternalCallbackScope::Close() [/Users/Jeremiah/Documents/node/out/Release/node]
 3: 0x100035d37 node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 4: 0x100035f56 node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) [/Users/Jeremiah/Documents/node/out/Release/node]
 5: 0x100023080 node::Environment::CheckImmediate(uv_check_s*) [/Users/Jeremiah/Documents/node/out/Release/node]
 6: 0x10098e9dc uv__run_check [/Users/Jeremiah/Documents/node/out/Release/node]
 7: 0x100989f79 uv_run [/Users/Jeremiah/Documents/node/out/Release/node]
 8: 0x10003e166 node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
 9: 0x10003d51e node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) [/Users/Jeremiah/Documents/node/out/Release/node]
10: 0x10003d1cb node::Start(int, char**) [/Users/Jeremiah/Documents/node/out/Release/node]
11: 0x100001034 start [/Users/Jeremiah/Documents/node/out/Release/node]
Command: out/Release/node /Users/Jeremiah/Documents/node/test/addons-napi/test_make_callback_recurse/test.js
[04:53|% 100|+ 2356|-   9]: Done
make[1]: *** [jstest] Error 1
make: *** [test] Error 2

maclover7 · 2018-08-14T15:41:01Z

Hmm, CITGM builds seem to have failed?

@Fishrock123 This happens on architectures which are only supported by some versions of Node.js, but not the one that the CITGM job is testing (ex: Ubuntu 12.04). This is being tracked at nodejs/build#1430

Fishrock123 · 2018-11-06T18:45:59Z

Superseded by #22842

timers: run nextTicks + MTQ between timers / immediates

036bb52

Refs: nodejs#22257

Fishrock123 added wip Issues and PRs that are still a work in progress. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. semver-major PRs that contain breaking changes and should be released in the next major version. labels Aug 14, 2018

Fishrock123 requested a review from apapirovski August 14, 2018 15:01

nodejs-github-bot added the timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. label Aug 14, 2018

Fishrock123 mentioned this pull request Aug 14, 2018

MacroTask and MicroTask execution order #22257

Closed

apapirovski mentioned this pull request Sep 13, 2018

timers: run nextTicks after each immediate and timer #22842

Closed

3 tasks

Fishrock123 closed this Nov 6, 2018

Fishrock123 deleted the timers-immediates-run-nextticks branch November 6, 2018 18:46

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

timers: run nextTicks + MTQ between timers / immediates#22316

timers: run nextTicks + MTQ between timers / immediates#22316
Fishrock123 wants to merge 1 commit intonodejs:masterfrom
Fishrock123:timers-immediates-run-nextticks

Fishrock123 commented Aug 14, 2018

Uh oh!

nodejs-github-bot commented Aug 14, 2018

Uh oh!

Fishrock123 commented Aug 14, 2018

Uh oh!

Fishrock123 commented Aug 14, 2018 •

edited

Loading

Uh oh!

devsnek commented Aug 14, 2018

Uh oh!

apapirovski commented Aug 14, 2018 •

edited

Loading

Uh oh!

Fishrock123 commented Aug 14, 2018

Uh oh!

Fishrock123 commented Aug 14, 2018

Uh oh!

maclover7 commented Aug 14, 2018

Uh oh!

Fishrock123 commented Nov 6, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

Uh oh!

Conversation

Fishrock123 commented Aug 14, 2018

Checklist

Uh oh!

nodejs-github-bot commented Aug 14, 2018

Uh oh!

Fishrock123 commented Aug 14, 2018

Uh oh!

Fishrock123 commented Aug 14, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

devsnek commented Aug 14, 2018

Uh oh!

apapirovski commented Aug 14, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Fishrock123 commented Aug 14, 2018

Uh oh!

Fishrock123 commented Aug 14, 2018

Uh oh!

maclover7 commented Aug 14, 2018

Uh oh!

Fishrock123 commented Nov 6, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

Fishrock123 commented Aug 14, 2018 •

edited

Loading

apapirovski commented Aug 14, 2018 •

edited

Loading