代码改变世界

NodeJS的代码调试和性能调优

2015-10-23 00:52 by Barret Lee, ... 阅读, ... 评论, 收藏, 编辑

本文转自我的个人博客

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 在打开文件的时候启动了内建调试功能,并且监听端口 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

更多的调试方式

node-inspector

NodeJS 提供的内建调试十分强大,它告诉 V8,在执行代码的时候中断程度,等待开发者操控代码的执行进度。我们熟知的 node-inspector 也是用的这个原理。

➜  $ node-inspector --web-port 8080 --debug-port 5858 

这里的 --web-port 是 Chrome Devtools 的调试页面地址端口,--debug-port 为 NodeJS 启动的内建 debug 端口,我们可以在 http://localhost:8080/debug?port=5858 打开页面,调试使用 --debug(-brk) 参数打开的程序。

更多设置可以查阅官方文档

IDE调试

Eclipse 和 webstorm 的工具栏中都有一个叫做 Run 的选择栏,在这里可以配置该文件的执行方式,比如在 webstorm 中(Navigation>Run>Edit Configurations):

第一步,为程序添加一个启动程序

如果没有 Nodejs 的选项(如在 phpstorm 中),可以手动配置下。

第二步,配置执行项

  • Node interpreter 是你 node 程序的位置
  • Node parameters 是开启 nodejs 程序的选项,如果使用了 ES6 特性,需要开始 --harmony 模式,如果需要远程调试程序,可以使用 --debug 命令,我们采用控制台调试,显然是不需要添加 --debug 参数的。
  • Working directory 是文件的目录
  • Javascript file 是需要调试的文件

第三步,断点,调试

其他 IDE 工具的调试大同小异,其原理也是通过 TCP 连接到 Nodejs 开启的内建调试端口。

发现程序的问题

上面介绍了 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,它在这里:

通过 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
...

我们也可以使用 headdump 之类的工具将日志导出,然后放到 Chrome 的 Profile 中去分析。

小结

本文主要从 NodeJS 程序的调试手段上,以及调试性能的入口上做了简要的介绍,希望对你有所启发,不到之处还请斧正!

本文转自我的个人博客