A View into the Vortex

Tracing Asynchronous Operations in Node.js

Lance Ball

Email: lball@redhat.com

Web: http://lanceball.com

Twitter: @lanceball

GitHub: @lance

Tracing Asynchronous Code

  • Event logging
  • Global state
  • Function parameters
  • Execution Hooks

What is the AsyncWrap API?

 

  • Hooks into the life cycle of asynchronous operations
  • Available since Node.js 4.x​
function loadUser () {
  readConfiguration();
}

function readConfiguration () {
  parseFile();
}

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

loadUser();

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 parseFile (/Users/lanceball/presentations/view-into-the-vortex/examples/ex1.js:10:9)
    at readConfiguration (/Users/lanceball/presentations/view-into-the-vortex/examples/ex1.js:6:3)
    at loadUser (/Users/lanceball/presentations/view-into-the-vortex/examples/ex1.js:2:3)
    at Object.<anonymous> (/Users/lanceball/presentations/view-into-the-vortex/examples/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

function loadUser () {
  setTimeout(readConfiguration, 10);
}

function readConfiguration () {
  setTimeout(parseFile, 50);
}

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

loadUser();

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?

What is the problem?

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

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

What can we do?

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

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 and 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, Nodevember 2016

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 loadUser () {
  setTimeout(readConfiguration, 50);
}

function readConfiguration () {
  setTimeout(parseFile, 50);
}

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

loadUser();

Let's say I have some code like this

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

Error: Surprise!
    at Timeout.parseFile [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 currentStack = [];

function init (uid, provider, parentUid, parentHandle) {
  const stack = getCallSite();
  const lastTrace = currentStack[currentStack.length - 1];
  stack.push.apply(stack, parentUid === null 
        ? lastTrace 
        : traces.get(parentHandle));
  stacks.set(this, stack);
}

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

function post (uid, didThrow) { currentStack.pop(); }

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

Saving Context


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

Restoring Context



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

The Result

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.

Tools & Packages

 

  • lightbright

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

  • async-hooks

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

  • clarify

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

References

 

http://lanceball.com/slides/nodeconf-budapest-2017

http://github.com/lance/nodeconf-budapest-2017

 

  • 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