NodeJS的代码调试和性能调优

原文地址： http://www.barretlee.com/blog/2015/10/07/debug-nodejs-in-command-line/

NodeJS 自 2009 年显露人间，到现在已经六个年头了，由于各种原因，中间派生出了个兄弟，叫做 iojs，最近兄弟继续合体，衍生出了 nodejs4.0 版本，这东西算是 nodejs new 1.0 版本，原班人马都统一到一个战线上。我没有太关注 nodejs 背后的开发，但一直是它的忠实使用者，通读了 v4.1.2 的文档，感觉从开发者角度去看，也没啥大的变化，所以这两个兄弟分开这么久，主要是在底层内建模块上做改造，上层建筑尚未有大的变更，具体可以看这篇文章。

如果你一直用着 nodejs，然而一直都在写最基本的小 demo，很少深入的去剖析 nodejs 的性能问题，甚至连如何 debug 代码、如何发现性能问题都不知从哪里下手，那么赶紧往下读吧！

命令行调试

命令行中调试 nodejs 代码，这是最基础的调试技能，如同我们在 Chrome 控制中调试 JS 代码一般，然而却用的很少，因为他太原始，显得比较麻烦。

回顾下，我们平时的调试方式：

在某个需要输入的地方输入 console.log() ，打印调试结果
引入 asserts 模块，对调试区域进行 debug

这两种调试方式，都需要我们显式将各种 debug 信息嵌入到我们的业务逻辑代码中，而熟悉了命令行调试之后，我们可以更好地开启自己的调试之旅。NodeJS 给我们提供了 Debugger 模块，内建客户端，通过 TCP 将命令行的输入传送到内建模块以达到调试的目的。

在启动文件时，添加第二个参数 debug ：

➜  $ node debug proxy2.js
< Debugger listening on port 5858
debug> . ok
break in proxy2.js:1
> 1 var http = require('http');
  2 var net = require('net');
  3 var url = require('url');
debug>

调试代码的时候存在两个状态，一个是操作调试的位置，比如下一步，进入函数，跳出函数等，此时为 debug 模式；另一个是查看变量的值，比如进入循环中，想查看循环计数器 i 的值，此时为 repl（read-eval-per-line）状态，在 debug 模式下输入 repl 即可进入 repl 状态：

debug> repl
Press Ctrl + C to leave debug repl
> http
print something about http
>

按下 Ctrl+C 可以从 repl 状态回到 debug 状态下，我们也不需要记忆 debug 状态下有多少调试命令，执行 help 即可：

debug> help
Commands: run (r), cont (c), next (n), step (s), out (o), backtrace (bt), setBreakpoint (sb), clearBreakpoint (cb),
watch, unwatch, watchers, repl, restart, kill, list, scripts, breakOnException, breakpoints, version

命令	解释
cont, c	进入下一个断点
next, n	下一步
step, s	进入函数
out, o	跳出函数
setBreakpoint(), sb()	在当前行设置断点
setBreakpoint(line), sb(line)	在 line 行设置断点

NodeJS的调试原理

我们平时开发都使用 IDE 工具，实际上很多 IDE 工具已经集成了 NodeJS 的调试工具，比如 Eclipse、webStorm 等等，他们的原理依然是利用 Nodejs 的 Debugger 内建模块，在这个基础上进行了封装。

细心的同学会发现，当我们使用 debug 参数打开一个 node 文件时，会输出这样一行文案：

Debugger listening on port 5858

可以访问下 http://localhost:5858 ，会看到：

NodeJS的代码调试和性能调优

它告诉我们 nodejs 在打开文件的时候启动了内建调试功能，并且监听端口 5858 过来的调试命令。除了在命令行中直接调试之外，我们还可以通过另外两种方式去调试这个代码：

node debug <URI> ，通过 URI 连接调试，如 node debug localhost:5858
node debug -p <pid> 通过 PID 链接调试

如果我们使用 --debug 参数打开文件：

➜  $ node --debug proxy2.js

此时，nodejs 不会进入到命令行模式，而是直接执行代码，但是依然会开启内建调试功能，这就意味着我们具备了远程调试 NodeJS 代码的能力，使用 --debug 参数打开服务器的 nodejs 文件，然后通过：

➜  $ node debug <服务器IP>:<调试端口，默认5858>

可以在本地远程调试 nodejs 代码。不过这里需要区分下 --debug 和 --debug-brk ，前者会执行完所有的代码，一般是在监听事件的时候使用，而后者，不会执行代码，需要等到外部调试接入后，进入代码区。语言表述不会那么生动，读者可以自行测试下。

默认端口号是 5858，如果这个端口被占用，程序会递增端口号，我们也可以指定端口：

➜  node  node --debug-brk=8787 proxy2.js
Debugger listening on port 8787

发现程序的问题

上面介绍了 NodeJS 调试需要掌握的几个基本技能，掌握起来还是很轻松的，但是要自己去尝试下。

Nodejs 相比 Java、PHP 这些老牌语言，其周边设施还是有所欠缺的，如性能分析和监控工具等，加上它的单线程运行特性，在大型应用中，很容易让系统的 CPU 或者内存达到瓶颈，从而导致程序崩溃。一旦发现程序警报 CPU 负载过高，或者内存飙高时，我们该如何深入排查 NodeJS 代码存在的问题呢？

