DTrace and JSON: Together at last!

29 November 2012

In August of this year I jumped on a plane and moved from Australia to San Francisco to work for Joyent. It’s been busy and exciting, from learning about a new city to finding my stride in a new role. I thought I’d take a moment to talk about a new DTrace feature that I just added to illumos-joyent, the core of our SmartOS operating system!

At Joyent we have been implementing JSON-formatted log files in some of our systems programming work, mostly through the node-bunyan logging framework for node.js applications. Formatting our log messages as JSON payloads affords us a substantially easier time of analysing and processing log records programmatically. Extending log files with more fields no longer requires rewriting the scripts that understand how to parse them — we can simply add new properties to the log records!

Bunyan, like every other modern logging framework, provides for a notion of ‘log levels’. Trace- or debug-level log messages generally provide information helpful during development — or later troubleshooting — but are usually too large in volume, and too much of a performance hit, to be left enabled in production at all times. Enter DTrace USDT probes for logging, added recently to Bunyan by Bryan Cantrill. Now, the developer or operator can dynamically enable logging at any level in any running process and receive the generated log records in the form of arguments to DTrace probes.

The only argument passed to the Bunyan log probes when they fire is a JSON-formatted string payload, containing the object passed to Bunyan for logging by the application. While this new feature is a definite boon for developers and operators alike in being able to better understand the operation of the system, it becomes clear reasonably quickly that the string manipulation subroutines available for use within DTrace actions are not the friendliest way to filter on or format for output the contents of a JSON-formatted payload.

When Bryan suggested that we should provide a subroutine for JSON parsing in DTrace my interest was immediately piqued. The challenge of writing a compact, bespoke JSON parser to operating in the tightly restricted environment that is DTrace probe context was a rewarding one. The strict, well-defined nature of the JSON specification was an immediate and welcome asset in completing this work, which I put back yesterday.

The operation of the new json() subroutine is relatively straightforward. It accepts two arguments: a string containing a JSON payload and an element selector string describing which value to pull out of the JSON payload. Element selectors support:

simple string keys for objects, e.g. "key"
dot-separated keys for nested objects, e.g. "nested.object.key"
array indexing, e.g. "nested.object.array[5].key"

As a practical example, consider adding a http.ServerRequest object as the "req" property on an object that you then logged through Bunyan. First, we have to increase the DTrace strsize option to be large enough for the JSON payloads we’ll be inspecting — in this example I’ve used four kilobytes. This D script would then filter on Bunyan log entries pertaining only to GET requests:

#pragma D option strsize=4k

bunyan*:::log-*
{
    this->j = copyinstr(arg0);
}

bunyan*:::log-*
/json(this->j, "req.method") == "GET"/
{
    printf("%s %s %s\n",
        json(this->j, "req.method"),
        json(this->j, "req.url"),
        json(this->j, "req.httpVersion"));
}

All values extracted by json(), including numeric values, are returned as a string precisely as they appeared in the original JSON. As part of this work, I also added a strtoll() subroutine to convert strings to integer types in D. This enables you to take a numeric value from a JSON payload representing something like latency or request size and aggregate these values using functions like sum() or quantize(). For example, if you were to add the HTTP response size to the object logged to Bunyan you could now trivially print out the sum of sizes of all responses once a second:

#pragma D option strsize=4k

bunyan*:::log-*
{
    this->j = copyinstr(arg0);
    @ = sum(strtoll(json(this->j, "response_size")));
}

tick-1s
{
    printa(@);
    trunc(@);
}

These new features are in the illumos-joyent gate right now, and should make their way into the next SmartOS bi-weekly build. In the (hopefully near!) future I will seek to integrate them into the upstream illumos-gate repository for other distributions to get access. My thanks to Bryan for guidance and code review, and to Joyent for being an awesome place to work!