async-wrap: nextTick and setImmediate is ignored

[AndreasMadsen]

Here is a test case you can run with node 0.11.14 and iojs 1.0.x.

var fs = require('fs');
function writeSync(text) { fs.writeSync(1, text + '\n'); fs.fsyncSync(1); }
Error.stackTraceLimit = Infinity;

// Enable asyncWrap and call init hook function on async initialization
try {
  var tracing = require('tracing');
  // Setup an async listener with the handlers listed below
  tracing.addAsyncListener({
    'create': asyncFunctionInitialized,
    'before': asyncCallbackBefore,
    'error': asyncCallbackError,
    'after': asyncCallbackAfter
  });
} catch (e) {
  var asyncWrap = process.binding('async_wrap');
  var asyncHooksObject = {};
  var kCallInitHook = 0;
  asyncWrap.setupHooks(
    asyncHooksObject,
    asyncFunctionInitialized,
    asyncCallbackBefore,
    asyncCallbackAfter);
  asyncHooksObject[kCallInitHook] = 1;
}

function asyncFunctionInitialized() {
  writeSync((new Error()).stack);
}
function asyncCallbackBefore() {}
function asyncCallbackError() {}
function asyncCallbackAfter() {}

// TEST
(function outer() {
  setImmediate(function () {
    writeSync('END');
  });
})();

In the node 0.11.14 asyncFunctionInitialized is called and the stack trace is printed. However in iojs 1.0.x just END is printed. This also seams to be the case for process.nextTick.

issue tracing: AndreasMadsen/trace#12

[othiym23]

@AndreasMadsen since async_wrap is only exposed as a binding, and only tracks asynchronous events on the C++ side of Node, it's not going to capture pure JS constructs like process.nextTick or set{Immediate,Timeout}. async_wrap isn't really meant to be a general-purpose replacement for tracing.addAsyncListener() or the async-listener package on npm. Instead, it's a primitive that handles the C++ behavior that we can build new behavior on top of.

See also #671.

[AndreasMadsen]

How is setImmediate a pure JS construct, the callback is invoked though https://github.com/iojs/io.js/blob/v1.x/src/node.cc#L2510 and https://github.com/iojs/io.js/blob/v1.x/src/node.cc#L180 ?
I get that there is a queue system like with setTimeout (https://github.com/iojs/io.js/blob/v1.x/lib/timers.js#L90) but setTimeout is supported.

The process.nextTick is implemented though the v8 microtask queue, and while I don't completely understand it, it looks like this also have roots in C++ https://github.com/iojs/io.js/blob/v1.x/src/node.cc#L1064

[vkurchatkin]

While both setImmediate and nextTick callback originate in C++ (everything does), there are no such things as nexttick_wrap or immediate_wrap.

[AndreasMadsen]

How can I implement something similar to tracing then.

[othiym23]

How is setImmediate a pure JS construct, the callback is invoked though https://github.com/iojs/io.js/blob/v1.x/src/node.cc#L2510 and https://github.com/iojs/io.js/blob/v1.x/src/node.cc#L180 ?

I think you're conflating two more or less unrelated things there: there's setImmediate() (which is defined in lib/timers.js) and the Node event loop's idle handler, which has code to check whether it needs to process immediateQueue.

There's a similar mechanism that checks to see whether the nextTick queue needs to be processed, but the callbacks themselves (in both cases) are called from the JS side, not the C++ side.

async_wrap events fire only for classes that inherit from the AsyncWrap base class defined in src/async-wrap.{h,cc}. git grep AsyncWrap in the io.js source tree should give you an idea of which bits of the Node API are included there. Importantly, none of the timer-related functions, nor things that interact with the microtask queue, are included. @vkurchatkin has done more work with the microtask queue than me, so he can give you a better idea of what the state of things is there.

How can I implement something similar to tracing then.

1. Take a look at contributing to the tracing module, which is a (somewhat-unmaintained) extraction of the Node 0.11.14 tracing module into a separate code base.
2. Join or follow the tracing WG as we figure out how to solve the underlying problem of Node / io.js instrumentation properly.
3. Take a look at async-listener, which includes a more-or-less faithful implementation of an earlier iteration of the asyncListener API. @Qard, @hayes and I are working on getting it to support V8-Native promises and doing a few other things that make it appropriate for use in tracers. It's not as efficient as async_wrap, but it's fast enough for production use in a bunch of commercially-supported tracing products.

[vkurchatkin]

I'm pretty sure that the only way is to monkey-patch setTimeout, setImmediate and process.nextTick

[othiym23]

I'm pretty sure that the only way is to monkey-patch setTimeout, setImmediate and process.nextTick

...which is what async-listener does, among other things. I'd actually be happy to merge a patch that takes advantage of async_wrap when it's present, which would be a good bridge strategy until we figure out what a proper asynchronous tracing API should look like.

[trevnorris]

FTI, I plan on implementing proper timer/nextTick support in the near future.

[marcominetti]

+1 @trevnorris