February 11, 2015 - by Dave Pacheco
Node.js provides the richest postmortem debugging facilities of just about any dynamic language. Postmortem debugging refers to debugging programs from a core file, heap dump, or some similar dump of memory. With a core file of a Node program (which is essentially a snapshot of your program's state), you can:
The postmortem approach has several advantages over other debugging techniques:
You can save core files of running programs using gcore(1) on most systems, and you can configure Node to generate a core file when it crashes using the --abort-on-uncaught-exception
flag. Although MDB only runs on illumos-based systems (like SmartOS), it can read core files from GNU/Linux systems as well.
If this is the first you've heard of debugging Node from core files, you'll want to check out the Node.js MDB intro. The rest of this post is just a summary of changes.
These changes are part of the debugger module that ships with Node 0.12, but you can use this module on core files from versions of Node as far back as 0.4. So you can use these features today before even upgrading your programs to use Node 0.12.
::jsstack
In previous versions, ::jsstack
's default output includes a lot of information that's not relevant for JavaScript-only problems and is frequently overwhelming for new users. After these changes, it hides internal frames, frame pointers, and instruction pointers by default. It also chops long C++ symbol names to fit lines at 80 columns.
Before:
> ::jsstack
8043190 0xb4e1a5ee MyObject (ba780b15)
80431b4 0x94e0fba9
80431c8 0xb4e1096c (as ) (ba7b3d59)
8043200 0x94e645bf (as EventEmitter.emit) (93f24ad9)
804321c 0x94e0f7a1
8043240 0xb4e0f9c0 (as parser.onIncoming) (92609b45)
804327c 0xb4e0c9f3 parserOnHeadersComplete (ba7917e9)
804329c 0x94e0fe19
80432d8 0x94e0a0aa
8043348 _ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0xef
...
8047c98 uv_run+0xea
8047d08 node::Start+0x17b
8047d28 main+0x1b
8047d40 _start+0x83
After:
> ::jsstack
js: MyObject
(1 internal frame elided)
js: (as )
js: (as EventEmitter.emit)
(1 internal frame elided)
js: (as parser.onIncoming)
js: parserOnHeadersComplete
(1 internal frame elided)
(1 internal frame elided)
native: _ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0...
...
native: uv_run+0xea
native: node::Start+0x17b
native: main+0x1b
native: _start+0x83
You can get the full native details with "-a" (for "all frames and information").
this
pointer and constructor names in ::jsstack -v
output::jsstack -v
now includes the this
pointer. Also, when it prints out object pointers (for this
as well as function arguments), they include the constructor name.
Before:
> ::jsstack -vn0
8043190 0xb4e1a5ee MyObject (ba780b15)
file: /root/example.js
posn: position 62
80431b4 0x94e0fba9
80431c8 0xb4e1096c (as ) (ba7b3d59)
file: /root/example.js
arg1: ba7ceb01 (JSObject)
arg2: ba7cf781 (JSObject)
posn: position 595
...
After:
> ::jsstack -vn0
js: MyObject
file: /root/example.js
posn: position 62
(1 internal frame elided)
js: (as )
file: /root/example.js
posn: position 595
this: ba7b3d7d (JSObject: Server)
arg1: ba7ceb01 (JSObject: IncomingMessage)
arg2: ba7cf781 (JSObject: ServerResponse)
...
::jsconstructor
: print constructor of a JavaScript objectGiven an object, you can print the constructor that was used to create it:
> ba7ce109::jsconstructor
SlowBuffer
> ba7ce781::jsconstructor
Object
> ba7cdb75::jsconstructor
HTTPParser
With "-v", the command prints out a pointer to the constructor function:
> ba7b3d7d::jsconstructor -v
Server (JSFunction: ba791bbd)
which is useful for passing to ::jssource
(see next).
::jssource
: print source for a JavaScript functionGiven a function, you can print the source code for it:
> 88a21d0d::jssource -n1
file: http.js
1963
1964 socket.addListener('error', function(e) {
1965 self.emit('clientError', e, this);
1966 });
1967
This closure is an instance of the anonymous function defined inline.
::nodebuffer
: fetch native pointer for a bufferWhen debugging memory leaks using ::findjsobjects
, you may find that you have a ton of Buffer objects. These represent chunks of memory from the native heap. You often want to know what that memory contains. With the ::nodebuffer
command, you can take one of these Buffers:
> b1a9ec5d::jsconstructor
Buffer
> b1a9ec5d::jsprint
{
"length": 1423,
"parent": {
"length": 8192,
"used": 7272,
},
"offset": 0,
}
and get a pointer to the underlying C memory:
> b1a9ec5d::nodebuffer
8db8c08
Then you can use ::dump (for example) to see what that memory actually contains:
> 8db8c08,0t64::dump
0 1 2 3 4 5 6 7 \/ 9 a b c d e f 01234567v9abcdef
8db8c00: 08200000 f89f103a 00000007 6f707469 . .....:....opti
8db8c10: 6f6e7300 00000468 65616400 00000470 ons....head....p
8db8c20: 6f737400 00000370 75740000 00066465 ost....put....de
8db8c30: 6c657465 00000005 74726163 65000000 lete....trace...
8db8c40: 06616363 65707400 00000e61 63636570 .accept....accep
This often points you to a particular HTTP request handler or other code path in your program.
::jsfunctions
: list closuresfindjsobjects
is very helpful for identifying classes of objects with many instances. Once you've found which objects are being leaked, you can use findjsobjects -r
to find out which objects reference the leaked one. Sometimes memory is not referenced by other objects, but rather by closures: JavaScript functions that are pending and may be invoked some time in the future. The new jsfunctions
command lists all functions in your JavaScript program, and how many different closures have been created for each one:
> ::jsfunctions
FUNC #FUNCS NAME FROM
...
8803e63d 1667 (as parser.onIncoming) http.js position 58040
880389c5 543 (as ) _stream_readable.js position 26340
88038921 543 (as ) _stream_writable.js position 8134
880388d5 543 (as cb) _stream_writable.js position 5923
8800be75 587 (as ) /home/dap/demo/restify-ex.js position 616
8800be35 2114 _ifError /home/dap/demo/node_modules/restify/lib/server.js position 2846
8800b229 691 (as ) net.js position 12228
880099a1 1755 (as ) http.js position 55840
8800997d 1755 (as ) http.js position 54999
88009939 1696 socketOnDrain http.js position 57774
88009915 2234 serverSocketCloseListener http.js position 54505
880098f1 2234 abortIncoming http.js position 54314
88009885 1754 g events.js position 5742
...
You can take one of these functions and print the source. Here's abortIncoming()
:
> 880098f1::jssource
file: http.js
1907 function connectionListener(socket) {
1908 var self = this;
1909 var outgoing = [];
1910 var incoming = [];
1911
1912 function abortIncoming() {
1913 while (incoming.length) {
1914 var req = incoming.shift();
1915 req.emit('aborted');
1916 req.emit('close');
1917 }
1918 // abort socket._httpMessage ?
1919 }
1920
1921 function serverSocketCloseListener() {
1922 debug('server socket close');
1923 // mark this parser as reusable
1924 if (this.parser)
1925 freeParser(this.parser);
Note that it's defined inside the connectionListener
function. This explains why we have 2234 closures for it. Each time connectionListener
is called, a new closures of abortIncoming
is created to close around socket
, self
, outgoing
, and incoming
.
As with findjsobjects
, the exact count in the jsfunctions
list may be misleading, but large values often reflect memory leaks.
::v8internal
: fetch internal fieldsNative code that uses the V8 API (whether part of Node.js itself or part of an add-on) often uses internal fields, which are essentially slots inside an object for storing internal data. For example, Node classes like TcpWrap typically store the underlying libuv handle as internal field 0. So if you have a TCP object, then you can grab internal field 0 to get the underlying libuv handle.
We're working on a few more impressive tools using jsfunctions
. Stay tuned
for details!
For help, file a Node issue or reach out to @dapsays, @tjfontaine, or @misterdjules on Twitter. Joyent also offers Nodejs Support that builds heavily on these tools.