Written by dap
on 

Playing with Node/V8 postmortem debugging

2016 Update: The commands and output in this post are pretty dated now, but you can find an up-to-date docs (including a tutorial and instructions for updated binaries) in the mdb_v8 user guide.

“Post Mortem” by C. MacLaurin

Several weeks ago I posted about postmortem debugging for Node.js, a critical technique for understanding fatal software failure (and thereby keeping up software quality). Now that the underlying pieces are freely available1, you can use the documentation below to start debugging your own Node programs. With these tools you can inspect the call stack and arbitrary JavaScript heap objects for both live programs and core dumps. Documentation is often dry reading, but I’ve worked to keep this document concise and relevant. You can read this start-to-finish in half an hour and you’ll learn a bunch about V8 internals by exploring your own node program. If you don’t care about this level of detail, just read my older post to get a sense of what this tool does. Shortly I’ll post an example of using this tool to debug a problem we weren’t able to debug with existing tools.

This tool works out of the box for Node.js on the latest SmartOS release. So if you’ve got a SmartOS live CD and any release of Node.js since 0.4.8, these tools will just work. If you’re running an older version of SmartOS, another illumos-based system, or a Joyent SmartMachine that hasn’t yet been upgraded to the latest SmartOS, you can just download the binaries that you need. The instructions below cover both of these cases.

Introduction

The V8 mdb dmod facilitates inspection of V8-level and JS-level state from MDB, the illumos modular debugger. If you’re not familiar with MDB, you may want to skim theĀ MDB man page. The syntax may take some getting used to, but you can probably pick up enough to get started from the examples below.

The various dcmds and walkers are prefixed with “v8” or “js” depending on which level they operate on.

The JavaScript-level dcmds are:

  walk jsframe              - walk V8 JavaScript stack frames
  dcmd jsframe              - summarize a JavaScript stack frame
  dcmd jsstack              - print a JavaScript stacktrace
  dcmd jsprint              - print a JavaScript object

The V8-level dcmds are:

  dcmd v8array              - print elements of a V8 FixedArray
  dcmd v8classes            - list known V8 heap object C++ classes
  dcmd v8load               - load canned config for a specific V8 version
  dcmd v8print              - print a V8 heap object
  dcmd v8str                - print the contents of a V8 string
  dcmd v8type               - print the type of a V8 heap object
  dcmd v8types              - list known V8 heap object types

Getting started

Step 1: Run MDB

First, run your program. Then attach with MDB (using mdb -p <pid>) or take a core dump with gcore(1M) and run MDB on the core file.

Step 2: Load the dmod

The dmod is not loaded by default. You must explicitly load it with:

> ::load v8

If this fails, you’re running an older version of SmartOS and you’ll need to download the v8.so binary and use ::load /path/to/v8.so. (You have to use ::load ./v8.so even if the file is in the same directory so that MDB knows you’re giving it a relative path; by default, MDB searches the dynamic library path, which probably doesn’t include “.”.)

Step 3: Configure the dmod

The dmod requires knowledge of internal V8 structures that change between versions of V8. Some builds of V8 include the required information directly in the binary, in which case the dmod will auto-configure itself and you’ll see this when you initially load the dmod:

> ::load v8
Loaded V8 support.

If you don’t see that, your version of Node doesn’t have support built-in, but you can load a pre-canned configuration using ::v8load, which supports arguments for “node-0.4” (for v0.4.8 and later) and “node-0.6.5” (which works on v0.6.5 and v0.6.6, and possibly later versions).

Summary

To summarize how you’d start debugging a core file from node 0.6.5:

$ mdb core.node.jpc
Loading modules: [ libc.so.1 ld.so.1 ]
> ::load v8
> ::v8load node-0.6.5
V8 dmod configured based on node-0.6.5

or, if you downloaded the binaries separately above:

$ ./mdb core.node.jpc
Loading modules: [ libc.so.1 ld.so.1 ]
> ::load ./v8.so
> ::v8load node-0.6.5
V8 dmod configured based on node-0.6.5

Inspecting JavaScript-level state

::walk jsframe

Iterates stack frames and prints out the frame pointers. Starts with %ebp, and then follows frame pointers until it finds something that doesn’t look like a V8 JavaScript stack frame. This is very much like MDB’s $C macro but only prints the frame pointers. To get more details, pipe this to ::jsframe.

Note: libv8 is typically compiled with -fomit-frame-pointer, so if mdb catches “node” while it’s somewhere inside of V8, you may not be able to get a stacktrace at all.

::jsframe [-v]

