Skip to content

async_hooks initial implementation#8531

Closed
trevnorris wants to merge 40 commits intonodejs:masterfrom
trevnorris:async-wrap-eps-impl
Closed

async_hooks initial implementation#8531
trevnorris wants to merge 40 commits intonodejs:masterfrom
trevnorris:async-wrap-eps-impl

Conversation

@trevnorris
Copy link
Contributor

@trevnorris trevnorris commented Sep 14, 2016

Checklist
  • make -j4 test (UNIX), or vcbuild test nosign (Windows) passes
  • tests and/or benchmarks are included
  • documentation is changed or added
  • commit message follows commit guidelines
Affected core subsystem(s)

async_wrap, async_hooks

Description of change

This is the initial implementation of the async_hooks API as outlined in nodejs/node-eps#18. There was a more extensive API initially proposed, but after completing all those features I found it had substantial performance impact. So I limited the scope of the proposal (the EP has just been updated to reflect those changes) and implemented them. I left the feature complete implementation in its own commit, and stripped it down in a following commit. So that reviewers could see how it was being done and possibly have some suggestions about how to improve that performance hit.

The biggest hit comes from tracking process.nextTick() calls. Here's a minimal http server with hooks:

const print = process._rawDebug;

require('async_hooks').createHook({
  init: (id, type) => print('init:   ', id, type),
  before: (id) =>     print('before: ', id),
  after: (id) =>      print('after:  ', id),
  destroy: (id) =>    print('destroy:', id),
}).enable();

http.createServer((req, res) => {
  res.end('bye');
}).listen(8080);

And here is the async call stack for a single request completion:

init:    21 TCPWRAP
before:  2
init:    22 TickObject
after:   2
before:  22
after:   22
destroy: 22
before:  6
init:    23 TIMERWRAP
init:    24 TickObject
init:    25 TickObject
after:   6
before:  6
init:    26 TickObject
after:   6
before:  6
after:   6
before:  24
init:    27 TickObject
after:   24
destroy: 24
before:  25
after:   25
destroy: 25
before:  26
init:    28 TickObject
after:   26
destroy: 26
before:  27
init:    29 TickObject
init:    30 TickObject
init:    31 TickObject
after:   27
destroy: 27
before:  28
after:   28
destroy: 28
before:  29
after:   29
destroy: 29
before:  30
after:   30
destroy: 30
before:  31
after:   31
destroy: 31
before:  21
init:    32 TickObject
init:    33 TickObject
after:   21
before:  32
after:   32
destroy: 32
before:  33
after:   33
destroy: 33
before:  21
after:   21
destroy: 21
before:  23
after:   23
destroy: 23

As you can see, the TickObject calls dominate the stack. So even doing something as minimal as generating a new id for each TickObject can be seen when stressing out a process.

The biggest functionality hit that was taken is that the hooks don't propagate with the call stack anymore. Instead once you run disable() they are removed from the global pool of hooks to process, and won't be run again until the user runs enable().

Would appreciate any feedback on how to reintroduce what was removed. Though even stripped down I'm seeing a few percent performance drop w/o using any callbacks. My goal was to have zero (or maybe better said is indistinguishable) overhead if the API wasn't being used. IMO that should be the first thing addressed.

Known Issues

This PR still has some bugs to fix. Here is a list:

  • HTTPParser doesn't propagate parent id properly
  • Reused resources aren't reassigned a new UID
  • Have potential for leak if references are made to handles that require GC for destroy() call

@nodejs-github-bot nodejs-github-bot added build Issues and PRs related to build files or the CI. c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. module Issues and PRs related to the module subsystem. timers Issues and PRs related to the timers subsystem / setImmediate, setInterval, setTimeout. async_hooks Issues and PRs related to the async hooks subsystem. labels Sep 14, 2016
@Fishrock123
Copy link
Contributor

@Fishrock123
Copy link
Contributor

cc @nodejs/ctc & @AndreasMadsen

Copy link
Member

@jasnell jasnell left a comment

Choose a reason for hiding this comment

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

