Tracing Asynchronous Operations

With Node's AsyncWrap API

Lance Ball

Email: [email protected]

Web: http://lanceball.com

Twitter: @lanceball

GitHub: @lance

What is the AsyncWrap API?

 

  • Hooks into the life cycle of asynchronous operations​

 

  • Available since Node.js 4.x​

​

  • Breaking API changes eminent​

 

Things Will Change

The API is undergoing major review and revision, but the techniques I will demonstrate today will still be relevant.

 

The API changes are "breaking" but not fundamentally different on a conceptual level.

function foo () {
  bar();
}

function bar () {
  foobar();
}

function foobar () {
  throw new Error('Surprise!');
}

foo();

process.on('uncaughtException', (e) => process._rawDebug(e.stack));

Some Code. What does it do?

tracing-async-operations/ex1.js:10
  throw new Error('Surprise!');
  ^

Error: Surprise!
    at foobar (/src/tracing-async-operations/ex1.js:10:9)
    at bar (/src/tracing-async-operations/ex1.js:6:3)
    at foo (/src/tracing-async-operations/ex1.js:2:3)
    at Object.<anonymous> (/src/tracing-async-operations/ex1.js:13:1)
    at Module._compile (module.js:570:32)
    at Object.Module._extensions..js (module.js:579:10)
    at Module.load (module.js:487:32)
    at tryModuleLoad (module.js:446:12)
    at Function.Module._load (module.js:438:3)
    at Module.runMain (module.js:604:10)

Makes Sense

Easy to SEE What is going on here

function foo () {
  setTimeout(bar, 10);
}

function bar () {
  setTimeout(foobar, 50);
}

function foobar () {
  const fs = require('fs');
  fs.readFile(__filename, (_)=>{ throw new Error('Surprise!'); });
}

foo();

process.on('uncaughtException', (e) => process._rawDebug(e.stack));

More Code - what does it do?

Error: Surprise!
    at require.readFile (/src/tracing-async-operations/ex2.js:10:56)
    at FSReqWrap.readFileAfterClose [as oncomplete] (fs.js:445:3)

Not Super Helpful

What is the problem here?

What is the problem here?

Error: Surprise!
    at require.readFile (/src/tracing-async-operations/ex2.js:10:56)
    at FSReqWrap.readFileAfterClose [as oncomplete] (fs.js:445:3)

Local Context is LOST

There is no mention of foo(), bar(), etc.

All we have is that after the close event there was an Error.

What to do about it?

const asyncWrap = process.binding('async_wrap');

asyncWrap.setupHooks({ init, pre, post, destroy });
asyncWrap.enable();

function init (uid, provider, parentUid, parentHandle) {}

function pre (uid) {}

function post (uid, didThrow) {}

function destroy (uid) {}

Async Wrap API

function init (uid, provider, parentUid, parentHandle) {
  // 'this' is the async Handle object
  process._rawDebug(`init: ${uid} : ${provider}`);
}

init()

called when an asynchronous operation is placed on the event queue

> const asyncWrap = process.binding('async_wrap');
> asyncWrap.Providers   

   { NONE: 0,               CRYPTO: 1,
     FSEVENTWRAP: 2,        FSREQWRAP: 3,
     GETADDRINFOREQWRAP: 4, GETNAMEINFOREQWRAP: 5,
     HTTPPARSER: 6,         JSSTREAM: 7,
     PIPEWRAP: 8,           PIPECONNECTWRAP: 9,
     PROCESSWRAP: 10,       QUERYWRAP: 11,
     SHUTDOWNWRAP: 12,      SIGNALWRAP: 13,
     STATWATCHER: 14,       TCPWRAP: 15,
     TCPCONNECTWRAP: 16,    TIMERWRAP: 17,
     TLSWRAP: 18,           TTYWRAP: 19,
     UDPWRAP: 20,           UDPSENDWRAP: 21,
     WRITEWRAP: 22,         ZLIB: 23 }

Providers

function pre (uid) {
  // 'this' is the async Handle object
  process._rawDebug(`pre: ${uid}`);
}
pre()

