async_hooks initial implementation

[trevnorris]

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

[Fishrock123]

CI: https://ci.nodejs.org/job/node-test-pull-request/4048/

[Fishrock123]

cc @nodejs/ctc & @AndreasMadsen

[jasnell]

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.

[jasnell]

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

[Fishrock123]

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

[jasnell]

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?

[trevnorris]

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.

[AndreasMadsen]

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.

[AndreasMadsen]

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.

[AndreasMadsen]

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

[AndreasMadsen]

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.

[AndreasMadsen]

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

[AndreasMadsen]

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

[AndreasMadsen]

hooks stack

Can you elaborate on what the hooks stack is.

[AndreasMadsen]

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

[AndreasMadsen]

Should be Environment::AsyncHooks::kAfter

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

[AndreasMadsen]

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.

[AndreasMadsen]

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.

[Fishrock123]

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

[Fishrock123]

Seems good, left some timers review.

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

[Fishrock123]

This should actually be in insert() I think.

[Fishrock123]

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

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

[Fishrock123]

This should be in unenroll().

[Fishrock123]

Same loop/variable comment as in listOnTimeout()

[Fishrock123]

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

[joshgav]

/cc @nodejs/diagnostics @digitalinfinity

[Fishrock123]

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.

[Fishrock123]

also needs roughly this:

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

[Fishrock123]

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

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

[Qard]

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

[Fishrock123]

@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]

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

[Fishrock123]

also needs

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

[Fishrock123]

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.

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]

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.)

[Fishrock123]

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]

@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]

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...?)

[trevnorris]

Superseded by #11883. Closing.

[bajtos]

Superseded by #11883. Closing.

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

• setTimeout, setInterval, setImmediate (old issue: async-wrap: nextTick and setImmediate is ignored #666, PR: async_hooks initial implementation #8531)

[AndreasMadsen]

@bajtos Thanks, I've just done that.