voila-trace

Voilà, Trace

A library for tracing sync/async execution paths in javascript

The intended use of this module is to be able to stitch together multiple disparate sync execution contexts into an abstraction called a trace since request/task handling is often broken up across different sync contexts in javascript environments.

This enables "trace-local" storage of state (for keeping track of a "traceId" and enabling distributed tracing in node) and, for allowing a rough grandularity overview of the execution paths of "traces" for analysis.

Note: Each wrapped function call try/catches its internal call, each call to tracer.wrap creates a new function, and new bound functions are created for each async attach, so there are performance impacts to consider. I would suggest wrapping functions ahead of time, where possible; to not wrap functions that are called extremely frequently; to not wrap functions that not very important; and to not abuse trace local state, as it can be difficult to debug, and reason about.

Configuration and Sync Trace

import tracerFactory from './index';
import * as topiary  from 'topiary';

const tracer = tracerFactory({
  // This onCompleteTrace handler uses topiary to pretty print a tree view of the trace tree.
  onCompleteTrace(trace) {
    const treeView = topiary(trace.root, 'children', {
      sort: true,
      name(node) {
        return `${node.name} ${node.ingressKind}@${node.ingressTimeMs}, ${node.egressKind}@${node.egressTimeMs},`;
      }
    });
    console.log(treeView);
  }
});

function aa() { return; }
const $aa = tracer.wrap(aa);

function ab() { throw new Error('demo'); }
const $ab = tracer.wrap(ab);

function a() {
  $aa();
  $ab();
}
const $a = tracer.wrap(a);

try {
  $a();
} catch (error) {
  // intended
}

// [a, 7adb7g] Call@1490654332637, Throw@1490654332637
//  ├──[aa, 1f2hv03] Call@1490654332637, Return@1490654332637
//  └──[ab, vp2xzk] Call@1490654332637, Throw@1490654332637

Async Trace

When associating a single async function with a sync execution context

import tracerFactory from './index';

const tracer = tracerFactory({ 
  // As Above
  onCompleteTrace 
});

function aaa() { return; }

function aa() {
  // Note: this call must be done in the sync context with which to attach
  setTimeout(tracer.asyncAttach(aaa), 50);
}

function a() {
  // Note: this call must be done in the sync context with which to attach
  setTimeout(tracer.asyncAttach(aa), 50);
}

const $a = tracer.wrap(a);
$a();

// [a, qxkpg0] Call@1490655389541, Return@1490655389542
//  └─┬[aa, 1y6qz19] Async Attach@1490655389597, Return@1490655389598
//    └──[aaa, md6ic5] Async Attach@1490655389653, Return@1490655389653

Async Trace With Optional Codepaths ie w/ Promises

When associating many possible async functions with a sync execution context

Utility Functions

// Similar to Bluebird.delay
function delay(ms) {
  return new Promise(resolve => { setTimeout(resolve, ms); });
}

// Similar to bluebird.asCallback
function asCallback(promise, callback) {
  return promise
    .then(result => {
      try {
        callback(undefined, result);
      } catch (error) {
        setTimeout(() => { throw error; }, 0);
      }
    })
    .catch(callback);
}

Example

import tracerFactory from './index';

const tracer = tracerFactory({ onCompleteTrace });

function aa() { return 1; }
function ab() { return 2; }

function a() {
  // Note: this call must be done in the sync context with which to attach
  const [[$aa, $ab], done] = tracer.asyncAttachMany(aa, ab);

  const promise = delay(50)
    .then($aa)
    // Note: $ab never gets called, that is why "done" is required
    .catch($ab);

  asCallback(promise, done);
}
const $a = tracer.wrap(a);
$a();

// [a, p0d47l] Call@1490656778798, Return@1490656778800
//  └──[aa, sihwyu] Async Attach@1490656778856, Return@1490656778857