Given a frame pointer, prints out a summary of the stack frame. With no arguments, prints a one-line summary for use in a stacktrace that includes the frame pointer, the name of the function (which may be inferred), the script where it was defined, and either the line number or character position in the file where the function was defined. The line number information will only be available if V8 has computed that information, which it does on a per-script basis as needed.

Example 1: anonymous function, invoked with a name, with line number information present:

> 8046df0::jsframe
8046df0 <anonymous> (as EventEmitter.emit) at events.js line 38

Example 2: named function with no line number information:

> 8046af8::jsframe
8046af8 caAggrValueHeatmapImage at
/opt/local/lib/node/.npm/cabase/1.0.3vrelease-20110901-20110901-3-gc693a90-dirty/package/lib/ca/ca-agg.js position 48960

Example 3: anonymous function invoked with no name and with no line number information:

> 8047500::jsframe
8047500 <anonymous> (as <anon>) at /home/dap/node-stack/examples/loop-anon.js line 15

With -v, prints out a best guess at function arguments. This uses the “length” property of the Function object to determine how many arguments the function consumes and then prints them from the stack. For example:

> 8046a9c::jsframe -v
8046a9c <anonymous> (as exports.bucketize)
    func: fc435fcd
    file:
/opt/local/lib/node/.npm/cabase/1.0.3vrelease-20110901-20110901-3-gc693a90-dirty/package/node_modules/.npm/heatmap/0.0.1/package/lib/heatmap.js
    posn: position 7838
    arg1: fc070709 (JSArray)
    arg2: fc070719 (JSObject)

You can use ::jsprint to print these objects.

Note: there are several types of non-JavaScript frames that ::jsframe recognizes:

::jsstack [-v]

Equivalent to ::walk jsframe | ::jsframe [-v]. This iterates the known JS stack frames and prints out the summary or detailed view.

::jsprint [-a] [-d depth]

Given a JavaScript object of class Object, Array, Function, Number, Boolean, or special value (like null or undefined), print it out. Except for functions, the result should closely resemble the JavaScript syntax you would use to define the object inline. For example:

> fc070719::jsprint
{
    base: 1320886447,
    weighbyrange: false,
    height: 281,
    width: 624,
    nbuckets: 50,
    max: 11538462,
    nsamples: 30,
    hue: [ 21 ],
    linear: false,
    min: 11538462,
}

Note: Not all types of objects are supported, but we haven’t yet encountered those that aren’t, and the dmod should behave sanely if they are encountered.

With -a, prints the address of the V8 heap object representing each JavaScript object so you can inspect it individually. For example:

> fc070719::jsprint -a
fc070719: {
    base: fbf4ec4d: 1320886447,
    weighbyrange: fe88e0ad: false,
    height: 232: 281,
    width: 4e0: 624,
    nbuckets: 64: 50,
    max: 160203c: 11538462,
    nsamples: 3c: 30,
    hue: fc043179: [ 2a: 21 ],
    linear: fe88e0ad: false,
    min: 160203c: 11538462,
}

Since many objects are circular (or just large), the -d option is provided to control how deep to recurse. The default recursion depth is 2.

Note: You may see expected special values like “undefined”, “null”, “true”, and “false”. There’s an additional special value called “hole” which represents holes in an array. For example:

> fc070709::jsprint
[
    [],    [],
...
    hole,
    hole,
    hole,
]

indicates that the array’s length has somehow been extended beyond the last actual element so the remaining elements are holes.

Inspecting V8-level state

Since not all information is contained directly in JavaScript state, it may be useful to inspect V8-level heap objects directly. To make sense of this, you must understand a few basics about the V8 heap. The details contained here are obviously subject to change at any time as V8 itself evolves.

Pointers in the heap are word-aligned, but the low-order bits are used to encode some information about the item. Specifically, most heap objects belong to one of two classes: SMI (small integer) values and HeapObjects.

Heap Object type information

Various C++ classes are used to represent objects of the heap, including JSFunction, JSObject, JSArray, Oddball (for undefined, null, true, and false), HeapNumber (for non-SMI numbers), and various types of String. You can list all of the ones that the dmod knows about with ::v8classes.

There’s a related but separate set of type values (a C++ enum): FUNCTION_TYPE, JSOBJECT_TYPE, JSARRAY_TYPE, ODDBALL_TYPE, etc. For strings, the type field also encodes whether the string is encoded in ASCII or two-byte encoding and whether it’s represented as a sequence of bytes or a ConsString. You can list the type values that the dmod knows about with ::v8types.

All of the various heap object classes are subclasses of HeapObject. HeapObject defines a field called “map” (of class Map, itself a HeapObject) which describes the layout of the object in detail. Most importantly, the Map includes the type of the object.