Looking very good so far. Left a couple minor comments but otherwise this is +1. Will have to do a more detailed review later on.

Copy link
Member

Choose a reason for hiding this comment

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

Ugh. Can we please consider making this a constant in os.constants rather than a method?

Copy link
Contributor

Choose a reason for hiding this comment

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

It's been a method for a long time, I see little reason to get rid of it.

Copy link
Member

Choose a reason for hiding this comment

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

Given that there's not a clear concept of unsigned integers in js, perhaps this should say that it must be a non-negative integer?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Are you specifically referring to the bit that's interpreted differently depending on whether it's unsigned or not? I am using the definition of

capable of representing only non-negative integers

I'll change the wording if you like, but personally don't think it's necessary.

Copy link
Member

@AndreasMadsen AndreasMadsen left a comment

Choose a reason for hiding this comment

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

Looks really good, but it's very tough to review.

I think most issues are documented in the TODOs, I found only one bug. Besides that:

  • I think you should create an async_hooks binding. Having the current_id, async_id, etc. counters in async_wrap seams to only be for historic reasons.
  • It appears that the C++ Embedder API hasn't been implemented.
  • Also if it helps, you herby have permission to steal tests from my async_hook module.

Copy link
Member

Choose a reason for hiding this comment

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

Just in case the id do get too high it might be a good idea to say it must be an unsigned safe integer. Otherwise it will be confusing when 9007199254740992 throw an error.

Copy link
Member

@AndreasMadsen AndreasMadsen Sep 15, 2016

Choose a reason for hiding this comment

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

I haven't checked, but I would assume that checking active_hooks_array[i][init_symbol] !== undefined is faster than looking up the type.

Copy link
Member

@AndreasMadsen AndreasMadsen Sep 15, 2016

Choose a reason for hiding this comment

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

I understand there are performance reasons for not checking with isSafeInteger. But I find it just as likely that I would pass a wrong argument to emitBefore as I would pass a wrong argument to emitInit.

Copy link
Member

Choose a reason for hiding this comment

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

Yeah, what is prevId about? It is not even used in emitAfter. I think you removed it from the documentation too.

Copy link
Member

Choose a reason for hiding this comment

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

We should document that hook.disable().enable() can change the order.

lib/timers.js Outdated
Copy link
Member

@AndreasMadsen AndreasMadsen Sep 15, 2016

Choose a reason for hiding this comment

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

hooks stack

Can you elaborate on what the hooks stack is.

Copy link
Member

@AndreasMadsen AndreasMadsen Sep 15, 2016

Choose a reason for hiding this comment

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

Just want to make sure you didn't forget this.

Copy link
Member

@AndreasMadsen AndreasMadsen Sep 15, 2016

Choose a reason for hiding this comment

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

Should be Environment::AsyncHooks::kAfter

kinda happy I found an error, halfway through I was starting to think it was perfect :)

Copy link
Member

Choose a reason for hiding this comment

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

I'm not so strong on my C++ V8, what does this mean? I assume it is similar to:

if (ret.IsEmpty()) {
  return ret;
}

but before that was checked/called after the post hook.

src/node.cc Outdated
Copy link
Member

Choose a reason for hiding this comment

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

How is before and after called now. The propused API is that MakeCallback(..., async_id, ...) will call before and after but this doesn't appear to do that.

lib/timers.js Outdated
Copy link
Contributor

Choose a reason for hiding this comment

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

Maybe just define this in the while where the code runs?

Copy link
Contributor

@Fishrock123 Fishrock123 left a comment

Choose a reason for hiding this comment

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

Seems good, left some timers review.

