A View into the Vortex

Tracing Asynchronous Operations in Node.js

Lance Ball

Email: [email protected]

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?

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/

A View into the Vortex

Tracing Asynchronous Code

What is the AsyncWrap API?

Some Code

What does it do?

Makes Sense

More Code

What does it do?

Not Super Helpful

What is the problem?

What is the problem?

Local Context is Lost

What can we do?

Async Wrap API

Providers

Sharing state

All together now

Enable it and run some async stuff

Result

Interesting

But now what?

How about...

Long Stack Traces

Informative stack traces

Let's say I have some code like this

That code produces

Saving Context

Restoring Context

The Result

Things Will Change

Tools & Packages

References

QUESTIONS