Using the type information in a HeapObject’s map, and a separate built-in mapping of type values to C++ classes, the dmod can take an arbitrary pointer and tell you what C++ class it must be. This is what the ::v8type dcmd does:

> fc070719::v8type
0xfc070719: JSObject

> fbf4ec4d::v8type
0xfbf4ec4d: HeapNumber

> fc043179::v8type
0xfc043179: JSArray

> fe88e0ad::v8type
0xfe88e0ad: Oddball: "false"

> 160203c::v8type
0x160203c: SMI: value = 11538462

(The above examples are taken from the JSObject printed with ::jsprint -a in the example above.)

The dmod also knows the layout of these C++ classes. You can use ::v8print to print out an object as an instance of its C++ class (which is automatically inferred as described above):

> fc070719::v8print
fc070719 JSObject {
    fc070719 HeapObject < Object < MaybeObject  {
        fc070718 map = fe85e7e1 (Map)
    }
    fc07071c properties = fc07b9c9 (FixedArray)
    fc070720 elements = fe88e021 (FixedArray)
}

> fc043179::v8print
fc043179 JSArray {
    fc043179 JSObject {
        fc043179 HeapObject < Object < MaybeObject  {
            fc043178 map = fe84caa1 (Map)
        }
        fc04317c properties = fe88e021 (FixedArray)
        fc043180 elements = fc0480f1 (FixedArray)
    }
    fc043184 length = 2 (SMI: value = 1)
}

A few notes about this output:

Note: Some fields may be missing because the dmod does not know about every field in every class.

Type-specific dcmds

There are two additional dcmds which are useful for printing out instances of certain specific V8 classes. You can always use ::v8print, but these commands give additional information.

::v8str [-v]

Prints the contents of any ASCII V8 string, regardless of representation. There are basically three representations:

With -v, this dcmd shows what it did. For example:

> fc3e2081::v8str
exports.bucketize

> fc3e2081::v8str -v
ConsString
    ptr1: fe8a7ba1
    ptr2: fc417a75
    SeqAsciiString
        length: 7, will read: 7
        value: "exports"
    SeqAsciiString
        length: 10, will read: 10
        value: ".bucketize"
exports.bucketize

In this case, the original pointer is a ConsString. Each pointer in this top-level ConsString is itself a SeqString. In general, these pointers may themselves be ConsStrings that must be followed recursively.

::v8array

Prints the contents of a V8 array. This is mostly useful for exploring and debugging the dmod. For example, here’s how you can get the contents of a JSArray:

> fc043179::v8print
fc043179 JSArray {
    fc043179 JSObject {
        fc043179 HeapObject < Object < MaybeObject  {
            fc043178 map = fe84caa1 (Map)
        }
        fc04317c properties = fe88e021 (FixedArray)
        fc043180 elements = fc0480f1 (FixedArray)
    }
    fc043184 length = 2 (SMI: value = 1)
}

We see that this is a JSArray with length 1 (since “length” is stored as an SMI with value 2). We can use ::v8array to print out the elements of the “elements” FixedArray:

> fc0480f1::v8array
2a

and then we can print out the one element’s value:

> 2a::v8print
SMI: value = 21

We can check our work with ::jsprint, which does all this automatically:

> fc043179::jsprint
[ 21 ]

Putting it all together

To reinforce all of this, we’ll get the details about a particular stack frame manually. First, walk the stack:

> ::walk jsframe
8046a9c
8046af8
...

We’ll take the top frame. Use ::jsframe -v to get a pointer to the frame’s “func” object:

> 8046a9c::jsframe -v
8046a9c <anonymous> (as exports.bucketize)
    func: fc435fcd
    file: /opt/local/lib/node/.npm/cabase/1.0.3vrelease-20110901-20110901-3-gc693a90-dirty/package/node_modules/.npm/heatmap/0.0.1/package/lib/heatmap.js
    posn: position 7838
    arg1: fc070709 (JSArray)
    arg2: fc070719 (JSObject)

We’ve cheated because we have the function and file names already, but we’ll show how to get this from just the function pointer, which is a fixed offset of -0x8 from the frame pointer. We only used ::jsframe to get the function pointer.

Print out the function:

> fc435fcd::v8print
fc435fcd JSFunction {
    fc435fcd JSObject {
        fc435fcd HeapObject < Object < MaybeObject  {
            fc435fcc map = fe84d8a1 (Map)
        }
        fc435fd0 properties = fe88e021 (FixedArray)
        fc435fd4 elements = fe88e021 (FixedArray)
    }
    fc435fdc prototype_or_initial_map = fe88e0cd (Oddball: "hole")
    fc435fe0 shared = fc4348c1 (SharedFunctionInfo)
    fc435fe8 literals = fc436021 (FixedArray)
    fc435fec next_function_link = fe88e05d (Oddball: "undefined")
}

