Skip to content

Debugging Node.js Memory Leaks

Tejesh Mehta edited this page Sep 16, 2015 · 1 revision

Memory dump steps

SSH into the server running the application container

# Check if gcore is installed

$ which gcore

# If it is not installed install it by using

sudo apt-get install -y gdb

$ sudo docker ps

$ sudo docker inspect <containerId> | grep Pid
        "Pid": 25549,
        "PidMode": "",

# Find the closest node pid to the docker container pid

$ pgrep node
10479
14219
16755
20382
25573 # <--- this one looks like the closest to the pid we are interested in.
30077
30081
30697
30700

# Now that we have found the node process pid, let's take a core dump

$ sudo gcore 25573
0x00007f1542a226e9 in ?? ()
warning: target file /proc/25573/cmdline contained unexpected null characters
Saved corefile core.25573

# This dumps a core file to the current directory (/home/ubuntu)

$ ls -alh
...
-rw-r--r--   1 root   root   236M Sep 16 00:06 core.25573
...

# Notice it is a few hundred MB if it is KB there is probably a problem.

###Return to your laptop shell.

Copy core file to you laptop
scp <user>@<box>:/home/ubuntu/core.25573 ./
Copy it to a Joyent box
scp ./core.25573 [email protected]:/root/

###SSH into Joyent box

Using MDB

# Open mdb with the core file of interest

$ mdb core.25573
mdb: warning: librtld_db failed to initialize; shared library information will not be available

# Mdb is a memory analysis cli tool

# Once we have it open load the latest version of mdb v8 plugin available

> ::load /root/mdb_v8_amd64.so
mdb_v8 version: 0.11.1 (release, from 7a32844)
V8 version: 3.14.5.9
Autoconfigured V8 support from target
C++ symbol demangling enabled

# Once you have v8's mdb plugin loaded you get a bunch of commands
#   for analyzing a node processes' memory usage

# You can list all of the mdb v8's commands w/ the following:

> ::dmods -l mdb_v8_amd64
mdb_v8_amd64
  dcmd findjsobjects        - find JavaScript objects
  dcmd jsclosure            - print variables referenced by a closure
  dcmd jsconstructor        - print the constructor for a JavaScript object
  dcmd jsframe              - summarize a JavaScript stack frame
  dcmd jsfunctions          - list JavaScript functions
  dcmd jsprint              - print a JavaScript object
  dcmd jssource             - print the source code for a JavaScript function
  dcmd jsstack              - print a JavaScript stacktrace
  dcmd nodebuffer           - print details about the given Node Buffer
  dcmd v8array              - print elements of a V8 FixedArray
  dcmd v8classes            - list known V8 heap object C++ classes
  dcmd v8code               - print information about a V8 Code object
  dcmd v8context            - print information about a V8 Context object
  dcmd v8field              - manually add a field to a given class
  dcmd v8frametypes         - list known V8 frame types
  dcmd v8function           - print JSFunction object details
  dcmd v8internal           - print v8 object internal fields
  dcmd v8load               - load canned config for a specific V8 version
  dcmd v8print              - print a V8 heap object
  dcmd v8scopeinfo          - print information about a V8 ScopeInfo 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
  dcmd v8warnings           - toggle V8 warnings
  walk jsframe              - walk V8 JavaScript stack frames
  walk jsprop               - walk property values for an object

# findjsobject analyzes all js objects in the applications core dump and groups them
# Note: this command can take some time depending on the dump size
# Once you run it once it's analysis is cached and can be rerun quickly

JS Object Analysis using MDB

> ::findjsobjects
    37b0f79b0079        1        1 Object: autoClose
    1c96da7a7021        1        1 Object: aborted
    3361440e93e1        1        1 TxSegmentNormalizer: terms
    3361440ae981        1        1 Object: encoding
    3361440a8cb9        1        1 Object: module
...

# You can pipe these commands in to bash by using an exclamation mark

# Let's sort objects based on count

>::findjsobjects ! sort -k2
...
     32f96404299    20980        2 Array
     32f96404709    24345        0 Array
     32f964043b9    39524        1 Array

# Here we have 38524 Arrays in our app's memory.

# You can list all of the Array instances by:

> 32f964043b9::findjsobjects

# You can inspect what an object looks like by:

> 32f964043b9::jsprint
...

# You can list all of the Array instances by:

