前言最近,我们团队接手了一个遗留项目,这是一个用Node.js语言编写的HTTP服务项目。项目的大体逻辑是通过Node.jsLogic实现一层proxy,做流量中转,增加一些关键埋点展示请求记录(还有一些高级用法,篡改请求相关数据,但是它有与此故障排除无关,因此我不会详细介绍)。我们刚接手的时候遇到的情况是,由于内存泄漏等不明原因,项目必须定时重启,否则用户在使用时会出现明显的延迟或者服务直接不可用。于是开始阅读源码,了解项目,分析问题原因并尝试修复,同时进行人肉运维。在调查过程中,该项目嵌入了关键指标,包括内存、CPU等指标,以及用户流量统计。我们看到了两个重要的指标:内存趋势中的活跃句柄数与最初获取的信息一致,存在内存泄漏问题,不到一个小时指标就因为服务重启而断崖式下跌。同样,下方的ActiveHandle指标也波动较大。下面简单介绍一下什么是ActiveHandle。这就引申出Node.js技术栈中经常涉及到的一个关键词:EventLoop。简单介绍一下EventLoop,简单说明一下EventLoop的工作模式。如果我们有一个文件并写了这样的代码:console.log('hello'),那么我们通过节点XXX运行这个文件,进程就会退出。而如果我们这样写一个文件:console.log('hello')setInterval(()=>{},1e3)通过节点XXX再次运行这个文件,终端会停留在进程中,不会退出,因为我们创建了一个定时器,定时器可以理解为一个ActiveHandle,而EventLoop的运行过程就是执行所有的同步代码,然后检测是否有ActiveHandle,如果检测不到则直接退出,如果有Handle,就会进入我们熟悉的EventLoop。我们可以通过一个非公开的API获取ActiveHandles的数量:process._getActiveHandles()console.log(process._getActiveHandles().length)//0如果我们通过节点XXX运行这样的代码,那么我们将得到一个0,而如果我们直接通过node进入交互式命令行,我们会发现这个值为2,这是因为交互式命令行会绑定stdin和stdout,这就是为什么你会停留在交互式命令行环境中,而不是一个终端。process.nextTick、net.listen和fs.XXX等各种异步API都可以视为ActiveHandle。只要有类似的场景,进程就可以一直运行。上面简单说明了什么是ActiveHandle,为什么这个指标会帮助我们排查问题,后面会提到。问题分析在查看项目代码的过程中,我们发现项目的核心逻辑是转发流量,而实现这个功能的方式是将两个Socket相互绑定。具体代码:exportfunctionpipeSocket(from:Socket,to:Socket){from.on('data',chunk=>{to.write(chunk)})from.on('close',()=>{to.destroy()})}看起来没什么问题,但是结合我们前面看到的活跃句柄数量的异常波动,我们有理由怀疑它有什么关系。同时,我们在各项指标异常的时候检查了服务器上的问题,发现了一些蛛丝马迹。我们执行netstat-an|awk'/^tcp/{++y[$NF]}END{for(winy)printw,y[w]}'查看当前连接类型数的统计,得到了一个结果类似这样:可以看到有很多ESTABLISHED类型。这其实和我最初的猜测不一样。本以为会是常见的CLOSE_WAIT和TIME_WAIT问题,没想到是ESTABLISHED的个数异常。在TCP连接的状态定义中,ESTABLISHED代表一个连接已经建立成功,可以理解为正常的数据传输状态:但是同时有那么多连接在传输显然不是正常状态,所以我们执行netstat-nat|grepESTABLISHED|awk'{print$5}'|awk-F:'{print$1}'|sort|uniq-c来进一步查看哪些IP占用最多的连接。不出所料,发现是127.0.0.1,这是因为本项目的代理逻辑是通过转发到本地特定端口服务来完成的,而实际的代理逻辑是由服务提供的。由于IP敏感性,不会发布任何地图。一般情况是查出几十条数据,127.0.0.1中一条数据对应的数量超过2W。接下来我们对127.0.0.1进行进一步的调查,我们要找出为什么会有这么多连接处于传输状态,为什么这些连接没有关闭。因此,我们通过执行ss-aoen|对前十个相关的Socket统计信息进行采样。grep'127.0.0.1'|grep'ESTAB'|tail-n10,这里我们发现了一些端倪,在统计的最后一栏的详细信息中,我们发现很多Sockets并没有超时设置。这更令人困惑,因为我们的系统实际上设置为保持活动状态。如果对端数据不再传输,连接应该只保持2小时(我们的系统设置为7200)。不会有那么多的连接。通过上面ss命令得到的结果,也帮助我们更加确定。有些socket没有正常释放,一直处于ESTABLISHED状态。为了统计准确的数据,我们分别输入以下两条命令,根据是否包含定时器来区分统计信息:ss-aoen|grep'127.0.0.1'|grep'ESTAB'|grep-v'定时器:'|wc-l#28636ss-aoen|grep'127.0.0.1'|grep'ESTAB'|grep'定时器:'|wc-l#115数量上的差距是可怕的。然后我们通过采样找到几个ss端口号,使用lsof-p
