node进程cpu 100%问题排查

案情描述

现象：监控系统显示，官网的服务每个月总有那么几天会烧脑，单台服务器qps 20以内的前提下，从某一刻开始，node进程持续性消耗cpu100%，并且在剔除流量后，居高不下。

问题：cpu持续性被单个服务消耗，既影响服务本身功能和用户体验，也威胁到其他系统和进程的正常运行，更重要的是，存在随时发生生产故障的可能性

应急措施

之前出现问题时，在不能快速定位到具体原因的尴尬前提下，选择了快速执行B计划应急

具体措施：运维对官网服务扩容，通过增加集群数量分担部分压力（其实没什么流量压力，只是因为cpu100%的那几台服务，响应能力变弱了，搞得人和服务器都压力山大的样子）,验证新集群可以正常提供服务后，接入流量，并摘除问题服务器的流量，以保证官网服务的正常

搜集证据

问题服务器摘除流量后，就可以开始尸检了，真正的生产debug就这样发生了，贼尴尬，运维开发协作，上演一场debug秀：
运维：

从监控入手，过滤出耗时请求，缩小定位范围
从问题服务器入手，观察cpu，网络等资源的消耗情况
追踪node进程的系统调用情况，企图了解真正消耗cpu底层调用
使用上古神器gdb debug进程
猜测

开发：

分析运维提供的耗时接口，查看是否存在耗时逻辑
使用更适配node应用的调试工具，企图生产debug（有兴趣的童鞋可以看下 node应用debug利器）
猜测

证据：所有相关的小伙伴都在尽可能的提取证据，以解开案情疑虑，以下列出证据

pm2 monit，显示node进程cpu占比100%，但每个进程业务日志并不多（当时截图居然只截了左边一半），说明真正的业务压力并不大
ss -ant | awk ‘{++s[$1]} END {for(k in s) print k,s[k]}’ ，问题服务器的网络连接状态统计如下

FIN_WAIT2 394
LISTEN 7
CLOSE_WAIT 5662
TIME_WAIT 768
ESTABLISHED 570
FIN_WAIT1 1

数据显示大部分网络连接处于close_wait状态，这个状态提供了什么信息呢，先看下这些网络状态的释意

LISTEN:       侦听来自远方的TCP端口的连接请求;
SYN-SENT:     在发送连接请求后等待匹配的连接请求;
SYN-RECEIVED: 在收到和发送一个连接请求后等待对方对连接请求的确认;
ESTABLISHED:  代表一个打开的连接;
FIN-WAIT-1:   等待远程TCP连接中断请求, 或先前的连接中断请求的确认;
FIN-WAIT-2:   从远程TCP等待连接中断请求;
CLOSE-WAIT:   等待从本地用户发来的连接中断请求;
CLOSING:      等待远程TCP对连接中断的确认;
LAST-ACK:     等待原来的发向远程TCP的连接中断请求的确认;
TIME-WAIT:    等待足够的时间以确保远程TCP接收到连接中断请求的确认;
CLOSE:        没有任何连接状态;

也就是说大部分连接在等待用户服务发送最后的连接中断的信号，也就是四次握手（挥手）的第三个阶段没有完成

strace -ffp 11112 -o shial.log ，跟踪进程的系统调用和信号情况
主线程调用：

一个任务线程调用：

可以看到的是，主线程和任务线程都在频繁的进行futex调用，而且在反复处理两个内存地址,0x3f0da84,0x3f0da58，并且
FUTEX_WAIT_PRIVATE这个指令的响应一直是 EAGAIN (Resource temporarily unavailable)

11132线程
futex(0x3f0da84, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x3f0da80, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x3f0da58, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x3f0da84, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x3f0da80, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x3f0da58, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x3f0da84, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x3f0da80, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x3f0da58, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x3f0da84, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x3f0da80, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x3f0da58, FUTEX_WAKE_PRIVATE, 1) = 011135线程
futex(0x3f0da84, FUTEX_WAIT_PRIVATE, 17359164, NULL) = 0
futex(0x3f0da58, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x3f0da58, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x3f0da84, FUTEX_WAIT_PRIVATE, 17359172, NULL) = 0
futex(0x3f0da58, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x3f0da58, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x3f0da84, FUTEX_WAIT_PRIVATE, 17359180, NULL) = 0
futex(0x3f0da58, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x3f0da58, FUTEX_WAKE_PRIVATE, 1) = 0

到这里触及到盲区了，futex到底是干哈的，为什么会 EAGAIN (Resource temporarily unavailable)
网上资料这样解释futex：

