Taming the dragon

Using llnode to debug your Node.js application

If you ever experienced memory leaks or infinite loops in your applications, you know how frustrating can be to find the source of those issues. Even though Node.js has a Garbage Collector powered by V8, it is still possible to have memory leaks (or infinite memory growth) if we keep unnecessary references to objects.

One technique available to investigate those kinds of issues is postmortem debugging. Developers of native languages (such as C++ and Go) might be familiar with it, especially postmortem debugging of core dump files — files with a copy of the process memory at a given time.

Fortunately, we can use this same technique with our Node.js applications! This is possible through llnode: a LLDB plugin which enables us to inspect Node.js core dumps. With llnode, we can inspect objects in the memory and look at the complete backtrace of the program, including native (C++) frames and JavaScript frames. It can be used on a running Node.js application or through a core dump.

It’s dangerous to go alone. Take this!

llnode is available through npm and works on with active Node.js Release Lines (v6.x, v8.x, v9.x and v10.x by the time of this writing). Since it is a plugin for lldb, you’ll need to install it first. llnode works best on LLDB 3.9 or later.

On Mac OS you get lldb by installing Xcode. If you’re using Ubuntu though, you can install LLDB by running:

sudo apt install lldb-4.0 liblldb-4.0-dev

After lldb is installed, you can use npm install -g llnode to install llnode globally. Please be aware that if you’re not using Node.js through nvm or don’t have a global prefix set, you’ll need to run sudo install -g llnode.

Generating a core dump

llnode can either attach to a process or read a core dump file. In this tutorial we’ll focus on the latter, and because of that we need to first be able to generate core dumps.

There are two main methods to generate core dumps in Unix systems: you can either create a core dump from a running process or create one when the process crashes.

To generate a core dump of a running process, you can use gcore {PID}(Linux) or lldb --attach-pid {PID} -b -o 'process save-core "core.{PID}"' (OS X), replacing {PID} with the PID of your application. Both methods will create a core dump file called core.$PID at the current working directory.

If, however, you want to generate a core dump when your process crashes (useful to debug your application when it dies by memory starvation, for example), you’ll need to set the ulimit of your system by running ulimit -c unlimited. This will set ulimit for the current terminal session, which means you’ll need to set again if you open another terminal. Core dumps generated this way are saved in a file named core in the current working directory for Linux, while on OS X cores are stored in the /cores/ folder. Be careful on Mac OS, because core dumps can quickly fill your HD.

Another thing about generating core dumps when your process crashes: Node.js won’t crash when it terminates because of an uncaught exception. If you want to generate a core dump in those cases, you’ll need to run Node.js with --abort-on-uncaught-exception.

Taming the Dragon

Now that we have llnode installed and we know how to generate a core dump let’s learn how to use them together. We’ll be using a small Node.js HTTP server as an example:

First, let’s run this server:

$ node index.js
server is listening on 3000. Our PID is: **74262**

To make things interesting, let’s send some requests to this server with autocannon:

$ # Send requests to localhost:3000 during 10 seconds
$ npx autocannon -d 10 localhost:3000

Now we’ll generate a core dump of the running process. In this case, the PID is 74262. Remember to change the PID in the commands below with the PID of your Node.js process.

To generate a core dump on Linux, run the following:

$ sudo gcore **74262** 

If you are on OS X, you can run the following:

$ lldb --attach-pid **74262** -b -o 'process save-core "core.74262"'

Both commands will create a core dump in the current working directory with the name core.74262, and now we can use llnode to open it. llnode takes one required argument, which is the binary you want to debug (in this case, node) and a variety of optional arguments. Since we want to debug a core dump, we need to tell llnode where the core dump file is with -c {core-file}. The final command will look like:

$ llnode node -c core.**74262**
(llnode)

Let’s start with a command that prints information about Node.js and its dependencies. This command will also help us understand the syntax of the commands for llnode. On the (llnode) prompt, type v8 nodeinfo and press Enter:

(llnode) v8 nodeinfo
Information for process id 74262 (process=0x1ca4ddb89cb9)
Platform = darwin, Architecture = x64, **Node Version = v8.11.2**
Component versions (process.versions=0x1ca4b45a0379):
    cldr = 32.0
    icu = 60.1
    tz = 2017c
    unicode = 10.0
Release Info (process.release=0x1ca4b45a0451):
Executable Path = /Users/mmarchini/.nvm/versions/node/v8.11.2/bin/node
Command line arguments (process.argv=0x1ca4b45a0411):
    [0] = '/Users/mmarchini/.nvm/versions/node/v8.11.2/bin/node'
    [1] = '/Users/mmarchini/workspace/blog-posts/index.js'