> 32f964043b9::jsprint
[
    {
        "name": "Callback: anonymous",
        "transaction": [...],
        "parameters": [...],
        "children": [...],
        "timer": [...],
        "partialName": null,
        "_exclusiveDuration": null,
        "host": null,
        "port": null,
        "state": "EXTERNAL",
        "async": false,
        "ignore": false,
    },
    hole
]

# You can list all of the objects that reference this object by using -r
# This also takes a while to compute.
# NOTE: If this returns nothing it is not a leak, bc it will be GCed soon

> 32f964043b9::findjsobjects -r
32f964043b9 referred to by 32f96404321.children

## Now print the referencing object

> 32f96404321::jsprint
{
    "name": "dns.lookup",
    "transaction": {
        "agent": [...],
        "metrics": [...],
        "id": "13ed3bbd8675070",
....


# Check out the other commands for fun.

JS Function Analysis

# jsfunctions analyzes all js functions in the applications core dump and groups them
# Note: this command can take some time depending on the dump size
# Once you run it once it's analysis is cached and can be rerun quickly

> ::jsfunctions
    37b0f79f4431        1 <anonymous> (as exports.parseHost)       /navi/node_modules/bunyan-loggly/node_modules/loggly/node_modules/reques[...] position 582
    37b0f79f43e9        1 <anonymous> (as exports.version)         /navi/node_modules/bunyan-loggly/node_modules/loggly/node_modules/reques[...] position 444
    37b0f79f4311        1 <anonymous> (as internals.import)        /navi/node_modules/bunyan-loggly/node_modules/loggly/node_modules/reques[...] position 254
...

> ::jsfunctions ! sort -k2
...
    21bc5cb04339      982 cb_map                                   /navi/node_modules/newrelic/lib/transaction/trace/segment.js position 6989
    21bc5cb04741      982 cb_map                                   /navi/node_modules/newrelic/lib/transaction/trace/segment.js position 7284
    20fd66eb9ca1      984 cb_reduce                                /navi/node_modules/newrelic/lib/transaction/trace/segment.js position 7097
    114088686899     1436 wrapped                                  /navi/node_modules/newrelic/lib/transaction/tracer/index.js line 152
...

# Let's see where this function is from

> 114088686899::jssource
file: /navi/node_modules/newrelic/lib/transaction/tracer/index.js

  147   wrapped[ORIGINAL] = handler[ORIGINAL] || handler
  148   wrapped[SEGMENT] = active
  149
  150   return wrapped
  151
  152   function wrapped() {
  153     var prev = tracer.segment
  154     tracer.segment = active
  155     if (active && full) segment.start()
  156     try {
  157       var result = handler.apply(this, arguments)
  158     } catch(err) {
  159       if (err instanceof Error && active && !err[ERROR_TRANSACTION]) {
  160         try {
  161           Object.defineProperty(err, ERROR_TRANSACTION, {
  162             enumerable: false,
  163             configurable: true,
  164             writable: true,
  165             value: active.transaction
  166           })
  167         } catch (_err) {
  168           logger.debug("Could not annotate error object: %s", _err)
  169         }
  170       }
  171
  172       throw err
  173     } finally {
  174       if (active && full) segment.touch()
  175       tracer.segment = prev
  176     }
  177     return result
  178   }
  179 }
  180
  181 function getOriginal(fn) {
  182   return fn && fn[ORIGINAL] ? fn[ORIGINAL] : fn
  183 }
  184

# Let's see variables in this function's closure

> 114088686899::jsclosure
    "full": 294bed204121: undefined
    "segment": 294bed204121: undefined
    "handler": 1140886dfde9: function next
    "tracer": 114088636fd9: {
        "agent": 3361440e6991: [...],
        "segment": 294bed204101: null,
    }
    "active": 1140886dfe31: {
        "name": 1d240b139469: "WebTransaction/Expressjs/POST//",
        "transaction": 3a27b40701c1: [...],
        "parameters": 3a27b4070299: [...],
        "children": 3a27b40702b9: [...],
        "timer": 3a27b40702d9: [...],
        "partialName": d2462ebb91: "Expressjs/POST//",
        "_exclusiveDuration": 294bed204101: null,
        "host": 294bed204101: null,
        "port": 294bed204101: null,
        "state": 283b1a383451: "EXTERNAL",
        "async": 294bed204141: true,
        "ignore": 294bed204161: false,
    }
Clone this wiki locally