首先来分析下问题，内存飙高存在哪些方面的因素呢：

缓存，很多人在敲程序的时候把缓存当内存用，比如使用一个对象储存用户的 session 信息
闭包，作用域没有被释放掉
生产者和消费者存在速度差，比如数据库忙不过来，Query 队列堆积

CPU 负载过高预警可能因素：

垃圾回收频率过高、量太大，这一般是因为内存或者缓存暴涨导致的
密集型的长循环计算，比如大量遍历文件夹、大量计算等

这些问题是最让人头疼的，一个项目几十上百个文件，收到这些警报如果没有经验，根本无从下手排查。

最直接的手段就是分析 GC 日志，因为程序的一举一动都会反馈到 GC 上，而上述问题也会一一指向 GC，如：

内存暴涨，尤其是 Old Space 内存的暴涨，会直接导致 GC 的次数和时间增长
缓存增加，导致 GC 的时间增加，无用遍历过多
密集型计算，导致 GC Now Space次数增加

这里需要稍微插一段，NodeJS 的内存管理和垃圾回收机制。

V8 的内存分为 New Space 和 Old Space，New Space 的大小默认为 8M，Old Space 的大小默认为 0.7G，64位系统这两个数值翻倍。

对象的生命周期是：首先进入 New Space，在这里，New Space 被平均分为两份，每次 GC 都会将一份中的活着的对象复制到另一份，所以它的空间使用率是 50%，这个算法叫做 Cheney 算法，这个操作叫做 Scavenge。过一段时间，如果 New Space 中的对象还活着，会被挪到 Old Space 中去，GC 会每隔一段时间遍历 Old Space 中死掉的对象，然后整理碎片（这里有两种模式 mark-sweep 和 mark-compact，不祥述）。上面提到的”死掉“，指的是对象已经没有被引用了，活着说被引用的次数为零了。

知道这些之后，我们就好分析问题了，如果缓存增加（比如使用对象缓存了很多用户信息），GC 是不知道这些缓存死了还是活着的，他们会不停地查看这个对象，以及这个对象中的子对象是否还存活，如果这个对象数特别大，那么 GC 遍历的时间也会特别长。当我们进行密集型计算的时候，会产生很多中间变量，这些变量往往在 New Space 中就死掉了，那么 GC 也会在这里多次地进行 New Space 区域的垃圾回收。

分析 GC 日志

说了这么多，如何去分析 GC 的日志？

在启动程序的时候添加 --trace_gc 参数，V8 在进行垃圾回收的时候，会将垃圾回收的信息打印出来：

➜  $ node --trace_gc aa.js
...
[94036]       68 ms: Scavenge 8.4 (42.5) -> 8.2 (43.5) MB, 2.4 ms [allocation failure].
[94036]       74 ms: Scavenge 8.9 (43.5) -> 8.9 (46.5) MB, 5.1 ms [allocation failure].
[94036] Increasing marking speed to 3 due to high promotion rate
[94036]       85 ms: Scavenge 16.1 (46.5) -> 15.7 (47.5) MB, 3.8 ms (+ 5.0 ms in 106 steps since last GC) [allocation failure].
[94036]       95 ms: Scavenge 16.7 (47.5) -> 16.6 (54.5) MB, 7.2 ms (+ 1.3 ms in 14 steps since last GC) [allocation failure].
[94036]      111 ms: Mark-sweep 23.6 (54.5) -> 23.2 (54.5) MB, 6.2 ms (+ 15.3 ms in 222 steps since start of marking, biggest step 0.3 ms) [GC interrupt] [GC in old space requested].
...

V8 提供了很多程序启动选项：

启动项	含义
–max-stack-size	设置栈大小
–v8-options	打印 V8 相关命令
–trace-bailout	查找不能被优化的函数，重写
–trace-deopt	查找不能优化的函数

这些启动项都可以让我们查看 V8 在执行时的各种 log 日志，对于排查隐晦问题比较有用。然而这堆日志并不太好看，我们可以将日志输出来之后交给专业的工具帮我们分析，相比很多人都用过 Chrome DevTools 的 JavaScript CPU Profile，它在这里：

NodeJS的代码调试和性能调优

通过 Profile 可以找到具体函数在整个程序中的执行时间和执行时间占比，从而分析到具体的代码问题，V8 也提供了 Profile 日志导出：

➜  $ node --prof test.js

执行命令之后，会在该目录下产生一个 *-v8.log 的日志文件，我们可以安装一个日志分析工具 tick:

➜  $ sudo npm install tick -g
➜  $ node-tick-processor *-v8.log
[Top down (heavy) profile]:
  Note: callees occupying less than 0.1% are not shown.

  inclusive      self           name
  ticks   total  ticks   total
    426   36.7%      0    0.0%  Function: ~<anonymous> node.js:27:10
    426   36.7%      0    0.0%    LazyCompile: ~startup node.js:30:19
    410   35.3%      0    0.0%      LazyCompile: ~Module.runMain module.js:499:26
    409   35.2%      0    0.0%        LazyCompile: Module._load module.js:273:24
    407   35.1%      0    0.0%          LazyCompile: ~Module.load module.js:345:33
    406   35.0%      0    0.0%            LazyCompile: ~Module._extensions..js module.js:476:37
    405   34.9%      0    0.0%              LazyCompile: ~Module._compile module.js:378:37
...