Node.js Postmortem Debugging for Fun and Production
Colin J. Ihrig
This post originally appeared as part of JavaScript January 2018.
Tools like the V8 Inspector are fantastic for debugging during development, or when known steps exist for reproducing a bug. Unfortunately, production environments don't lend themselves as well to analysis using these tools. Stopping a production server while stepping through instructions would lead to a poor user experience, making it impractical.
The shortcomings of traditional debugging tools have lead to the rise of a separate class of debugging, referred to as postmortem debugging. This typically consists of capturing a core dump of a process when it crashes, restarting the process, and analyzing the core dump offline. This allows the process to be debugged while keeping the production system running.
This article explores the postmortem debugging process in more detail, including how to capture core dumps, and how those dumps can be analyzed using the llnode tool. For the purposes of this article, Node 8.9.3, llnode 1.6.2, and the latest LLVM are assumed. Unfortunately, many of the techniques described in this article do not currently apply to Windows operating systems, although there are efforts underway to improve this.
Core Dumps
A core dump is the exact state of an application's memory at the time of an abnormal exit. Because a dump contains everything in memory, core files are large (typically over a gigabyte) and usually not captured by default. Imagine the implications for disk utilization if a process repeatedly crashed and created a large core file each time. Cores are also disabled by default because they represent a potential information leak. Any sensitive information, such as credentials or personal information, that is in memory when the process crashes will be included in the core dump. The ulimit -c
command can verify if core files are written or not, as shown in Listing 1. In this example, the value of 0 indicates that no core files are written.
$ ulimit -c
0
Listing 1. Displaying core file size limit using ulimit -c
.
Enabling core dump capture is possible using the command ulimit -c unlimited
. Listing 2 enables core dump capture, and then queries the value to verify that it has been set. At this point, core files are enabled, but note that this setting does not persist across shell sessions.
$ ulimit -c unlimited
$ ulimit -c
unlimited
Listing 2. Setting core file size using ulimit -c
.
When a process dumps core, the location of the core file will vary depending on operating system. On macOS, the core file is placed in /cores/core.PID
, where PID
is the process ID. On Linux, the core file location defaults to the current directory, although there are ways to configure this.
Creating Core Dumps
At this point, core dumps have been enabled, and their location has been determined. It is now time to begin creating core files. There are multiple ways to do this. The simplest way is to send the SIGABRT
signal to the process. An example of this is shown in Listing 3. In this example, pid
corresponds to the process ID of the application whose core is being dumped.
kill -SIGABRT pid
Listing 3. Example of creating a core dump using the SIGABRT
signal.
Another way to create a core file is to call process.abort()
from the Node application, as shown in Listing 4.
'use strict';
process.on('uncaughtException', function onUncaughtException (err) {
process.abort();
});
throw new Error('this is uncaught');
Listing 4. Example that calls process.abort()
on uncaught exception.
The previous example throws an exception. The exception triggers the uncaughtException
handler, which aborts the process and dumps core. This approach has a few drawbacks. First, the application code must be modified to use the ill-advised uncaughtException
event, and explicitly call process.abort()
. Second, when it comes time to analyze the core file, it will contain additional stack frames related to emitting the uncaughtException
event, that aren't relevant to debugging the crash. There is no need to add complexity to the problem of tracking down production bugs!
An alternative, and preferred approach is to pass the --abort-on-uncaught-exception
command line argument to Node. As its name implies, this flag causes Node to abort and dump core when an uncaught exception occurs. This allows the uncaughtException
handler from Listing 4 to be removed, leaving only the code in Listing 5. Assuming that the code is saved in a file named exception.js
, execute the command shown in Listing 6. The result should be a process crash and the creation of a new core file.
'use strict';
throw new Error('this is uncaught');
Listing 5. Code from Listing 4 without the uncaughtException
handler.
$ node --abort-on-uncaught-exception exception.js
Listing 6. Launching Node with the --abort-on-uncaught-exception
flag.
Note. Core dumps can also be created for running processes without crashing the process. The
gcore
utility and thelldb
debugger (covered later) are examples of applications that can do this. They are not covered in detail here, but the core files that they generate can be analyzed in the same fashion described in this article.
Analyzing Core Files with LLDB
LLDB is a debugger for applications written using the C language family. It can be used as a step debugger, but also supports core file inspection, making it extremely useful for postmortem debugging. At this time, please install the newest version of LLDB on your machine if you have not already done so. Once LLDB is installed, core dumps can be analyzed using the command shown in Listing 7.
$ lldb path_to_node_executable -c path_to_core_file
Listing 7. Analyzing a core file using LLDB.
In the previous command, path_to_node_executable
can typically just be node
to debug the version of Node located in the user's $PATH
. Node executables outside of the user's $PATH
can be referenced by providing an absolute or relative path to the binary. The path_to_core_file
following the -c
argument specifies the location of the core file to analyze. Running this command with real data should yield output similar to Listing 8.
(lldb) target create \"node\" --core \"/cores/core.99710\"
Core file '/cores/core.99710' (x86_64) was loaded.
(lldb)
Listing 8. Sample output from running the command in Listing 7.
The first two lines of Listing 8 show that the node
executable and /cores/core.99710
core file are loaded. For the purposes of this article, core.99710
is the core dump from Listing 7. The final line of output is the LLDB command prompt. Typing help
at the prompt displays information on the available LLDB commands.
Displaying Stack Traces
The bt
command, or the more verbose thread backtrace
, is used to view the state of the stack when the core dump was created. An example use of the bt
command and its output is shown in Listing 9. The first line of output, starting with * thread
, describes the state of the main thread. Although JavaScript is single threaded, recall that libuv utilizes a thread pool, so there are other threads that can be inspected. The thread line contains the following information:
- The thread index (
#1
). This is a thread ID, guaranteed to be unique as threads are created and destroyed during execution. This is largely not applicable for Node applications. - The reason that the thread stopped (
signal SIGSTOP
).
(lldb) bt
* thread #1, stop reason = signal SIGSTOP
* frame #0: 0x0000000100b26ed2 node`v8::base::OS::Abort() + 18
frame #1: 0x000000010064be13 node`v8::internal::Isolate::Throw(v8::internal::Object*, v8::internal::MessageLocation*) + 835
frame #2: 0x00000001007f6b5b node`v8::internal::Runtime_Throw(int, v8::internal::Object**, v8::internal::Isolate*) + 59
frame #3: 0x000004e36ee0463d
frame #4: 0x000004e36ef0443a
frame #5: 0x000004e36eebf9ce
frame #6: 0x000004e36eef4048
frame #7: 0x000004e36eebf9ce
frame #8: 0x000004e36eef474a
frame #9: 0x000004e36eebf9ce
frame #10: 0x000004e36eef474a
frame #11: 0x000004e36eebf9ce
frame #12: 0x000004e36eef45fc
frame #13: 0x000004e36eebf9ce
frame #14: 0x000004e36eef5002
frame #15: 0x000004e36eebf9ce
frame #16: 0x000004e36eef4048
frame #17: 0x000004e36eebf9ce
frame #18: 0x000004e36ef12229
frame #19: 0x000004e36eebf9ce
frame #20: 0x000004e36eef4da1
frame #21: 0x000004e36eebf9ce
frame #22: 0x000004e36eebe479
frame #23: 0x000004e36ee0410d
frame #24: 0x000000010051b267 node`v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, bool, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, v8::internal::Handle<v8::internal::Object>, v8::internal::Execution::MessageHandling) + 679
frame #25: 0x000000010051af2e node`v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) + 158
frame #26: 0x00000001001e358d node`v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) + 381
frame #27: 0x0000000100981699 node`node::LoadEnvironment(node::Environment*) + 612
frame #28: 0x0000000100989954 node`node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) + 468
frame #29: 0x0000000100983b23 node`node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) + 454
frame #30: 0x0000000100982f7a node`node::Start(int, char**) + 469
frame #31: 0x0000000100001a34 node`start + 52
Listing 9. Sample output from running the bt
command.
After the thread information, each stack frame is listed, starting with the most recently called. Most stack frames contain the following information (frame #0 is used as a reference):
- The frame index (
frame #0
). The frame's position on the call stack. The lowest numbered frame represents the function that was executing when the core dump was created. - The frame's program counter as a hex address (
0x0000000100b26ed2
). - The file basename (
node
). - The executing function (
v8::base::OS::Abort()
) and its formal parameters. - The program counter offset within the function (
+ 18
).
Notice that frames #3-23 are missing much of their context. These frames represent the time spent in JavaScript, as opposed to compiled C++. LLDB does not have insight into JavaScript by default because V8 generates the machine code at runtime. Luckily, the llnode plugin, described later in this article, can mitigate that problem.
Note. To view the stack traces for all threads use
bt all
, or the more verbosethread backtrace all
. This is useful for inspecting the libuv threadpool and any user-created threads. To display only then
most recent stack frames usebt n
orthread backtrace -c n
. This is useful when the entire stack trace is not needed.
Working with Stack Frames
The asterisk to the left of frame #0
in Listing 9 indicates the currently selected frame. At any point, the currently selected frame can be printed using the frame info
command, as shown in Listing 10.
(lldb) frame info
frame #0: 0x0000000100b26ed2 node`v8::base::OS::Abort() + 18
Listing 10. Example use of the frame info
command.
It is possible to switch between frames using the frame select
command. This will be very helpful when llnode is introduced. An example that selects frame #2
is shown in Listing 11. The command output shows the frame information, as well as a snippet of the frame's assembly code. At this point, the bt
and frame info
commands will report frame #2
as the selected frame.
(lldb) frame select 2
frame #2: 0x00000001007f6b5b node`v8::internal::Runtime_Throw(int, v8::internal::Object**, v8::internal::Isolate*) + 59
node`v8::internal::Runtime_Throw:
0x1007f6b5b <+59>: movq %rax, %r14
0x1007f6b5e <+62>: movq %r12, 0x19e8(%rbx)
0x1007f6b65 <+69>: decl 0x19f8(%rbx)
0x1007f6b6b <+75>: cmpq %r15, 0x19f0(%rbx)
Listing 11. Example use of the frame info
command.
Frames can also be selected relative to the current frame by passing the --relative
or -r
option to frame select
. Assuming that frame #2
is selected, the command frame select -r -1
would move to frame #1
, while frame select -r 1
would move to frame #3
.
It is also worth pointing out that similar commands exist for navigating threads. For example, thread info
and thread select
work like their frame
counterparts. In the case of typical Node.js applications, the main thread will contain the majority of the useful information.
The llnode Plugin
llnode is a plugin that enhances LLDB by giving it insight into the JavaScript runtime. llnode is an officially supported project of the Node.js Foundation. Building and installation instructions for macOS and Linux are available on the project's GitHub page. It can also be installed from npm. Once installed, issue the command shown in Listing 12 to view the available llnode commands. Note that all llnode commands are within the v8
namespace.
(lldb) v8 help
Listing 12. Command to view llnode's help.
Inspecting the JavaScript Stack
The v8 bt
command displays a stack trace similar to the native bt
command. However, v8 bt
includes JavaScript information. Listing 13 shows example output from the v8 bt
command. In this example, the C++ stack frames have been removed, as they are identical to the ones from Listing 9.
Frames #23 (<entry>
) and #22 (<internal>
) represent entering the JavaScript runtime from C++. Similarly, frame #3 (<exit>
) corresponds to exiting the JavaScript runtime. These three frames, and the various <stub>
frames are internal to V8 and provide limited information. However, the other JavaScript frames offer substantial information. Frame #5, for example, corresponds to the simple code from Listing 5. Frame #5 contains the following information:
- The function name (
(anonymous)
). In this case, the anonymous function in question is the Node module wrapper. - The address (
0x00000b5e0a607e11
) and data type (<Object: Object>
) of the function'sthis
value. - The function's arguments. The module wrapper provides the following values:
exports
(0x00000b5e0a607e11:<Object: Object>
)require()
(0x00000b5e0a6088d9:<function: require at (external).js:8:19>
)module
(0x00000b5e0a607d49:<Object: Module>
)__filename
(0x00000b5e0a607931:<String: \"/private/tmp/exc...\">
)__dirname
(0x00000b5e0a608871:<String: \"/private/tmp\">
)
- The location of the function in the source code (
/private/tmp/exception.js:1:10
). - The address of the function (
0x00000b5e0a608829
).
(lldb) v8 bt
... Thread information and frames #0-2 omitted ...
frame #3: 0x000004e36ee0463d <exit>
frame #4: 0x000004e36ef0443a <stub>
frame #5: 0x000004e36eebf9ce (anonymous)(this=0x00000b5e0a607e11:<Object: Object>, 0x00000b5e0a607e11:<Object: Object>, 0x00000b5e0a6088d9:<function: require at (external).js:8:19>, 0x00000b5e0a607d49:<Object: Module>, 0x00000b5e0a607931:<String: \"/private/tmp/exc...\">, 0x00000b5e0a608871:<String: \"/private/tmp\">) at /private/tmp/exception.js:1:10 fn=0x00000b5e0a608829
frame #6: 0x000004e36eef4048 <stub>
frame #7: 0x000004e36eebf9ce Module._compile(this=0x00000b5e0a607d49:<Object: Module>, 0x00000b5e0a608541:<String: \"'use strict';
t...\">, 0x00000b5e0a607931:<String: \"/private/tmp/exc...\">) at module.js:592:37 fn=0x00000b5e3f709b91
frame #8: 0x000004e36eef474a <stub>
frame #9: 0x000004e36eebf9ce Module._extensions..js(this=0x00000b5e7353b451:<Object: Object>, 0x00000b5e0a607d49:<Object: Module>, 0x00000b5e0a607931:<String: \"/private/tmp/exc...\">) at module.js:644:37 fn=0x00000b5e3f709bd9
frame #10: 0x000004e36eef474a <stub>
frame #11: 0x000004e36eebf9ce Module.load(this=0x00000b5e0a607d49:<Object: Module>, 0x00000b5e0a607931:<String: \"/private/tmp/exc...\">) at module.js:545:33 fn=0x00000b5e3f709b01
frame #12: 0x000004e36eef45fc <stub>
frame #13: 0x000004e36eebf9ce tryModuleLoad(this=0x00000b5e46302311:<undefined>, 0x00000b5e0a607d49:<Object: Module>, 0x00000b5e0a607931:<String: \"/private/tmp/exc...\">) at module.js:494:23 fn=0x00000b5eea5aa3a1
frame #14: 0x000004e36eef5002 <stub>
frame #15: 0x000004e36eebf9ce Module._load(this=0x00000b5ebce03d31:<function: Module at module.js:66:16>, 0x00000b5e0a607339:<String: \"/private/tmp/exc...\">, 0x00000b5e46302201:<null>, 0x00000b5e463023b1:<true>) at module.js:440:24 fn=0x00000b5e3f709a41
frame #16: 0x000004e36eef4048 <stub>
frame #17: 0x000004e36eebf9ce Module.runMain(this=0x00000b5ebce03d31:<function: Module at module.js:66:16>) at module.js:674:26 fn=0x00000b5e3f709cb1
frame #18: 0x000004e36ef12229 <stub>
frame #19: 0x000004e36eebf9ce startup(this=0x00000b5e46302311:<undefined>) at bootstrap_node.js:1:10 fn=0x00000b5ebce09ab9
frame #20: 0x000004e36eef4da1 <stub>
frame #21: 0x000004e36eebf9ce (anonymous)(this=0x00000b5e46302201:<null>, 0x00000b5ebce09b51:<Object: process>) at bootstrap_node.js:1:10 fn=0x00000b5ebce09ba1
frame #22: 0x000004e36eebe479 <internal>
frame #23: 0x000004e36ee0410d <entry>
... Frames #24-31 omitted ...
Listing 13. Example v8 bt
command and output.
All of the addresses associated with these values can be inspected in more detail using the v8 inspect
command, shortened as v8 i
. For example, the module
variable, located at address 0x00000b5e0a607d49
, can be inspected as shown in Listing 14.
(lldb) v8 i 0x00000b5e0a607d49
0x00000b5e0a607d49:<Object: Module properties {
.id=0x00000b5e46303289:<String: \".\">,
.exports=0x00000b5e0a607e11:<Object: Object>,
.parent=0x00000b5e46302201:<null>,
.filename=0x00000b5e0a607931:<String: \"/private/tmp/exc...\">,
.loaded=0x00000b5e46302421:<false>,
.children=0x00000b5e0a607e59:<Array: length=0>,
.paths=0x00000b5e0a6080f1:<Array: length=17>}>
Listing 14. Inspecting the module
variable using the v8 inspect
command.
module
is a Module
instance with a filename
property. This property specifies the source code file for the module, but unfortunately, the filename has been truncated. Listing 15 shows how the filename
property, located at address 0x00000b5e0a607931
, can be inspected with more precision. The first command uses the --full-string
flag (abbreviated as -F
) to print the string in its entirety. The second command truncates strings at a user-defined length of 10 via the --length
flag. Array printing can be similarly controlled with --length
.
(lldb) v8 i --full-string 0x00000b5e0a607931
0x00000b5e0a607931:<String: \"/private/tmp/exception.js\">
(lldb) v8 i --length 10 0x00000b5e0a607931
0x00000b5e0a607931:<String: \"/private/t...\">
Listing 15. Controlling string lengths with v8 inspect
.
If the address passed to v8 inspect
refers to a function, that function's source code can be printed using the --print-source
(-s
) flag. For example, the main module's require()
function is located at address 0x00000b5e0a6088d9
. This code can be displayed as shown in Listing 16. In addition to the source code, notice that other useful function features are included for inspection, such as the context and closure.
(lldb) v8 i -s 0x00000b5e0a6088d9
0x00000b5e0a6088d9:<function: require at (external).js:8:19
context=0x00000b5e0a608899{
(previous)=0x00000b5eea590df1
(closure)=0x00000b5eea58e0e1 {<function: makeRequireFunction at (external).js:5:29>},
mod=0x00000b5e0a607d49:<Object: Module>,
Module=0x00000b5ebce03d31:<function: Module at module.js:66:16>}
source:
function require(path) {
try {
exports.requireDepth += 1;
return mod.require(path);
} finally {
exports.requireDepth -= 1;
}
}
>
Listing 16. Displaying function source code using v8 inspect
.
Passing the --print-map
or -m
flag to v8 inspect
causes the object's map address to be printed. A JavaScript object's map describes the layout of the object. For example, the map address of module
is included in Listing 17. The output in Listing 17 is identical to the output in Listing 14, with the exception of the added (map=0x00000b5e371414f9)
. This value can then be analyzed separately using v8 inspect
, as shown in Listing 18.
(lldb) v8 i -m 0x00000b5e0a607d49
0x00000b5e0a607d49(map=0x00000b5e371414f9):<Object: Module properties {
.id=0x00000b5e46303289:<String: \".\">,
.exports=0x00000b5e0a607e11:<Object: Object>,
.parent=0x00000b5e46302201:<null>,
.filename=0x00000b5e0a607931:<String: \"/private/tmp/exc...\">,
.loaded=0x00000b5e46302421:<false>,
.children=0x00000b5e0a607e59:<Array: length=0>,
.paths=0x00000b5e0a6080f1:<Array: length=17>}>
Listing 17. Displaying an object's map address using v8 inspect
.
The output in Listing 18 shows all of the own properties (id
, exports
, etc.) of the module
object. The number of own properties corresponds to own_descriptors=7
.
(lldb) v8 i 0x00000b5e371414f9
0x00000b5e371414f9:<Map own_descriptors=7 in_object=14 instance_size=136 descriptors=0x00000b5e0a605281:<FixedArray, len=23 contents={
[0]=<Smi: 7>,
[1]=0x00000b5e0a609561:<FixedArray, len=2>,
[2]=0x00000b5e4634aa49:<String: \"id\">,
[3]=<Smi: 3584>,
[4]=<Smi: 1>,
[5]=0x00000b5e9bf82ae1:<String: \"exports\">,
[6]=<Smi: 1049088>,
[7]=<Smi: 1>,
[8]=0x00000b5e9bfef169:<String: \"parent\">,
[9]=<Smi: 2102784>,
[10]=<Smi: 1>,
[11]=0x00000b5e9bfaf9d1:<String: \"filename\">,
[12]=<Smi: 3150336>,
[13]=<Smi: 1>,
[14]=0x00000b5e9bfb05e9:<String: \"loaded\">,
[15]=<Smi: 4195840>,
[16]=<Smi: 1>,
[17]=0x00000b5efa5bdc59:<String: \"children\">,
[18]=<Smi: 5249536>,
[19]=<Smi: 1>,
[20]=0x00000b5e9bfb0009:<String: \"paths\">,
[21]=<Smi: 6294016>,
[22]=<Smi: 1>}>>
Listing 18. Analyzing an object map using v8 inspect
.
Printing JavaScript Source Code
llnode's v8 source list
command prints a snippet of the selected stack frame's source code. An example of this is shown in Listing 19. In this example, frame select 5
is used to select a JavaScript frame. Then, v8 source list
is used to print the frame's source code. Note that all
in v8 source list all
is not normally required, but is necessary to work around a bug in version 1.6.2 of llnode.
(lldb) frame select 5
frame #5: 0x000004e36eebf9ce
0x4e36eebf9ce: movq -0x20(%rbp), %rbx
0x4e36eebf9d2: movl 0x2b(%rbx), %ebx
0x4e36eebf9d5: leave
0x4e36eebf9d6: popq %rcx
(lldb) v8 source list all
1 (function (exports, require, module, __filename, __dirname) { 'use strict';
2
3 throw new Error('this is uncaught');
4
Listing 19. Printing JavaScript source code using v8 source list
.
v8 nodeinfo
Command
The To display information about the Node.js executable, issue the command v8 nodeinfo
as shown in Listing 20. The output includes useful information such as dependency versions, release information, the executable path, and command line information. The addresses of process
, process.versions
, process.release
, process.argv
, and process.execArgv
are also included, allowing them to be inspected using the v8 inspect
command.
(lldb) v8 nodeinfo
Information for process id 99710 (process=0xb5ebce09b51)
Platform = darwin, Architecture = x64, Node Version = v8.9.3
Component versions (process.versions=0xb5eea5ab769):
cldr = 31.0.1
icu = 59.1
tz = 2017b
unicode = 9.0
Release Info (process.release=0xb5eea5ab8d1):
Executable Path = /Users/cjihrig/.nvm/versions/node/v8.9.3/bin/node
Command line arguments (process.argv=0xb5eea5ab8b1):
[0] = '/Users/cjihrig/.nvm/versions/node/v8.9.3/bin/node'
[1] = '/private/tmp/exception.js'
Node.js Comamnd line arguments (process.execArgv=0xb5eea5ab6b1):
[0] = '--abort-on-uncaught-exception'
Listing 20. Displaying Node.js information using v8 nodeinfo
.
v8 findjsobjects
Command
The The v8 findjsobjects
command outputs a list of all JavaScript object types. The list includes the type names, the number of instances of each type, and the total size of each type. The list is sorted in ascending order of instance count. An example of this command is shown in Listing 21.
(lldb) v8 findjsobjects
Instances Total Size Name
---------- ---------- ----
1 24 AssertionError
1 24 AsyncResource
1 24 FastBuffer
1 24 Instance
1 24 Loader
1 24 Memory
1 24 ModuleJob
1 24 ModuleMap
1 24 Performance
1 24 PerformanceObserver
1 24 SafeMap
1 24 SafePromise
1 24 SafeSet
1 24 Table
1 24 TextDecoder
1 24 TextEncoder
1 24 TickObject
1 24 URL
1 24 URLContext
1 24 URLSearchParams
1 24 WebAssembly
1 24 console
1 24 listen
1 32 (Object)
1 104 ImmediateList
1 104 Stack
1 112 Console
2 48 (anonymous)
2 48 process
2 64 ChannelWrap
2 64 Signal
2 120 Resolver
2 128 PerformanceNodeTiming
2 136 NextTickQueue
2 152 AsyncHook
2 200 PerformanceObserverEntryList
2 608 ReadableState
2 640 WritableState
3 72 NodeError
3 96 TTY
3 248 BufferList
3 296 Module
3 312 WriteStream
10 320 ContextifyScript
11 880 (ArrayBufferView)
53 3392 NativeModule
331 10592 (Array)
624 35048 Object
6806 64064 (String)
---------- ----------
7899 118432
Listing 21. Example output of the v8 findjsobjects
command.
v8 findjsinstances
Command
The v8 findjsobjects
provides a high-level view of the existing JavaScript objects, and serves as an excellent starting point when dissecting a core file. However, a more fine-grained analysis is often required when dealing with production problems. That is where the v8 findjsinstances
command comes into play. v8 findjsinstances
takes a constructor name as input, and outputs a list of all objects created with that constructor.
Based on the output from Listing 21, there are three Module
instances in the core dump. These instances are inspected in more detail using v8 findjsinstances
in Listing 22. The resulting output isn't overly helpful on its own, but it does include the address of the Module
instances, meaning that they can be analyzed using v8 inspect
.
(lldb) v8 findjsinstances Module
0x00000b5e0a604bc1:<Object: Module>
0x00000b5e0a607d49:<Object: Module>
0x00000b5e9bfa7189:<Object: Module>
Listing 22. Example output of the v8 findjsinstances
command.
Note.
v8 findjsinstances
accepts the same flags asv8 inspect
.
v8 findrefs
Command
The Locating and inspecting JavaScript objects is not always sufficient in diagnosing a problem. For example, in the case of a memory leak, it is often necessary to identify the references to an object. llnode provides this functionality via the v8 findrefs
command.
The result of v8 findrefs 0x00000b5e0a607d49
, the address of the main Module
instance found in Listing 22, is shown in Listing 23. The resulting output shows that the Module
instance is referenced from four places in the core dump. Each line of output indicates the address of the referring object, followed by a short description. For example, the last line of output indicates that the referring object's address is 0xb5e0a607d49
. In this case, the referring object is process
, and its mainModule
property is the Module
instance in question.
(lldb) v8 findrefs 0x00000b5e0a607d49
0xb5e0a608e79: (Array)[6]=0xb5e0a607d49
0xb5e0a608e79: (Array)[16]=0xb5e0a607d49
0xb5e7353b421: Object./private/tmp/exception.js=0xb5e0a607d49
0xb5ebce09b51: process.mainModule=0xb5e0a607d49
Listing 23. Example output of the v8 findrefs
command.
Caveats
Postmortem debugging is a truly powerful way of analyzing production crash data. However, it does have limitations, which are important to understand. First, when analyzing a core file, it is imperative that the Node executable that created the core file is provided to LLDB. Tools like llnode use a set of postmortem metadata constants to properly parse the data in the core file. These constants are compiled into the Node executable, and vary from version to version of Node, and, more specifically the version of V8 included in Node. Therefore, llnode requires a core file and correct corresponding Node executable in order to function properly.
llnode's tight coupling to V8 implementation details also means that things break occasionally. This happens for several reasons. For example, one or more of the postmortem metadata constants could have its name changed, or be removed completely from V8. This would leave llnode unable to properly understand some aspects of the core file. Alternatively, V8's internal implementation can change such that the existing metadata or llnode implementation is no longer adequate. Developers of postmortem debugging tools are playing a constant game of catchup with the V8 implementation. Several examples of this can be seen throughout this very article. For example, in Listing 13, notice the string <function: require at (external).js:8:19>
. (external)
is meant to be a filename, but it is not displayed because an implementation detail in V8 has changed, and llnode has not yet caught up.
These limitations are annoying, but usually result in a debugging experience that is "good enough." However, the biggest issue with postmortem debugging at the moment is Promise support. Postmortem debugging is so powerful because developers get an exact snapshot of a process at the instant that is crashes. However, the asynchronous nature of a Promise rejection means that the state of the process can change significantly in the time between an exception occurring and the process aborting. This means the core file may not be as helpful as it otherwise could be.
In the past, Promise support was mostly viewed as a "nice to have" but not critical component of postmortem debugging because it was relatively easy for postmortem debugging users to blacklist Promises from their applications. However, the rise of async
/await
has the potential to substantially change the way JavaScript applications are written. This makes postmortem debugging support for Promises much more important. There is a fair amount of past and present investigation into solving this problem, and, ideally it will be solved in the near future.
Conclusion
This article has introduced postmortem debugging of Node.js applications. The concept of a core dump was introduced, and readers learned how to properly collect dumps from Node apps using the --abort-on-uncaught-exception
flag. From there, readers learned how to analyze the C/C++ bits of a core dump using LLDB, before moving on to the JavaScript aspects using the llnode plugin. After a fairly in depth exploration of llnode's functionality, the limitations of postmortem debugging were discussed. Thanks for reading, and hopefully you will add postmortem debugging to your skillset.