DTrace Your Node.js JS

Mark Cavage

dtrace.conf April 03, 2012

Me

@mcavage (Twitter)
mcavage (GitHub)
mcavage at gmail dot com

Just to level-set (i.e., What's Node.js?)

What's Node.js?

Server-side Javascript.
Always non-blocking (threads aren't exposed to you)
And networking/HTTP are first class

Why would you use Node.js?

You want to spin up some new network service (relatively) quickly
You want it to talk to other things
And you care about performance/scalability

Bored now. What's this talk about?

(Briefly) What DTrace is available for node itself
How to DTrace your application with node-dtrace-provider
Some example usage of dtrace-provider (ldapjs/restify)

DTrace the Node core

Basically, you've got USDT probes for socket, http and gc
Those let you get the basics of what your app is doing
But it's a pretty course granularity

Some One-liners (thanks @bmc)

dtrace -n node*:::http-server-request{
    printf(“%s of %s from %s\n”, args[0]->method,
        args[0]->url, args[1]->remoteAddress)}

 dtrace -n http-server-request’{@[args[1]->remoteAddress] = count()}‘

 dtrace -n gc-start’{self->ts = timestamp}’ \
    -n gc-done’/self->ts/{@ = quantize(timestamp - self->ts)}

Cool - do I need anything else?

As said before, those probes tell you a lot about what the interpreter sees
They don't tell you much about your app's components
Wouldn't you like to know if say a DB call or a FS call were what was slowing your app down?

What if your infrastructure looks like this?

Suppose you had some (crappy) REST api...

var server = require('restify').createServer({
    name: 'foo'
});

server.use(function slowDown(req, res, next) {
    setTimeout(function () {
        return next();
    }, 513);
});

server.get('/hello/:name', function echo(req, res, next) {
    res.send('hello ' + req.params.name);
    return next();
});

server.listen(8080, function() {
    console.log('%s listening at %s', server.name, server.url);
});

Wouldn't it be nice to see that slowdown?

foo*:::get*-*-start
{
    tracker[arg0, substr(probename, 0, rindex(probename, "-"))] = timestamp;
}

foo*:::get*-*-done
/tracker[arg0, substr(probename, 0, rindex(probename, "-"))]/
{
    this->name = substr(probename, 0, rindex(probename, "-"));
    @[this->name] = quantize(((timestamp - tracker[arg0, this->name]) / 1000000));
    tracker[arg0, substr(probename, 0, rindex(probename, "-"))] = 0;
}

In action?

$ ./latency.d
...
$ curl -s http://localhost:8080/hello/dtrace | json
hello dtrace
$ curl -s http://localhost:8080/hello/dtrace | json
hello dtrace
...
  gethelloname-echo
           value  ------------- Distribution ------------- count
               0 |                                         0
               1 |@@@@@@@@@@@@@@@@@@@@                     1
               2 |@@@@@@@@@@@@@@@@@@@@                     1
               4 |                                         0

  gethelloname-slowDown
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
            1024 |                                         0

Wait. What?

There was some magic in restify
Under the covers it creates DTrace probes for all the handlers in a server
The rest of this talk is about showing you how to do that

Thanks Chris Andrews!

$ npm install dtrace-provider

Allows you to DTrace for your Node.js application code
Installs everywhere; useful on Solaris derivations/OSX
You don't need to be root

What is node-dtrace-provider?

Allows you to define DTrace USDT probes on the fly in JS
This is the third time he's done it. Used the same technique for Ruby and Perl
He's currently "normalizing" all three implementations into libusdt.

Is this magic? How does this work?

Dynamically create tracepoints in the running process
Dynamically creates DOF to describe the provider to the kernel
ioctl said DOF into the kernel
For more information, see Chris' blog

How do you use it?

var fs = require('fs');
var dtp = require('dtrace-provider').createDTraceProvider('nodecat');

dtp.addProbe('fs-read-start', 'char *');
dtp.addProbe('fs-read-done', 'char *', 'char *', 'int');

function readFile(file) {
    dtp.fire('fs-read-start', function () {
        return [file]
    });
    fs.readFile(file, 'utf8', function (e, data) {
        dtp.fire('fs-read-done', function () {
            return [file, e && e.code ? e.code : null, data ? data.length : 0];
        });
        if (e)
            throw e;
        process.stdout.write(data);
    });
}

dtp.enable();
process.argv.slice(2).forEach(function (f) {
    return readFile(f);
});

Node's read vs system read

nodecat*:::fs-read-start
{
    node[copyinstr(arg0)] = timestamp;
}


syscall::open:entry
/node[substr(copyinstr(arg0), (rindex(copyinstr(arg0), "/") + 1), 128)]/
{
    this->fname = substr(copyinstr(arg0),rindex(copyinstr(arg0),"/")+1,128);
    sys[strjoin("_", this->fname)] = timestamp;
}


syscall::read:entry
/node[fds[arg0].fi_name] && sys[strjoin("_", fds[arg0].fi_name)]/
{
    self->fd = arg0;
}

syscall::read:return
/self->fd > 0 && arg0 == 0 && !sys[fds[self->fd].fi_name]/
{
    this->fname = fds[self->fd].fi_name;
    sys[this->fname] = (timestamp - sys[strjoin("_", this->fname)]) / 1000;
    sys[strjoin("_", this->fname)] = self->fd = 0;
}


nodecat*:::fs-read-done
/node[copyinstr(arg0)] && sys[copyinstr(arg0)]/
{
    this->fname = copyinstr(arg0);
    this->delta = (timestamp - node[this->fname]) / 1000;
    printf("%-20s\t%-16d\t%-16d\n", this->fname, sys[this->fname], this->delta);
    node[this->fname] = sys[this->fname] = 0;
}

Pretty decent in terms of interpreter overhead (μs)

$ ./nodecat.d
FILE                	SYSTEM TIME     	NODE TIME
intro.js            	17693           	18032
nurl                	33436           	33726
latency.d           	1006            	1456
^C

(Tangent) What's with the goofy read:return?

man -s 2 read says if (read(fd) == 0) then EOF
node however decides to keep calling it. and calling it. and calling it.
Hence, that janky D script to get the timing of the first return 0 (since the system is ready to move on)

Bah! Show me some examples!

Ok, ok. Clearly the availability heuristic is going to kick in...now!
Let's look at:
- ldapjs
- restify

ldapjs: hello world server

var server = require('ldap').createServer();

server.search('o=example', function(req, res, next) {
    var obj = {
        dn: req.dn.toString(),
        attributes: {
            o: 'example',
            objectclass: ['organization', 'top']
        }
    };

    if (req.filter.matches(obj.attributes))
        res.send(obj);

    res.end();
});

server.listen(1389);

Show me the probes!

$ dtrace -l -P ldapjs*
   ID   PROVIDER            MODULE                          FUNCTION NAME
...
21618 ldapjs70778            module                              func server-search-start
21619 ldapjs70778            module                              func server-search-done
21620 ldapjs70778            module                              func server-search-entry
...

Some search one(ish) liners

dtrace -n "ldapjs*:::server-search-start{printf(\"search: base=%s, \
    filter=%s from %s\n\", copyinstr(arg3), copyinstr(arg5), \
    copyinstr(arg1));}"

ldapjs*:::server-search-start
{
    req[arg0] = timestamp;
}


ldapjs*:::server-search-done
/req[arg0]/
{
    @search = quantize(((timestamp - req[arg0]) / 1000000));
}

Fancy: Visualization of ldapjs

That said: it's pretty course granularity

This was my first pass at integrating dtrace into node app code.
Really there's just start/done for each LDAP operation
Lets us see what a server is doing, but not very well broken out

Take two: restify

Restify lets you build a REST api by pipelining handlers
After having done ldapjs, what I really wanted was to be able to visualize all the steps in a request
DTrace start/done probes get inserted for every distinct handler

A (slightly) bigger exampe

var restify = require('restify');
var server = restify.createServer();
server.use(restify.acceptParser(server.acceptable));
server.use(restify.authorizationParser());
server.use(restify.dateParser());
server.use(restify.queryParser());
server.use(restify.urlEncodedBodyParser());

server.use(function slowHandler(req, res, next) {
  setTimeout(function() { return next(); }, 513);
});

server.get('/hello/:name', function echo(req, res, next) {
  res.send({
    hello: req.params.name
  });
});

server.listen(8080);

Now we're talking!

   ID   PROVIDER            MODULE                          FUNCTION NAME
21688 restify88193            module                              func gethelloname-start
21689 restify88193            module                              func gethelloname-done
21690 restify88193            module                              func gethelloname-parseAccept-start
21691 restify88193            module                              func gethelloname-parseAccept-done
21692 restify88193            module                              func gethelloname-parseAuthorization-start
21693 restify88193            module                              func gethelloname-parseAuthorization-done
21694 restify88193            module                              func gethelloname-parseDate-start
21695 restify88193            module                              func gethelloname-parseDate-done
21696 restify88193            module                              func gethelloname-parseQueryString-start
21697 restify88193            module                              func gethelloname-parseQueryString-done
21698 restify88193            module                              func gethelloname-parseUrlEncodedBody-start
21699 restify88193            module                              func gethelloname-parseUrlEncodedBody-done
21700 restify88193            module                              func gethelloname-slowHandler-start
21701 restify88193            module                              func gethelloname-slowHandler-done
21702 restify88193            module                              func gethelloname-echo-start
21703 restify88193            module                              func gethelloname-echo-done

The same D script as before...

restify*:::get*-*-start
{
    tracker[arg0, substr(probename, 0, rindex(probename, "-"))] = timestamp;
}

restify*:::get*-*-done
/tracker[arg0, substr(probename, 0, rindex(probename, "-"))]/
{
    this->name = substr(probename, 0, rindex(probename, "-"));
    @[this->name] = quantize(((timestamp - tracker[arg0, this->name]) / 1000000));
    tracker[arg0, substr(probename, 0, rindex(probename, "-"))] = 0;
}

Shows us a lot more data

  gethelloname-parseAccept
           value  ------------- Distribution ------------- count
              -1 |                                         0
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15
               1 |                                         0

  gethelloname-parseAuthorization
           value  ------------- Distribution ------------- count
              -1 |                                         0
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15
               1 |                                         0

  gethelloname-parseDate
           value  ------------- Distribution ------------- count
              -1 |                                         0
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15
               1 |                                         0

  gethelloname-parseQueryString
           value  ------------- Distribution ------------- count
              -1 |                                         0
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15
               1 |                                         0

  gethelloname-parseUrlEncodedBody
           value  ------------- Distribution ------------- count
              -1 |                                         0
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 15
               1 |                                         0

  gethelloname-slowHandler
           value  ------------- Distribution ------------- count
             256 |                                         0
             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 14
            1024 |

Every time a route/handler is added

restify sets up a start/done DTrace probe for the route
plus a start/done probe for each handler in the route
plus a start/done probe for the shared handlers to track in that route
You can glob to your heart's content in D scripts, since the names are predictable

mapping code

function addProbes(dtrace, name) {

  // id, requestid, authenticated user, user-agent, content-type, content-length
  dtrace.addProbe(name + '-start',
                  'int', 'char *', 'char *', 'char *', 'char *', 'int');

  // id, requestid, statusCode, content-type, content-length
  dtrace.addProbe(name + '-done',
                  'int', 'char *', 'int', 'char *', 'int', 'int');

  return true;
}

Route runner fires

function run(req, res) {
    var chain = this.chain;
    var i = -1;
    var self = this;

    function next() {
        if ((i + 1) > 0 && chain[i]) // handler done
            fireProbeDone(self.dtrace, self.probe + '-' + chain[i]._name, req, res);

        if (!done && chain[++i]) {
            fireProbeStart(self.dtrace, self.probe + '-' + chain[i]._name, req);
            return chain[i].call(self, req, res, next);
        }

        // route done
        fireProbeDone(self.dtrace, self.probe, req, res);
    }

    fireProbeStart(this.dtrace, this.probe, req);
    return next();

Some tips on how to use dtrace-provider...

Ride on top of other probes

Whenever possible, piggyback on system probes by using an argument you can correlate (like filename in the nodecat example)

Picking arguments

There's no support for argument structs (yet), and you only get 6 arguments to play with, so choose your args wisely

Build into your framework

ldapjs and restify are two examples where DTrace isn't in user code at all, but provides substantial value.

Most nodey things end up in a control-flow problem

I.e., everybody I know uses async or a home-grown thing like it.

But that makes an excellent place to put probes.

Easy latency tracking

For any given probe, add -start and -done so latency can be calculated
Where it makes sense, make arg0 be a monotonically increasing integer

What would be nice in the future?

JS objects as probe arguments (i.e., structs)
Being able to tack on more probes on the fly (i.e., after calling enable())
Minimizing the disabled probe effect