Futex是一种用户态和内核态混合的同步机制，同步的进程间通过mmap共享一段内存，futex变量就位于这段共享的内存中且操作是原子的，当进程尝试进入互斥区或者退出互斥区的时候，先去查看共享内存中的futex变量，如果没有竞争发生，则只修改futex,而不用再执行系统调用了。当通过访问futex变量告诉进程有竞争发生，则还是得执行系统调用去完成相应的处理(wait 或者 wake up)。简单的说，futex就是通过在用户态的检查，（motivation）如果了解到没有竞争就不用陷入内核了，大大提高了low-contention时候的效率。
其原型和系统调用号为
#include <linux/futex.h>
#include <sys/time.h>
int futex (int *uaddr, int op, int val, const struct timespec *timeout,int *uaddr2, int val3);
#define __NR_futex 240
虽然参数有点长，其实常用的就是前面三个，后面的timeout大家都能理解，其他的也常被ignore。
uaddr就是用户态下共享内存的地址，里面存放的是一个对齐的整型计数器。
op存放着操作类型。定义的有5中，这里我简单的介绍一下两种，剩下的感兴趣的自己去man futex
FUTEX_WAIT: 原子性的检查uaddr中计数器的值是否为val,如果是则让进程休眠，直到FUTEX_WAKE或者超时(time-out)。也就是把进程挂到uaddr相对应的等待队列上去。
FUTEX_WAKE: 最多唤醒val个等待在uaddr上进程。
————————————————
版权声明：本文为CSDN博主「nellson」的原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接及本声明。
原文链接：https://blog.csdn.net/nellson/article/details/5400360

EAGAIN (Resource temporarily unavailable)是futex返回的一个异常码，提示重新尝试

也就是说我们的node的进程陷入了某种资源竞争，并得不到期望的响应，一直在重试，也就导致了证据2中大量close_wait的结果，
4. gdb不是很熟悉，没有获取到特别有用的信息
5. node进程分析工具，由于node性能分析工具多少都对项目有侵入，需要重启服务，这样会破坏现场，所以当时并没有立即接入
6. 猜测，在pm2的一个issue里，看到有相似的问题，所以也怀疑过是pm2调度的问题

以上便是当时收集证据的过程和结果，然而并没能定位到具体问题，只能加强监控，持续应急方案，以保证系统功能正常

接入alinode

后续一段时间里，依旧是偶然出现某台服务器node进程cpu消耗100%的情况，分析的结果都是node应用有异常，在某种条件下，会触发耗时耗时操作，但依然定位不到具体的问题，木有办法，只能在流量较少的时段，逐个接入alinode，对node应用层的任务和堆栈进行分析，以求找到蛛丝马迹，接入相对还是很便捷的，详见alinode帮助文档
不过在接入的过程中，我们也遇到了一些小问题，说明一下，有遇到同款坑的可以拿去用
问题描述：我们的服务是用pm2管理的，按照文档需要按照如下方式启动服务,/tmp改为自己的数据存储路径

首次接入后，数据收集都没问题，然而在后续的一次发版后，有部分节点的数据收集出现异常，在alinode的监控界面看不到监控数据，
alinode的日志如图，建立连接，完成注册后，就没有数据传输日志了

后来通过alinode的配置校验，发现有两个路径配置不一致，该路径用来存alinode收集到的数据

NODE_LOG_DIR=/tmp/zm_v2是我们启动项目的时候设置的环境变量，很显然和alinode检验得到的路径不一致，但在node进程的环境变量中，可以找到NODE_LOG_DIR=/tmp/zm_v2，那就是说alinode检验时并没有读取这个环境变量

所以就看下alinode的源码，巧了，找到了问题，具体看提给alinode的issue，获取环境变量的逻辑中，用默认配置“/tmp”覆盖了 pm2_env中的环境变量，所以只有重启PM2，node进程才能从pm2中继承到正确的环境变量
依次摘除流量，重启pm2，重启服务，至此alinode已正常接入

定位问题

alinode接入后，项目稳定运行，很长一段时间并没有出现cpu暴涨的情况，但这期间也并不是没有收获，找到了意料之外的一些问题

内存使用异常

很明显可以看到websiteDataCache这个对象占了100MB的内存，定位到代码中，如图，对请求的url进行了缓存，那么即使是同一个路由，只要参数不同，就会缓存一份在内存中，这样肯定是有问题的，node进程的堆内存使用上限是和v8的限制相关的，64位系统，默认堆内存上限是1.4G（不包括堆外内存，并且可通过启动参数扩展），这样用不了多久就会触发到上限制，内存溢出很可能会导致v8的频繁gc，频繁gc会持续消耗cpu，阻塞线程执行，一切看起来好像很符合我们cpu出现100%的情况，以为找到了问题的根源，在解决该问题后，内存上升的幅度也没有之前那么大了