Node.js Comamnd line arguments (process.execArgv=0x1ca4b45a0579):

llnode commands are prefixed by v8 + a space. This will help you distinguish between llnode and lldb commands. Speaking of help, v8 help will be your best friend from now on:

(llnode) v8 help
     Node.js helpers

Syntax:

The following subcommands are supported:

      **bt**              -- Show a backtrace with node.js JavaScript 
                         functions and their args. An optional 
                         argument is accepted; if that argument is a 
                         number, it specifies the number of frames 
                         to display. Otherwise all frames will be 
                         dumped.
                         Syntax: v8 bt [number]
      **findjsinstances** -- List every object with the specified type 
                         name. Use -v or --verbose to display 
                         detailed `v8 inspect` output for each 
                         object. Accepts the same options as 
                         `v8 inspect`
      **findjsobjects**   -- List all object types and instance counts     
                         grouped by type name and sorted by instance 
                         count. Use -d or --detailed to get an 
                         output grouped by type name, properties, 
                         and array length, as well as more 
                         information regarding each type.
      **findrefs**        -- Finds all the object properties which meet 
                         the search criteria. The default is to list 
                         all the object properties that reference 
                         the specified value.
                         Flags:
                         * -v, --value expr     - all properties 
                                                  that refer to the 
                                                  specified 
                                                  JavaScript object 
                                                  (default)
                         * -n, --name  name     - all properties 
                                                  with the specified     
                                                  name
                         * -s, --string string  - all properties 
                                                  that refer to the 
                                                  specified 
                                                  JavaScript string 
                                                  value
      **inspect**         -- Print detailed description and contents of 
                         the JavaScript value.
                         Possible flags (all optional):
                         * -F, --full-string    - print whole string 
                                                  without adding 
                                                  ellipsis
                         * -m, --print-map      - print object's map 
                                                  address
                         * -s, --print-source   - print source code 
                                                  for function 
                                                  objects
                         * -l num, --length num - print maximum of 
                                                  `num` elements 
                                                  from string/array
                         Syntax: v8 inspect [flags] expr
      **nodeinfo**        -- Print information about Node.js
      **print**           -- Print short description of the JavaScript 
                         value.
                         Syntax: v8 print expr
      **source**          -- Source code information

For more help on any particular subcommand, type 'help <command> <subcommand>'.

Yes, there’s a lot of information there. But don’t worry, we’ll go through the interesting commands now.

v8 findjsobjects

v8 findjsobjects lists all object types alongside their sizes and quantities. This is useful to find out which object types are using most of your memory. The first time you run this command might take a few minutes to process, so don’t worry if that happens.

(llnode) v8 findjsobjects
 Instances  Total Size Name
 ---------- ---------- ----
          1         24 AssertionError
          1         24 AsyncResource
          1         24 Control
          1         24 FastBuffer
          1         24 Loader
          1         24 ModuleJob
          1         24 ModuleMap
          1         24 Performance
          1         24 PerformanceObserver
          1         24 SafeMap
          1         24 SafePromise
          1         24 SafeSet
          1         24 SocketListReceive
          1         24 SocketListSend
          1         24 TextDecoder
          1         24 TextEncoder
          1         24 URL
          1         24 URLContext
          1         24 URLSearchParams
          1         24 WebAssembly
          1         32 (Object)
          1         32 ContextifyScript
          1        104 ImmediateList
          1        104 Stack
          1        128 Server
          1        168 Agent
          2         48 (anonymous)
          2         48 process
          2         64 ChannelWrap
          2         64 Signal
          2        120 Resolver
          2        128 PerformanceNodeTiming
          2        136 NextTickQueue
          2        144 FreeList
          2        200 PerformanceObserverEntryList
          2        208 EventEmitter
          2        208 WriteStream
          2        224 Console
          2        272 Module
          3         72 NodeError
          3         96 TTY
          3        280 AsyncHook
          4        128 Timer
          6        432 TimersList
         10       2480 Socket
         11        352 HTTPParser
         11        352 WriteWrap
         12        384 TCP
         12       2688 WritableState
         15       1360 (ArrayBufferView)
         74       4736 NativeModule
       5715    1234440 IncomingMessage
       5744     781184 ServerResponse
       5747    1103424 ReadableState
       5748     275880 BufferList
      45980    2942680 TickObject
      69344    2219008 (Array)
     **235515    9420584 Visit**
     293720   15437744 Object
     615411    3750984 (String)
 ---------- ----------
    1283140   37182200

