Node 生产环境调试

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

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

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

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

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

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

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

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

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

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

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

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

   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 并生成可视化的栈信息火焰图

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

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

解释这种图片的含义：

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

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

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

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

1. 配置 Solaris 环境

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

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

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

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

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

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

   var obj = {
       myproperty: "Hello World",
       count: 0,
   };
   
   function increment() {
       obj.count++;
       
       if (obj.count === 1000)
           throw new Error("sad trombone");  // 该行会让应用崩溃
       
       setImmediate(increment);
   }
   
   setImmediate(increment);
   

   # 运行上述代码
   node --abort-on-uncaught-exception throw.js
   

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

   # 打包 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 文件

   # 下载最新的 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 指令，查看最后的调用栈情况

   > ::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 ，因此可以查下该函数的地址

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

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

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

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

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

   > ::findjsobjects -p count | ::findjsobjects -l | ::jsprint
   {
       "myproperty": "Hello World",
       "count": 0,
   }
   {
       "myproperty": "Hello World",
       "count": 1000,
   }
   

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

如何追踪内存泄露问题？

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

   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

   # 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 对象，并输出文件

   # 每行命令生成两个文件，分别为 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 对象的异同，即可获得未被释放的对象地址。

   # 下载安装 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
   

   打印出来的结果为：

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

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

   # 打印该地址对象的内容
   > 135f38df83d9::jsprint
   {
       "longStr": "*******....",
       "closure": function <anonymous> (as bigData.closure),
   }
   
   # 找出该对象所有的实例
   > 135f38df83d9::findjsobjects
   39fac26f83d9
   39ec3a4f83d9
   3720c57f83d9
   ...
   

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

后语

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