called just before an asynchronous operation is executed

function init (uid, provider, parentUid, parentHandle) {
  this.someValue = 'foo';
}

function pre (uid) {
  process._rawDebug(this.someValue); // > 'foo'
}

Sharing state between hooks

function post (uid, didThrow) {
  // 'this' is the async Handle object
  process._rawDebug(`post: ${uid}`);
}
post()

called just after an asynchronous operation is executed

function destroy (uid) {
  process._rawDebug(`destroy: ${uid}`);
}
destroy()

called when the C++ handle object is destroyed

function init (uid, provider, parentUid, parentHandle) {
  process._rawDebug(`init: ${uid} : ${provider}`);
}

function pre (uid) {
  process._rawDebug(`pre: ${uid}`);
}

function post (uid, didThrow) {
  process._rawDebug(`post: ${uid}`);
}

function destroy (uid) {
    process._rawDebug(`destroy: ${uid}`);
}

All together now

asyncWrap.setupHooks({ init, pre, post, destroy });
asyncWrap.enable();

process._rawDebug('user: before');

foo();

process._rawDebug('user: after');

function foo () {
  setTimeout(foobar, 10);
}

function foobar () {
  process._rawDebug('user: during');
}

Enable it & RUN SOME ASYNC STUFF

$ node ex3.js

user: before
init: 1 : 17
user: after
pre: 1
user: during
post: 1
destroy: 1

RESULT

Interesting

But now what?

How about...

Long Stack Traces

"If you can't observe your software, you have no idea what it's doing." - C J Silverio

Informative stack traces

 

  • Use the AsyncWrap API to keep track of where our operations are within the call stack.

​

  • When an async operation is placed into the event queue - i.e. on init(), store the current call stack.

​

  • If things blow up, we can get some insight into what went wrong.

function foo () {
  setTimeout(foobar, 50);
}

function foobar () {
  throw new Error('Surprise!');
}

foo();

Let's say I have some code like this

/src/tracing-async-operations/ex5.js:6
  throw new Error('Surprise!');
  ^

Error: Surprise!
    at Timeout.foobar [as _onTimeout] (/Users/lanceball/presentations/tracing-async-operations/ex4.js:34:9)
    at ontimeout (timers.js:365:14)
    at tryOnTimeout (timers.js:237:5)
    at Timer.listOnTimeout (timers.js:207:5)

That code produces

(Again note, context is lost)

const stacks = new WeakMap();
let callSite = null;

function init (uid, provider, parentUid, parentHandle) {
  stacks.set(this, getCallSites(2)); // getCallSites returns call stack
}

function pre (uid) {
  // async stuff about to go down. restore the previous call stack
  callSite = stacks.get(this);
}

function post (uid, didThrow) {
  callSite = null;
}

asyncWrap.setupHooks({ init, pre, post });
asyncWrap.enable();

Saving Context


Error.prepareStackTrace = function prepareStackTrace (err, stack) {
  if (currentCallSite) stack.push.apply(stack, currentCallSite);
  return formatter(err, stack);
};

RESTORING CONTEXT


function foo () {
  setTimeout(foobar, 50);
}

function foobar () {
  throw new Error('Surprise!');
}

foo();


Error: Surprise!
    at Timeout.foobar [as _onTimeout] (/src/tracing-async-operations/ex4.js:30:9)
    at foo (/src/tracing-async-operations/ex4.js:26:3)
    at Object.<anonymous> (/src/tracing-async-operations/ex4.js:55:1)

The RESULT

Tools & Packages

 

  • lightbright​ - https://github.com/bucharest-gold/lightbright

  • async-hooks - https://github.com/AndreasMadsen/async-hook

  • clarify - https://github.com/AndreasMadsen/clarify

References

 

https://redhat.slides.com/lball/tracing-asynchronous-operations

 

  • AsyncWrap Public API Proposal - https://github.com/nodejs/node-eps/pull/18

​

  • async_hooks initial implementation - https://github.com/nodejs/node/pull/8531

 

  • Diagnostics working group - https://github.com/nodejs/diagnostics/

 

QUESTIONS

redhat.com