node.js写日志堵塞问题

今天遇到一起后台服务中断问题，原因是有一个服务写日志导致磁盘满，清掉日志释放磁盘空间后，服务无法自动恢复，此时有以下症状：

  • node.js 进程内存占用超高（超过1G），CPU占用超高（接近100%）

  • pm2 运行异常

    stop 和 delete 操作会卡住， start 和 restart 操作失败。

    后台有大量 pm2 进程，应该是 crontab 每分钟调用 pm2 start 确保服务拉起导致。

    killall -9 node 及 pm2 仍然无法将服务恢复。

    pm2 kill 也会卡住，最终通过 kill -9 干掉 pm2 的后台进程 PM2 v0.14.3: God Daemon 才把服务重新启动。

一个小时后又出现险情，类似的症状，虽然没有严重到中断服务，但是 pm2 失控很让人揪心，服务开了两个实例，其中一个实例状态： 

│ App name          │ id │ mode    │ pid │ status  │ restart │ uptime │ memory │ watching │
│ xxx.xxxxxxxxx.com │ 0  │ cluster │ N/A │ errored │ 2       │ 0      │ 0 B    │ disabled │

执行 pm2 delete 0 也是挂住，最终还是通过 kill -9 干掉 pm2 的后台进程 PM2 v0.14.3: God Daemon 才把服务重新启动。

top 看到的进程状态： 

 PID USER      PR  NI  VIRT  RES  SHR S %CPU   %MEM  TIME+   COMMAND           
1640 nobody    20   0  793m 149m 8468 R 105.5  0.9   0:34.74 node /usr/local  
1649 nobody    20   0  796m 152m 8472 R 103.6  1.0   0:34.78 node /usr/local

服务输出的日志量在每秒700行（每行不超过120个字符）左右，最终将日志级别调到 error ，几乎不再输出日志，方才将CPU占用降下来： 

    PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM  TIME+    COMMAND           
3527 nobody       20   0  829m 185m 8476 R 62.3  1.2  30:41.12 node /usr/local
3537 nobody       20   0  825m 181m 8476 R 60.4  1.1  30:45.96 node /usr/local

我使用的日志模块为 tracer ，简单地通过 tracer.console(options) 实例化全局的日志对象，最终写日志调用的是 console.log 。

在上层，我使用 pm2 来做进程管理，使用以下参数启动我的服务： 

pm2 -n xxx.xxxxxxxxx.com -l /usr/local/xxx.xxxxxxxxx.com/run.log --merge-logs start /usr/local/xxx.xxxxxxxxx.com/src/index.js -i 2

通过 pm2 describe xxx.xxxxxxxxx.com 输出可以发现最终会写三个日志文件： 

│ entire log path   │ /usr/local/xxx.xxxxxxxxx.com/run.log             │
│ error log path    │ /root/.pm2/logs/xxx.xxxxxxxxx.com-error.log      │
│ out log path      │ /root/.pm2/logs/xxx.xxxxxxxxx.com-out.log        │

根据 console的文档 中的描述：

The console functions are synchronous when the destination is a terminal or a file (to avoid lost messages in case of premature exit) and asynchronous when it's a pipe (to avoid blocking for long periods of time).

如果输出目标为终端或文件时，console函数是同步的（避免程序过早退出导致丢消息），目标为管道时则为异步（避免长时间堵塞）。

这个特性引起的问题我也在另一篇文章《 process.exit导致的控制台输出不全 》里有提及。

也就是说不出意外的话，我们的服务写日志是阻塞式的，每秒钟同步方式写700行日志到一块普通机械硬盘上， node.js 不卡死才怪，更何况这块硬盘上还在被其它服务频繁读写。

一个服务运行过程中不写日志文件是不可能的，在 node.js 写日志方面需要找到更优的方案。

但是在寻找更好的方案之前，我做了一个常识性的思考：

将应用程序日志写到磁盘文件的模块，除非它丢弃日志，当磁盘写入无法跟上日志产生的速度，就要暂存到某个地方，它可能是本机的内存或连网的另一台机器。

所以我最终要找的，不仅仅是一个异步写日志文件的模块，还要先减少磁盘写入量，或者日志不直接写到磁盘文件，而是发送到一个日志服务，如果日志是写在本地磁盘，最好能够做到磁盘满时不中断服务，这种情况下丢失日志也是可以接受的。


node