本文以问答的形式，介绍生产环境中该如何去调试 Node 应用。
文章覆盖到了性能问题、崩溃问题、内存泄露的检查和解决手段。

随着用户请求数越来越多，Node 请求越来越慢。怎么处理？

每个用户的请求，都会经过这几个阶段：

1
网络请求 -> Node 中间层 -> 目标接口 -> 返回

前三个过程都会消耗一定的时间，因此我们应该分析每个阶段的耗时，进行针对性优化。

假设你是用 Express 作为 API 服务器，你可以利用 Express 官方的 response-time 和 StatsD，
将每个中间层的请求数据都收集并统计起来。

但在 Express 世界之外，还有一个更专注于做 API 服务器的框架，叫 restify。
restify 是一个纯 Restful 的框架，它可以结合 DTrace 去记录一个用户请求中，每个环节消耗的时间。

图中高亮的部分是 restify 对于请求耗时的记录：

resify_bunyan

此外，restify 还有着更多强大功能，包括请求频率控制、内置 Ajax 错误类型、基于 bunyan 的日志。

如何知道线上项目哪个函数消耗更多的 CPU 时间？

参考以下几个步骤，通过可视化的角度，揪出消耗 CPU 的凶手。

  1. 确保你线上的 Node 版本是 5.0 以上

  2. 启动 Node 项目时，增加 --perf-basic-prof-only-functions 参数，如：

    1
    node --perf-basic-prof-only-functions app.js &   # Tips: `&`表示后台运行该代码

  3. 用 perf 生成 Node 进程的栈信息文件(stack trace)

    1
    2
    3
    4
    5
    6
    7
    8
    sudo yum install perf  # perf 非系统自带，需另外安装
    # 获取 Node 的进程 ID，用 30 秒时间记录栈信息并生成 `perf-xxxxx.map` 文件（被保存在 /tmp/）
    sudo perf record -F 99 -p `pgrep -n node` -g -- sleep 30
    ls /tmp/*.map                         # 检查该文件是否存在
    sudo chown root /tmp/perf-xxxxx.map   # 该文件设置权限
    sudo perf script > nodestacks         # 将该文件转换成可解析的 `nodestacks` 文件

  4. 下载 FlameGraph 并生成可视化的栈信息火焰图

    1
    2
    3
    4
    5
    git clone --depth 1 http://github.com/brendangregg/FlameGraph  # 下载 FlameGraph
    # 生成火焰图
    cd FlameGraph
    ./stackcollapse-perf.pl < ../nodestacks | ./flamegraph.pl --colors js > ../node-flamegraph.svg

最后会生成类似这样的图片：

image

解释这种图片的含义：

  1. 每个方块为被调用的函数
  2. X 轴表示 CPU 的消耗时间
  3. Y 轴表示栈的深度
  4. 颜色为随机值

如果方块横向越长，说明这个函数消耗的 CPU 时间越多。
这样，你就可以定位到这个函数，深入代码去定位问题了。

如何收集线上的崩溃信息？

可以让 Node 在运行过程中，记录自身的运行状态，并崩溃的时候输出调试信息。
而这些调试信息被称为 Core Dump，会被保存在一个文件中，我们称之为 Core 文件。
Core 文件记录了进程运行时的一切状态，包括调用栈、内存变量、被调用的函数源码等。
有了这个文件，我们就可以最大化的还原出当时应用运行的过程。

下面我们利用 mdb_v8 工具，这个目前最好的 Node 命令行分析工具，结合一个简单案例来演示。

  1. 配置 Solaris 环境

    由于 mdb_v8 只能运行在 Solaris 环境，因此你有两种选择：

    • 安装基于 Illumos 的系统，如 OmniOS 虚拟机

    • 使用 Joyent 公司收费的 Manta 服务，请参阅这里

      笔者使用第一种方式，即通过虚拟机运行 mdb_v8，详见 Vagrant 安装 OmniOS 指南。

  2. 启动 Node 项目时，增加 --abort-on-uncaught-exception 参数，让应用在崩溃时输出 Core 文件

    本文用以下会崩溃的代码测试，生成 Core 文件。

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    var obj = {
        myproperty: "Hello World",
        count: 0,
    };
    function increment() {
        obj.count++;
        
        if (obj.count === 1000)
            throw new Error("sad trombone");  // 该行会让应用崩溃
        
        setImmediate(increment);
    }
    setImmediate(increment);
    1
    2
    # 运行上述代码
    node --abort-on-uncaught-exception throw.js

  3. 将 Core 文件和 Node 二进制程序打包，传到 Vagrant 虚拟机内

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    # 打包 Core Dump 和 Node 二进制程序
    mkdir debug
    cp core.* debug/
    cp $(which node) debug/
    zip -r debug.zip debug 
    # 传压缩包到 Vagrant 虚拟机内
    mv debug.zip xxxx  # xxxx 表示 Vagrantfile 所在的目录，即你启动虚拟机的目录
    # 在虚拟机里解压缩包
    unzip -o /vagrant/debug.zip -d ~

  4. 使用 mdb_v8 解析 Core 文件

    1
    2
    3
    4
    5
    6
    7
    8
    # 下载最新的 mdb_v8 模块
    wget https://us-east.manta.joyent.com/Joyent_Dev/public/mdb_v8/v1.1.2/mdb_v8_amd64.so
    # 使用 mdb 工具加载 Core Dump，格式为：mdb [Node 二进制程序] [Core 文件]
    mdb ./node ./core
    # 进入 REPL 后, 运行以下代码加载 mdb_v8 模块
    > ::load ./mdb_v8_amd64.so

  5. 分析崩溃原因

    5.1. 使用 mdb_v8 的 jsstack 指令，查看最后的调用栈情况

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    > ::jsstack -v
    native: v8::base::OS::Abort+0xd
    native: v8::internal::Isolate::DoThrow+0x381
    native: v8::internal::Isolate::Throw+0x11
    native: v8::internal::Runtime_Throw+0x3d
            (1 internal frame elided)
    js:     increment
            file: /export/www/node/mongo-express/throw.js
            posn: line 6
            this: 2ac5150fc3f9 (JSObject: Immediate)
            (    1 function (exports, require, module, __filename, __dirname) { var obj = {
                2   myproperty: "Hello World",
                3   count: 0,
                4 };
                5
                6 function increment() {
                7   obj.count++;
                8
                9   if (obj.count === 1000)
                10     throw new Error("sad trombone");
                11
                12   setImmediate(increment);
                13 }
                14
                15 setImmediate(increment);
                16
                17 });
    js:     processImmediate
            file: timers.js
            posn: line 342
            this: 2d184056ef69 (JSObject: process)
            ...

    5.2. 从上面信息得知，最后一个被调用的函数是 increment，因此可以查下该函数的地址

    1
    2
    3
    4
    # 查询 increment 函数地址值
    > ::jsfunctions -n increment
            FUNC   #FUNCS NAME         FROM
    2ac51509c7a9        1 increment    /export/www/node/mongo-express/throw.js line 6

    5.3. 查到地址值后，就可以查出函数当时的局部变量

    1
    2
    3
    4
    5
    6
    7
    # 查询 increment 函数当时的局部变量
    > 2ac51509c7a9::jsclosure
    "obj": 2ac51509c941: {
        "myproperty": 2ae60c1a3f39: "Hello World",
        "count": 3e800000000: 1000,
    }
    "increment": 2ac51509c7a9: function increment

    结合代码可知，由于 count 数值已经到达 1000，导致应用崩溃。

    5.4. 当然，通过以下命令，还能查到 count 属性所在对象的起始状态和结束状态

    1
    2
    3
    4
    5
    6
    7
    8
    9
    > ::findjsobjects -p count | ::findjsobjects -l | ::jsprint
    {
        "myproperty": "Hello World",
        "count": 0,
    }
    {
        "myproperty": "Hello World",
        "count": 1000,
    }

    对于 mdb_v8 更多的 Node 指令，请参阅这里。

如何追踪内存泄露问题？

上个问题中，我们用 Node 的 --abort-on-uncaught-exception 参数，让应用在崩溃后输出 Core 文件。
但如果应用一直在运行（即无崩溃），可以用 Linux 自带的 gcore 命令，导出 Core 文件并分析内存泄露的原因。

  1. 本文用以下代码测试，该代码会导致内存泄露

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    var bigData = null;
    var replaceData = function () {
        var originalData = bigData
        bigData = {
            longStr: new Array(1000000).join('*'),
            closure: function () {
                // 这里引用到了 originalData，导致旧的 bigData 没有被释放
                if (originalData)
                    console.log(originalData.longStr.length)
            }
        }
        
        bigData.closure()
    }
    setInterval(replaceData, 1000)
    console.log('process id: ', process.pid)

    用 node xxx.js 命令运行代码即可。

  2. 每隔一段时间，用 gcore 对上述代码所在进程进行 Core Dump

    1
    2
    3
    4
    5
    6
    7
    # PID 为进程 ID，上面代码会打印出来
    # 文件会被保存为 leak_1.PID
    gcore -o leak_1 PID  
    # 进程运行一段时间后（如15秒），再 Core Dump 一次
    # 文件会被保存为 leak_2.PID
    gcore -o leak_2 PID

  3. 利用 mdb_v8 提供的工具 dumpjsobjects，提取 Core 文件中的 JS 对象，并输出文件

    1
    2
    3
    # 每行命令生成两个文件，分别为 obj_id_x / obj_content_x
    ./dumpjsobjects ./leak_1.PID ./mdb_v8_amd64.so obj_id_1 obj_content_1
    ./dumpjsobjects ./leak_2.PID ./mdb_v8_amd64.so obj_id_2 obj_content_2

  4. 利用 mdb_v8 提供的工具 mdbv8diff，进行 JS 对象对比

    比较两个时期的 JS 对象的异同，即可获得未被释放的对象地址。

    1
    2
    3
    4
    5
    6
    7
    # 下载安装 mdbv8diff
    git clone https://github.com/joyent/mdb_v8.git
    cd mdb_v8/tools/mdbv8diff
    npm install
    # 对比 Core 文件的 JS 对象
    ./mdbv8diff /path/to/obj_content_1 /path/to/obj_content_2

    打印出来的结果为：

    1
    135f38df83d9: only in /Users/edc/Downloads/omnios/du_3

  5. 用 mdb_v8 打印 135f38df83d9 内存地址对应的对象

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    # 打印该地址对象的内容
    > 135f38df83d9::jsprint
    {
        "longStr": "*******....",
        "closure": function <anonymous> (as bigData.closure),
    }
    # 找出该对象所有的实例
    > 135f38df83d9::findjsobjects
    39fac26f83d9
    39ec3a4f83d9
    3720c57f83d9
    ...

    从结果可以发现，该对象的实例一直在内存里未被释放。

后语

本文参考了 Netflix 工程师 Yunong Xiao 的演讲分享，在此感谢。
希望该文章可以给读者更多解决 Node 生产环境调试的思路。但对于生产环境中面临的各种复杂问题，也许需要更多的手段才能解决。

References

  1. http://techblog.netflix.com/2015/12/debugging-nodejs-in-production.html
  2. http://yunong.io/2015/11/23/generating-node-js-flame-graphs/
  3. http://www.slideshare.net/davidapacheco/surge2012
  4. https://www.joyent.com/blog/mdb-and-linux
  5. http://info.meteor.com/blog/an-interesting-kind-of-javascript-memory-leak