The interesting details are all in the associated SharedFunctionInfo:

> fc4348c1::v8print
fc4348c1 SharedFunctionInfo {
    fc4348c1 HeapObject < Object < MaybeObject  {
        fc4348c0 map = fe84c681 (Map)
    }
    fc4348c4 name = fe88e2f1 (SeqAsciiString: "")
    fc4348d0 construct_stub = fe86ea21 (Code)
    fc4348d4 instance_class_name = fe88e199 (SeqAsciiString: "Object")
    fc4348d8 function_data = fe88e05d (Oddball: "undefined")
    fc4348dc script = fc434581 (Script)
    fc4348e0 debug_info = fe88e05d (Oddball: "undefined")
    fc4348e4 inferred_name = fc3e2081 (ConsString: "exports.bucketize")
    fc4348e8 initial_map = fe88e05d (Oddball: "undefined")
    fc4348ec this_property_assignments = fe88e021 (FixedArray)
    fc4348f4 length = 4 (SMI: value = 2)
    fc4348f8 formal_parameter_count = 4 (SMI: value = 2)
    fc4348fc expected_nof_properties = 14 (SMI: value = 10)
    fc434900 num_literals = 8 (SMI: value = 4)
    fc434904 start_position_and_type = 7ac0 (SMI: value = 15712)
    fc434908 end_position = 3968 (SMI: value = 7348)
    fc43490c function_token_position = 1e9e (SMI: value = 3919)
    fc434910 compiler_hints = 0 (SMI: value = 0)
    fc434914 this_property_assignments_count = 0 (SMI: value = 0)
    fc434918 opt_count = 0 (SMI: value = 0)
}

We can already see that the name is “”, indicating an anonymous function, and the inferred name is “exports.bucketize”. If ::v8print hadn’t printed the function name, we could get it with ::v8str:

> fc3e2081::v8str
exports.bucketize

To get the script name, follow the “script” field:

> fc434581::v8print
fc434581 Script {
    fc434581 Struct {
        fc434581 HeapObject < Object < MaybeObject  {
            fc434580 map = fe84c581 (Map)
        }
    }
    fc434584 source = fc130021 (
    SeqAsciiString: "(function (exports, require, module, __filename, __dirname) { /*
     * Copyright 2010 Joyent, Inc.  All rights reserved.
     * Use is subject to license terms.
     */

    var assert = require('assert');
    var libpng = require('png');
    var sys = require()
    fc434588 name = fc4120bd (
    SeqAsciiString: "/opt/local/lib/node/.npm/cabase/1.0.3vrelease-20110901-20110901-3-gc693a90-dirty/package/node_modules/.npm/heatmap/0.0.1/package/lib/heatmap.js")
    fc43458c line_offset = 0 (SMI: value = 0)
    fc434590 column_offset = 0 (SMI: value = 0)
    fc434594 data = fe88e05d (Oddball: "undefined")
    fc434598 context_data = fe88e05d (Oddball: "undefined")
    fc43459c wrapper = fc400bf1 (<unknown>)
    fc4345a0 type = 4 (SMI: value = 2)
    fc4345a4 compilation_type = 0 (SMI: value = 0)
    fc4345a8 line_ends = fe88e05d (Oddball: "undefined")
    fc4345ac id = 96 (SMI: value = 75)
    fc4345b0 eval_from_shared = fe88e05d (Oddball: "undefined")
    fc4345b4 eval_from_instructions_offset = 0 (SMI: value = 0)
}

See the “name” field. (Interestingly, the “Script” object includes as a member the source code of the script itself, but we only print out the first 255 characters or so.)

You can now see how the JavaScript-level dcmds work based on the lower-level V8 facilities.

Finally, we can look back at the ::jsframe output to get the argument pointers and then print out the corresponding values. We saw that arg2 was “fc070719”, a JSObject, and we can print it out with ::jsprint:

> fc070719::jsprint
{
    base: 1320886447,
    weighbyrange: false,
    height: 281,
    width: 624,
    nbuckets: 50,
    max: 11538462,
    nsamples: 30,
    hue: [ 21 ],
    linear: false,
    min: 11538462,
}

The way the dmod extracts the object’s properties is surprisingly complex and beyond the scope of this document.

I hope this documentation is helpful for people looking to debug Node programs. Expect more information and examples in the coming weeks.

  1. For the curious, the postmortem support for V8 is contained in two illumos commits (1, 2) plus a V8 patch that has not yet landed. The illumos commits include support for the versions of V8 from Node.js 0.4.8 through 0.6.6 (and possibly later) so that you don’t actually need the V8 patch yet. ↩︎