生产很长一段时间并没有复现之前cpu100%的问题，为了验证问题是否已被解决，我们将uat环境也接入alinode，并找测试同事进行压测，压测结果显示，问题并没有被解决，起码没有完全解决
结果显示Logger和Object对象占用了比较多的内存，发现多了一个Domain对象,并且和logger形成循环引用

也就是说，我们的应用中使用了logger，domain，两者之间存在关联，按迹寻踪，在yog-log这个某块中找到了痕迹，yog-log是干哈的，官方解释如下详见yog2文档:

日志管理
在 YOG2 中，使用 yog-log 来处理日志功能，YOG2 的日志功能的特点在于可以准确的提供请求的 LogID ，方便以请求为单位对问题进行追查。准确提供请求级 LogID 的难点在于如何让各种与请求无关的模块正确的获取当前调用请求的 LogID ，如果使用全局变量，由于 Node.js 的异步 I/O 模型，不同请求直接的 LogID 会出现被覆盖的情况。 yog-log 则通过 domain 技术来保证了不同的请求之间，可以获取到正确的 LogID

yog-log通过domain来保证logId的唯一性，看了下源码，部分源码实现如下图，yog-log作为中间件模块，在每一个请求上生成一个logger实例，并挂到对应的domain上，所以在请求的生命周期内，对应的logger上就保存着对应的logId

domain是哈，为啥有这么牛皮的功能，官方解释domain是用来处理node异步错误的原生模块，熟悉node都知道，很长一段时间，node异步回调错误处理并没有很好的办法，try{}catch(){}并不能捕获异步错误，一般的做法是把错误抛到外层，通过process.on("uncaughtException",()=>{})事件捕获错误，并记录日志，方便问题查找，但是我们没有办法对发现错误的请求友好返回，因为异常处理只返回给我们一个 error, 脱离了上下文，我们只能够让它超时返回。

在node v0.8+版本的时候，发布了一个模块domain。这个模块能做到try catch无法做到的：捕捉异步回调中出现的异常。我们就可以通过domain来捕捉异步错误，给请求以友好的响应，但也隐藏了一个问题，domain捕获了异常，但也由于异常导致的堆栈积压，导致内存泄漏，不过一般都会通过pm2等守护进程进行管理，pm2可以设置node进程的内存达到设置限度时重启进程，但如果内存增长过快，会出现频繁重启的情况，也难免会出现服务异常

对于这样一个中间件模块（官方早已宣布不维护），如果项目中的日志记录都使用这个模块，那要剔除这个模块将是很大的工作量，幸运的是这个模块是yog2绑定的一个模块，项目中日志记录并没有大量使用，所以选择将该模块剔除，通过修改yog2的插件配置，yog-log打印日志的部分已经剔除了，但是压测结果并没有明显好转，扒开yog2的源码，发现插件的加载在核心的模块yog2-kernel中，修改插件配置，只是表面上不使用yog-log记录日志了，app.use(yog-log)还是将yog-log作为中间件加载，每一个请求到达时依然会构造domain

偶然的事情发生了，正在考虑怎么处理yog-log的时候，生产有一台服务器出现了cpu暴走的情况，快速使用alinode保留了堆快照，cpu-profile等信息，如下图组，qps没有大波动的情况下，内存暴涨，cpu吃满，内存的问题指向了logger，和我们之前看到的一样，但是cpu使用最多的却指向了thenfail.js，而且也和domain相关

thenfail.js是公司早期的研发对promise的实现，解决了早期nodejs回调地狱的问题，但domain这块的使用却是"from Q"，源码如下，q这个promise实现之前有用过，并没有出现这个问题，我也看了q的源码，如出一辙，但是q这么知名的promise库，issue中并没有搜到cpu100%相关的问题，仔细看源码后发现，q并没有引入domain模块，而是从process.domain获取的，然而process默认并没有domain这个属性，也就是domain是被其他模块或者代码引入的，而项目中唯一引入domain的只有yog-log，到这一切好像都打通了，两个模块之间产生影响，触发了thenfail中domain的使用，致使domain的使用贯穿到整个项目，因为所有的promise链都使用的thenfail，而且一旦出现异步错误，domain的调用将是嵌套的，也就是耗时调用会更多

   //thenfail源码/*** from Q.*/export var nextTick = (() => {// linked list of tasks (single, with head node)var head: NextTickTask = {};var tail = head;var flushing = false;var requestTick: () => void = null;var isNodeJS = false;head = head.next;var task = head.task;head.task = null;var domain = head.domain;if (domain) {head.domain = null;domain.enter();}......if (domain) {domain.exit();}}flushing = false;}var nextTick = (task: () => void) => {tail = tail.next = {task: task,domain: isNodeJS && process.domain,next: null};if (!flushing) {flushing = true;requestTick();}};.......})