(Hopefully I'm using this new review thing correctly?)

lib/timers.js Outdated
Copy link
Contributor

Choose a reason for hiding this comment

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

This should actually be in insert() I think.

Copy link
Contributor

Choose a reason for hiding this comment

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

Note: some sort of ID retention needs to be done for intervals...

(And maybe even timers that are re-inserted...)

lib/timers.js Outdated
Copy link
Contributor

Choose a reason for hiding this comment

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

This should be in unenroll().

lib/timers.js Outdated
Copy link
Contributor

Choose a reason for hiding this comment

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

Same loop/variable comment as in listOnTimeout()

Copy link
Contributor

Choose a reason for hiding this comment

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

Is this comment still valid since after() no longer has a didThrow?

@joshgav
Copy link
Contributor

joshgav commented Sep 16, 2016

/cc @nodejs/diagnostics @digitalinfinity

Copy link
Contributor

@Fishrock123 Fishrock123 left a comment

Choose a reason for hiding this comment

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

Trying to get dprof running properly on this. Progress is good, but representing timers properly with this is... difficult.

I think destory() may need to have an extra parameter for resources that may be reused in the future.

For example, someone may unenroll a non-repeating timer, keep it alive, and re-enroll it later.

A quicker example of that would be any timer that gets its duration updated.

lib/timers.js Outdated
Copy link
Contributor

Choose a reason for hiding this comment

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

also needs roughly this:

if (!timer._repeat && async_hook_fields[kDestroy])
        async_hooks.emitDestroy(timer._asyncId);

lib/timers.js Outdated
Copy link
Contributor

Choose a reason for hiding this comment

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

Note: some sort of ID retention needs to be done for intervals...

(And maybe even timers that are re-inserted...)

@Qard
Copy link
Member

Qard commented Sep 18, 2016

@Fishrock123 Do you think it'd be more generically solvable with this? nodejs/node-eps#18 (comment)

@Fishrock123
Copy link
Contributor

Fishrock123 commented Sep 18, 2016

@Qard hmmmm, could be. Wouldn't you also need an unqueue or finish then?

That could solve the TIMERWRAP - Timeout disparity though. Edit2: Maybe?

For example, take interval.dprof.json and look at the rendered version by:

npm i -g dprof
cat interval.dprof.json | dprof

(Should work with latest published dprof I think.)

Edit: the code is this, for reference:

setInterval(function timeout() {
  console.log('#')
}, 100)

@Qard
Copy link
Member

Qard commented Sep 18, 2016

Maybe something like this for cancelables:

create -- resource created
- queue -- request queued
    - before -- request reaches callback
       - after -- request completes callback
- queue -- request queued
    - unqueue -- request cancelled
destroy -- resource cleaned up

lib/timers.js Outdated
Copy link
Contributor

@Fishrock123 Fishrock123 Sep 18, 2016

Choose a reason for hiding this comment

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

also needs

if (immediate._asyncId && async_hook_fields[kDestroy]) {
    async_hooks.emitDestroy(immediate._asyncId);
  }

@Fishrock123
Copy link
Contributor

Fishrock123 commented Sep 18, 2016

Still needs even more timers fixes. A diff will follow this.

(From AndreasMadsen/dprof#17 (comment))

Take, for example, this.

The handles with the line in-between are actually the same, the timeout was created and the updated three times, from different places, causing re-insertion.

timers-async_hooks

UIDs at the current time (with patches for timers): 12, 17, 20, then 26.

This was taken using a WIP dprof using the following patches to get roughly correct timers behavior but without conceptual same-ID re-use patching.

diff --git a/lib/timers.js b/lib/timers.js
index 6ead9c2..3194ab4 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -145,6 +145,15 @@ function insert(item, unrefed) {
     list._timer[kOnTimeout] = listOnTimeout;
   }

+  if (unrefed === true) item._timerUnref = true;
+
+  if (!item._asyncId) {
+    // No UID, assign a new one.
+    item._asyncId = async_hooks.newUid();
+    if (async_hook_fields[kInit])
+      async_hooks.emitInit(item._asyncId, item, 'Timeout');
+  }
+
   L.append(list, item);
   assert(!L.isEmpty(list)); // list is not empty
 }
@@ -188,7 +197,14 @@ function listOnTimeout() {
     L.remove(timer);
     assert(timer !== L.peek(list));

-    if (!timer._onTimeout) continue;
+    if (!timer._onTimeout) {
+      if (timer._asyncId && async_hook_fields[kDestroy]) {
+        async_hooks.emitDestroy(timer._asyncId);
+        timer._asyncId = 0
+      }
+
+      continue;
+    }

     var domain = timer.domain;
     if (domain) {
@@ -224,6 +240,10 @@ function listOnTimeout() {
       async_hooks.setCurrentId(prev_id);
       if (async_hook_fields[kAfter])
         async_hooks.emitAfter(timer._asyncId);
+      if (!timer._repeat && async_hook_fields[kDestroy]) {
+        async_hooks.emitDestroy(timer._asyncId);
+        timer._asyncId = 0
+      }
     }

     if (domain)
@@ -300,6 +320,12 @@ function reuse(item) {

 // Remove a timer. Cancels the timeout and resets the relevant timer properties.
 const unenroll = exports.unenroll = function(item) {
+  if (item._asyncId) {
+    if (async_hook_fields[kDestroy])
+      async_hooks.emitDestroy(item._asyncId);
+    item._asyncId = 0;
+  }
+
   var handle = reuse(item);
   if (handle) {
     debug('unenroll: list empty');
@@ -480,9 +506,7 @@ function Timeout(after) {
   this._idleStart = null;
   this._onTimeout = null;
   this._repeat = null;
-  this._asyncId = async_hooks.newUid();
-  if (async_hook_fields[kInit])
-    async_hooks.emitInit(this._asyncId, this, 'Timeout');
+  this._asyncId = 0;
 }


@@ -534,8 +558,6 @@ Timeout.prototype.close = function() {
   } else {
     unenroll(this);
   }
-  if (this._asyncId && async_hook_fields[kDestroy])
-    async_hooks.emitDestroy(this._asyncId);
   return this;
 };

@@ -575,6 +597,10 @@ function processImmediate() {
         async_hooks.emitAfter(immediate._asyncId);
     }

+    if (immediate._asyncId && async_hook_fields[kDestroy]) {
+      async_hooks.emitDestroy(immediate._asyncId);
+    }
+
     if (domain)
       domain.exit();
   }

@Fishrock123
Copy link
Contributor

Perhaps it is better to just re-use the same UID and forget about re-insertion pre- timeout/unenroll.

That is, only destroy and re-insert after timeout or removal, not on updating the timeout duration or start (re-insert.)

e.g. this patch on the last one:

diff --git a/lib/timers.js b/lib/timers.js
index 9f397cd..3194ab4 100644
--- a/lib/timers.js
+++ b/lib/timers.js
@@ -152,13 +152,6 @@ function insert(item, unrefed) {
     item._asyncId = async_hooks.newUid();
     if (async_hook_fields[kInit])
       async_hooks.emitInit(item._asyncId, item, 'Timeout');
-  } else if (!item._repeat) {
-    // UID but no repeat, emit Destroy on the existing, then create a new one.
-    if (async_hook_fields[kDestroy])
-      async_hooks.emitDestroy(item._asyncId);
-    item._asyncId = async_hooks.newUid();
-    if (async_hook_fields[kInit])
-      async_hooks.emitInit(item._asyncId, item, 'Timeout');
   }

   L.append(list, item);
@@ -205,8 +198,10 @@ function listOnTimeout() {
     assert(timer !== L.peek(list));

     if (!timer._onTimeout) {
-      if (timer._asyncId && async_hook_fields[kDestroy])
+      if (timer._asyncId && async_hook_fields[kDestroy]) {
         async_hooks.emitDestroy(timer._asyncId);
+        timer._asyncId = 0
+      }

       continue;
     }
@@ -245,8 +240,10 @@ function listOnTimeout() {
       async_hooks.setCurrentId(prev_id);
       if (async_hook_fields[kAfter])
         async_hooks.emitAfter(timer._asyncId);
-      if (!timer._repeat && async_hook_fields[kDestroy])
+      if (!timer._repeat && async_hook_fields[kDestroy]) {
         async_hooks.emitDestroy(timer._asyncId);
+        timer._asyncId = 0
+      }
     }

     if (domain)

Gives this output: (Same handle circled in orange, UID 12.)

timers-maybe-better-async_wrap

@Fishrock123
Copy link
Contributor

Fishrock123 commented Sep 19, 2016

It may be worthwhile to have timers use their own unique _asyncId property though, since timers can be made off of other objects that could have an _asyncId it could get very confusing...

e.g. _timerAsyncId

Edit: or we could just use symbol-hidden properties.

@trevnorris
Copy link
Contributor Author

@Fishrock123

Perhaps it is better to just re-use the same UID and forget about re-insertion pre- timeout/unenroll.

That is, only destroy and re-insert after timeout or removal, not on updating the timeout duration or start (re-insert.)

agreed.

It may be worthwhile to have timers use their own unique _asyncId property though, since timers can be made off of other objects that could have an _asyncId it could get very confusing...

e.g. _timerAsyncId

to clarify, you mean to use a different property name and not to have their own unique id mechanism? that works for me.

@Fishrock123
Copy link
Contributor

Fishrock123 commented Sep 20, 2016

to clarify, you mean to use a different property name and not to have their own unique id mechanism? that works for me.

I mean a different property name for the ID specific to timers so that it does not conflict because any object could be a timer. (yes, I think...?)

Add NODE_TEST_WITH_ASYNC_HOOKS environment variable to allow running
tests with init/before/after/destroy noops to make sure that basic
mechanics work properly across all tests.
Place restoreTmpHooks() closer to setupTmpActiveHooks() to make it more
apparent what each is used for.
Switch to using a v8::Eternal array to retrieve the provider strings
passed as the  "type" to the init() callback.
Instead of always passing in a Float64Array to getIdsFromFd()
preallocate one during initialization and write to those fields
directly.
When emitAfterS() is called, make sure the id passed in is the same id
that's on the stack.
destroy() hooks from JS should also be called async, but instead of
trying to do this in a setImmediate, just use the same list that is used
for native ids.
Add NODE_TEST_HANDLE_ACCESS, which tests if a resource aborts if
inspected at the end of the process (specifically if the resource has
been cleaned up on the C++ side), and NODE_CHECK_ASYNC_DESTROY, which
checks if destroy has been called on the same id twice.
This was originally done as a safety measure, but fails in practice if
a clear*() is run on the same handle that's currently executing its
callback.
In some cases, like triggering the microtask queue, there is no id
(though that should change in the future). So instead trigger that
execution is happening in the void, and return early if destroy is
emitted on the void.
async_hooks does not allow recovery from errors because it's currently
unknown what will happen to the state of the application if that
happens. So instead, force the application to print an error message
then either exit or abort. Depending on whether the user passed
--abort-on-uncaught-exception.

exit() is used instead of reallyExit() to allow any 'exit' events to
fire.
ForceSet() everything with v8::ReadOnly | v8::DontDelete to make sure
none of the object properties can be overridden.
In order to get a stack tracker that is performant in JS had to do some
ridiculous stuff. This allows the stack to be tracked from both C++ and
JS with almost no overhead, and allows it to unwind properly in case
there's a fatal exception.
Instead of using a CHECK(), print an error message to the user. Check if
--abort-on-uncaught-exception has been passed, and abort if this is the
case. Otherwise exit(1).
@joshgav joshgav added the diag-agenda Issues and PRs to discuss during the meetings of the diagnostics working group. label Feb 23, 2017
@joshgav joshgav removed the diag-agenda Issues and PRs to discuss during the meetings of the diagnostics working group. label Feb 23, 2017
@trevnorris
Copy link
Contributor Author

Superseded by #11883. Closing.

@bajtos
Copy link
Contributor

bajtos commented Mar 27, 2017

Superseded by #11883. Closing.

@trevnorris would you mind updating the checklist in nodejs/diagnostics#29 with the new PR number?

@AndreasMadsen
Copy link
Member

@bajtos Thanks, I've just done that.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

async_hooks Issues and PRs related to the async hooks subsystem. c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. semver-minor PRs that contain new features and should be released in the next minor version.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

10 participants