If we look at the output, we’ll see a lot of Visit objects generated by our autocannon run. We’ll also see Visit is the third type using more memory. In a real case scenario, this information is the first step to track down memory leaks.

There’s also a detailed version of this command which can be called with v8 findjsobjects -d. The result will group types with the same attributes and number of elements, and will also provide the address to an example object of that type.

v8 findjsinstances

v8 findjsinstances gives you a list with all objects of a given type. It also has a detailed version which can be called with v8 findjsinstances -d. This will print all objects of a given type with their attributes and elements.

(llnode) v8 findjsinstances -d Visit
0x0000176d04402201:<Object: Visit properties {
    .visit_id=<Smi: 82704>,
    .headers=0x0000176d7d99f1c9:<Object: Object>}>
0x0000176d04402229:<Object: Visit properties {
    .visit_id=<Smi: 82705>,
    .headers=0x0000176d7d99f191:<Object: Object>}>
0x0000176d04402251:<Object: Visit properties {
    .visit_id=<Smi: 82706>,
    .headers=0x0000176d7d99f159:<Object: Object>}>
0x0000176d04402279:<Object: Visit properties {
    .visit_id=<Smi: 82707>,
    .headers=0x0000176d7d99f121:<Object: Object>}>
0x0000176d044022a1:<Object: Visit properties {
    .visit_id=<Smi: 82708>,
    .headers=0x0000176d7d99f0e9:<Object: Object>}>
0x0000176d044022c9:<Object: Visit properties {
    .visit_id=<Smi: 82709>,
    .headers=0x0000176d7d99f0b1:<Object: Object>}>
*// A thousand miles later...
*0x0000176dffba62d9:<Object: Visit properties {
    .visit_id=<Smi: 156026>,
    .headers=0x0000176dffbef559:<Object: Object>}>
0x0000176dffba6301:<Object: Visit properties {
    .visit_id=<Smi: 156027>,
    .headers=0x0000176dffbef8a9:<Object: Object>}>
**0x0000176dffba6329**:<Object: Visit properties {
    .visit_id=<Smi: 156028>,
    .headers=0x0000176dffb82481:<Object: Object>}>

v8 findjsinstances -d accepts the same arguments you can pass to v8 inspect, which we will see next.

v8 inspect

v8 inspect prints all attributes and elements of a given object. It can also print additional information, such as the address to the object’s map. If you want to see the object’s map address, you should run v8 inspect -m. You can inspect the map like any other object by using v8 inspect.

(llnode) v8 inspect -m **0x0000176dffba6329**
0x0000176dffba6329(map=***0x0000176d689cec29***):<Object: Visit properties {
    .visit_id=<Smi: 156028>,
    .headers=0x0000176dffb82481:<Object: Object>}>
(llnode) v8 inspect ***0x0000176d689cec29***
0x0000176d689cec29:<Map own_descriptors=2 in_object_size=2 
  instance_size=40 
  descriptors=0x0000176d7f284569:<FixedArray, len=8 contents={
    [0]=<Smi: 2>,
    [1]=<Smi: 0>,
    [2]=0x0000176dd8566a11:<String: "visit_id">,
    [3]=<Smi: 320>,
    [4]=<Smi: 1>,
    [5]=0x0000176dd8566a31:<String: "headers">,
    [6]=<Smi: 1050112>,
    [7]=0x0000176d117509f9:<unknown>}>>

v8 findrefs

Now we know how to find which types are using a huge amount of memory, how to find objects of those types and how to inspect attributes of those objects. But if we want to find memory leaks, we’ll need to find what’s keeping those objects in the memory. In other words, we need to find other objects referencing them. There’s a command perfect for that: v8 findrefs. This command will return all objects referencing another object. Let’s give it a try:

(llnode) v8 findrefs **0x0000176dffba6329
**0x176d1f4fac41: (Array)[156027]=0x176dffba6329

The result shows us that there’s an array holding a lot (156027) of objects, and is probably the reason we have so many Visit objects in memory (spoiler: it is, look at line 13 and 16 of our server). Unfortunately, llnode can’t tell where this array is located yet, but there’s an open issue to add this feature in the future.

Conclusion

Even with a limited set of features, llnode is a powerful debugging tool to have on our Node.js Diagnostics arsenal. It’s ability to inspect the state of an application right after it crashed and the lightweight nature of core dumps can help us identify memory issues with less effort when compared to traditional tools. It also makes llnode and core dumps a good fit to be used on production environments.

admin
Leave a Reply