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

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

每个用户的请求,都会经过这几个阶段:

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

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

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

但在 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
感谢您的阅读,本文由 凹凸实验室 版权所有。如若转载,请注明出处:凹凸实验室(https://aotu.io/notes/2016/02/24/node-debug-in-production/