一个部署在阿里云上的服务突然有一天发现原来正常运行的程序突然挂了,这时候发现内存偏高,CPU 100%,一开始怀疑是不是代码造成的死循环 Bug,之后就开始了痛苦的排查过程。

node –prof

node --prof 命令是用来排查性能问题的一个很有用的命令,他会生成一个 v8 的 log 文件。

通过一番 Google,然后把原来的启动命令 node app.js 替换成 node --prof app.js,运行一段时间后生成了一个几百兆的分析文件,然后通过命令 node --prof-process isoxxx 分析。看到一大堆密密麻麻的字母,一开始不知道该怎么看,又一番 Google 之后大概看出来个一二,发现某个关键字出现很多,是 mongoose 库里的一个文件 pool.js ,看单词就可以猜到,应该是连接池,接着有一个关键字也出现频率很高,是 timeout ,猜测大概是操作超时了。然后顺着这个思路继续查。

node-heapdump

从上面的排查大概猜测是数据库问题之后,因为只是猜测,所以又用到另外一个常用方法 heapdump,这个库可以很方便的通过代码来捕获当前内存的快照,然后通过导入 Chrome 来分析。经过对比分析之后,发现有一个对象 system / JSArrayBufferData 不断的增长而且很缓慢的释放,所以应该不算内存泄漏而是产生太快而消费太慢导致内存极速增长。而展开这个对象,里面又出现了两个关键字 pool queue,这时候大致上认为是请求的队列在增长。

node –trace_gc –trace_gc_verbose

经过上面的分析,虽然已经猜测到了大概,也 Review 了代码,已经差不多可以确认就是过快的写入数据库导致的,因为我在 Review 代码的时候竟然发现大量的循环操作写数据库 😂。但是我还是无法确认为什么在空闲的时候 CPU 已然是那么高,对比其他应用几乎不占用 CPU 资源,内存也很低。没办法,把命令换成 node --trace_gc --trace_gc_verbose 把每一次 GC 的过程都打出来,这时候我瞬间明白了为什么 CPU 一直在增长。通过 GC 日志知道,系统在频繁的进行 GC,v8 的 GC 分两种,一种是函数里面的临时变量,这些变量被放在 new_space 里面,基本上这些内存在下一次 young gc 的时候就会被回收,而没有被回收的内存会被放到 old_spaceold_space 的资源会存在比较久,而且只要没有被清除系统就会定时的执行 full gc ,这时候系统扫描这里面的资源是否有被释放然后回收。如果你的应用程序的 old_space 在不断的增加而没有被释放的话,基本上可以断定内存泄漏了。所以当 old_space 增大到某个程度的时候,这时候 GC 扫描这个对象就造成 CPU 100%,GC 本身就是一个耗 CPU 的操作,当前面 old_space 还没那么庞大的时候 GC 还能跑得动,运行一段时间之后 GC 已经跑不动了,这时候 CPU 已经 100%,所以程序也就挂了。

总结

后来跟工程师反应这个问题,并给出优化的方案,同时在简单的 Code Review 里面我还发现了几个问题:

  1. 在没有设置限制的情况之下直接循环执行数据库更新操作。(由于 Nodejs 的异步特性,所有操作会在同一时间执行,造成数据库资源紧张导致部分执行 timeout 错误)

    解决:限制并发执行的最大数量。

  2. 代码里面出现长长的一个 function,里面满满的 if-else,完全看不出代码逻辑是干什么的,非常混乱。

    解决:把逻辑抽象出来,并用清晰的 function_name 来描述代码逻辑是干什么用的。

  3. 代码逻辑里面跑满了各种计算和数据库操作,每次 API 请求都要跑一遍,而大多数情况之下这些计算是浪费资源的,因为结果基本上是一样的。

    解决:加入适当的缓存机制,避免重复的计算浪费资源。