后来的一次快照中，domain对cpu的占用更是达到了60%，domain.enter()，domain.exit()最为耗时，在官方domain已死的介绍中也说明了domian对性能的影响，并且domain早在2014年末就已经被官方弃用了，由于并没有设计出可以替代的模块，考虑到历史问题，并没有从node中删除

// domain源码中耗时的两个函数
//设置当前活跃的 domain, 并且为了便于回溯，将当前的 domain 加入到队列的后面，更新栈的深度
Domain.prototype.enter = function() {// Note that this might be a no-op, but we still need// to push it onto the stack so that we can pop it later.exports.active = process.domain = this;stack.push(this);updateExceptionCapture();
};// 退出当前的 domain, 更新长度，设置当前活跃的 domain。
Domain.prototype.exit = function() {// Don't do anything if this domain is not on the stack.const index = stack.lastIndexOf(this);if (index === -1) return;// Exit all domains until this one.stack.splice(index);exports.active = stack[stack.length - 1];process.domain = exports.active;updateExceptionCapture();
};

解决问题

至此已基本找到问题，只需要将process.domian这个开关去掉就可以避免thenfail中domain的频繁执行，并且对项目来说基本是无感知的改动，最方便的办法就是在yog-log加载之后，业务逻辑处理之前，将process.domain开关关掉，所以只需要写一个yog2的插件，处理该参数即可，改动之后，压测如下图组，gc时间相同的情况下，cpu耗时占比高了，也就是总体的cpu耗时下降了，压测结束后内存也会很快被回收掉，而且domian的耗时也不存在了，当然，按照分析结果，项目可优化的地方还有不少，但影响不大，目前来看，解决了最为烧眉的问题，后续会继续跟进一段时间，确保问题解决，其余的优化可以在后续工作中逐步进行

归纳总结

再回过头来看，大致可以梳理为以下流程 外部请求->.../网关/slb/nginx/ -> pm2->node进程->node任务线程，在这条处理链中，我们看到的现象是
外部部分请求响应504 -> pm2和nginx之间存在大量的close_wait链接状态 -> node进程cpu100%居高不下，node进程内存暴涨，node业务日志频率不高 -> node任务线程忙于处理某种cpu消耗的任务，表现在底层为futex频繁wait和wake，并且wake返回异常

现在根据结果可以反推
内存泄漏->频繁gc(只是开始gc的时间和domain耗时相比差太多没有表现的很明显)+domain中某种任务耗时（表现在底层就是futex的频繁调用，且得不到正常响应）->其他任务得不到cpu时间，不能正常响应-> 导致请求连接长时间close_wait（该状态不会释放链接描述符，如果服务器文件描述符被消耗完或达到配置的最大上限，将导致该服务器不能响应）->外部请求504

总结：

这是一场耗时较长的异常排查，早期出现问题时，由于业务需求和技改比较多，缺少集中精力排查问题的时间，也没有使用合适的工具
对domain这种极少使用的早期原生模块，缺乏了解和实战经验
老项目累积下来的技术栈存在历史问题，并没有在合适的时候选择优化或重构，尤其是domain被官方弃用的时候，如今尾大不掉，比较棘手
对node c++<->js的调用知之甚少，对linux底层技术了解浅薄，导致定位问题的效率降低
经过所有node从业人员的努力，十年间node模块已经堆积如山，在框架和模块选择上应该慎重，除了关注模块能力外，对性能和潜在问题的评估也应该重视
以上提供了node问题的一些排查思路和方法，有不正之处，请帮忙纠正

遗留疑问：
虽然整个推理已经串起来，并得到了验证，但是更为详细的问题触发点还有待探索，domain的执行并不是在某个点才会被触发的，而是项目运行起来后，第一个thenfail被处理的时候，就已经执行了，为什么会存在比较常的一段时间并没有明显的问题出现，而是到某一个点才会出现，cpu瞬间吃满，有时候也伴随着内存暴增的现象，这个点到底触发了什么机制或限制，这是待解释和验证的疑问

文献资料

https://github.com/nodejs/node/blob/master/lib/domain.js
https://www.bookstack.cn/read/node-in-debugging/8.2alinode.md
https://blog.csdn.net/nellson/article/details/5400360
https://github.com/kriskowal/q/blob/master/q.js
https://www.yiibai.com/unix_system_calls/futex.html