NodeJs内存占用过高的排查实战记录
作者：noxxxx
前言
一次线上容器扩容引发的排查，虽然最后查出并不是真正的 OOM 引起的，但还是总结记录一下其中的排查过程，整个过程像是破案，一步步寻找蛛丝马迹，一步步验证出结果。
做这件事的意义和必要性个人觉得有这么几个方面吧：
- 从程序员角度讲：追求代码极致，不放过问题，务必保证业务的稳定性这几个方面
- 从资源角度讲：就是为了降低无意义的资源开销
- 从公司角度讲：降低服务器成本，给公司省钱
环境：腾讯 Taf 平台上运行的 NodeJs 服务。
问题起因
最开始是因为一个定时功能上线后，线上的容器自动进行了扩容，由于 NodeJs 服务本身只有一些接口查询和 socket.io 的功能，一没大流量，二没高并发的一个服务居然需要扩容 8 个容器（一个容器分配的是 2G 的内存），想到这里怀疑是内存泄漏了。同时日志中偶发的看到内存不足。
扩容原因
问了运维同学查到是由于内存占用到临界值导致的扩容。
负载情况
首先排除一下是不是因为服务压力过大导致的内存占用升高，可能这是一种正常的业务现象。
通过监测，发现流量和 CPU 占用都不是很高，甚至可以说是很低，那么这么高的内存占用是属于不正常的现象的。
因为是内存原因导致的，而且有逐步持续上升的现象，所以就联想到了内存泄漏这个方向，常用的做法是打印「堆快照」即 heapsnapshot 文件。
进入容器：
go 节点名称
进入 NodeJs 项目的文件夹
/usr/local/app/taf/service_name/bin/src
生成快照：
const heapdump = require('heapdump');
heapdump.writeSnapshot('./' + new Date().getTime() + '.heapsnapshot', function(err, filename) {
console.log('dump written to', filename);
});
受限于容器内使用 lrzsz 命令直接传输文件很慢，因此需要使用 scp 命令传输到一台静态资源服务器上，可以通过浏览器进行下载的。
scp 1620374489828.heapsnapshot username@ip:/data/static/snapshot
对比 heapsnapshot
在服务启动后，和运行一段时间后的生成两次快照内容，对比后的排序也只能大致看到 Websocket Socket 这些关键字。
进一步展开也无法定位到是否由某个函数引起的。
从快照里面似乎找不到什么线索，由于整个工程的业务量代码并不是很大，因此逐行 review 排查，但是似乎也没有什么异常的写法会引起 oom，其实业务代码小还好，如果是个大工程的话，这种做法没有性价比，还是需要通过一些诊断手段来排查，而不是直接去 codereview。
反复打印了几次快照，看了几遍后，还是看到 websocket 这些字眼，因而考虑到是否是因为 socket 链接未释放导致的问题呢？
Google 关键字搜了一下 WebSocket memory leak ，还真有，解决方案是加上 perMessageDeflate ，禁用压缩。目前低版本的 socket-io 默认是开启的，于是我加了之后观察了一段时间的内存占用，并未有明显的下跌，发布后，内存占用依旧很高。
配置语法：
require('socket.io').listen(server, {perMessageDeflate: false});
客户端发送的请求中含有这个字段：
首先这个参数是用来压缩数据的，client 端默认是开启，server 端是关闭的，出于某些原因，开启后会导致内存和性能的消耗，官方建议是考虑后再决定是否开启。但是低版本的 socket-io 是开启的，比如 ^2.3.0 的版本（貌似是 bug，后续版本已经改为默认关闭）。
The extension is disabled by default on the server and enabled by default on the client. It adds a significant overhead in terms of performance and memory consumption so we suggest to enable it only if it is really needed.
https://github.com/socketio/socket.io/issues/3477#issuecomment-610265035
开启后，内存仍旧居高不下。
console.log
另外一个现象就是现有的 Node 服务会打印一些日志，翻了一些网上的 NodeJs 内存泄漏的文章，有看到 console 日志输出导致的泄漏的情况，因此注释掉 console 之后继续观察内存占用，结果仍旧是内存高占用。
线索到这里似乎就断掉了，没有头绪了。
日志
过了一天后，无意中看了一下日志文件，由于服务启动的时候会打印一些启动日志，发现有重复输出的情况：
说明有重复运行的情况，为了验证这一猜想，使用 top 命令查看。
TOP 命令
同时还想看一下具体的内存占用。发现居然有这么多的 worker process ，根据当前业务的实际使用情况不应该只有 2 ~ 4 个就够了么，为什么要开这么多的子进程。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 90359 username 20 0 736m 38m 14m S 0.0 0.0 0:07.30 /usr/local/app/service_name/bin/src/index.js: worker process 90346 username 20 0 864m 38m 14m S 0.3 0.0 0:07.08 /usr/local/app/service_name/bin/src/index.js: worker process 90381 username 20 0 730m 38m 14m S 0.3 0.0 0:08.75 /usr/local/app/service_name/bin/src/index.js: worker process 90366 username 20 0 804m 37m 14m S 0.0 0.0 0:06.94 /usr/local/app/service_name/bin/src/index.js: worker process 90618 username 20 0 730m 37m 14m S 0.0 0.0 0:08.42 /usr/local/app/service_name/bin/src/index.js: worker process 90326 username 20 0 736m 37m 14m S 0.0 0.0 0:08.46 /usr/local/app/service_name/bin/src/index.js: worker process 90542 username 20 0 736m 37m 14m S 0.0 0.0 0:08.85 /usr/local/app/service_name/bin/src/index.js: worker process 90332 username 20 0 799m 37m 14m S 0.0 0.0 0:07.32 /usr/local/app/service_name/bin/src/index.js: worker process 90580 username 20 0 732m 37m 14m S 0.3 0.0 0:08.94 /usr/local/app/service_name/bin/src/index.js: worker process 90602 username 20 0 731m 37m 14m S 0.3 0.0 0:08.33 /usr/local/app/service_name/bin/src/index.js: worker process 90587 username 20 0 735m 37m 14m S 0.0 0.0 0:08.83 /usr/local/app/service_name/bin/src/index.js: worker process 90568 username 20 0 731m 37m 14m S 0.0 0.0 0:08.83 /usr/local/app/service_name/bin/src/index.js: worker process 90544 username 20 0 729m 37m 14m S 0.0 0.0 0:09.07 /usr/local/app/service_name/bin/src/index.js: worker process 90556 username 20 0 729m 37m 14m S 0.0 0.0 0:08.82 /usr/local/app/service_name/bin/src/index.js: worker process 90431 username 20 0 735m 37m 14m S 0.0 0.0 0:08.29 /usr/local/app/service_name/bin/src/index.js: worker process 90486 username 20 0 729m 37m 14m S 0.0 0.0 0:09.06 /usr/local/app/service_name/bin/src/index.js: worker process 90516 username 20 0 735m 37m 14m S 0.0 0.0 0:08.95 /usr/local/app/service_name/bin/src/index.js: worker process 90465 username 20 0 729m 37m 14m S 0.0 0.0 0:09.06 /usr/local/app/service_name/bin/src/index.js: worker process 90527 username 20 0 735m 37m 14m S 0.0 0.0 0:08.46 /usr/local/app/service_name/bin/src/index.js: worker process 90487 username 20 0 732m 37m 14m S 0.3 0.0 0:08.48 /usr/local/app/service_name/bin/src/index.js: worker process 90371 username 20 0 731m 37m 14m S 0.3 0.0 0:08.75 /usr/local/app/service_name/bin/src/index.js: worker process 90423 username 20 0 729m 36m 14m S 0.3 0.0 0:08.09 /usr/local/app/service_name/bin/src/index.js: worker process 90402 username 20 0 729m 36m 14m S 0.3 0.0 0:08.96 /usr/local/app/service_name/bin/src/index.js: worker process 90500 username 20 0 729m 36m 14m S 0.0 0.0 0:08.70 /usr/local/app/service_name/bin/src/index.js: worker process 90353 username 20 0 729m 36m 14m S 0.3 0.0 0:08.95 /usr/local/app/service_name/bin/src/index.js: worker process 90636 username 20 0 729m 36m 14m S 0.0 0.0 0:08.84 /usr/local/app/service_name/bin/src/index.js: worker process 90425 username 20 0 732m 36m 14m S 0.0 0.0 0:08.78 /usr/local/app/service_name/bin/src/index.js: worker process 90506 username 20 0 729m 36m 14m S 0.0 0.0 0:08.84 /usr/local/app/service_name/bin/src/index.js: worker process 90589 username 20 0 729m 36m 14m S 0.3 0.0 0:09.05 /usr/local/app/service_name/bin/src/index.js: worker process 90595 username 20 0 729m 36m 14m S 0.0 0.0 0:09.03 /usr/local/app/service_name/bin/src/index.js: worker process 90450 username 20 0 729m 36m 14m S 0.3 0.0 0:08.97 /usr/local/app/service_name/bin/src/index.js: worker process 90531 username 20 0 729m 36m 14m S 0.0 0.0 0:08.99 /usr/local/app/service_name/bin/src/index.js: worker process 90509 username 20 0 735m 36m 14m S 0.0 0.0 0:08.67 /usr/local/app/service_name/bin/src/index.js: worker process 90612 username 20 0 730m 36m 14m S 0.3 0.0 0:08.84 /usr/local/app/service_name/bin/src/index.js: worker process 90479 username 20 0 729m 36m 14m S 0.0 0.0 0:08.58 /usr/local/app/service_name/bin/src/index.js: worker process 90609 username 20 0 731m 36m 14m S 0.3 0.0 0:09.23 /usr/local/app/service_name/bin/src/index.js: worker process 90404 username 20 0 734m 36m 14m S 0.3 0.0 0:08.78 /usr/local/app/service_name/bin/src/index.js: worker process 90395 username 20 0 736m 36m 14m S 0.0 0.0 0:08.57 /usr/local/app/service_name/bin/src/index.js: worker process 90444 username 20 0 729m 36m 14m S 0.0 0.0 0:09.04 /usr/local/app/service_name/bin/src/index.js: worker process 90438 username 20 0 729m 36m 14m S 0.3 0.0 0:07.78 /usr/local/app/service_name/bin/src/index.js: worker process 90340 username 20 0 736m 36m 14m S 0.3 0.0 0:07.37 /usr/local/app/service_name/bin/src/index.js: worker process 90333 username 20 0 729m 36m 14m S 0.0 0.0 0:07.60 /usr/local/app/service_name/bin/src/index.js: worker process 90563 username 20 0 735m 36m 14m S 0.3 0.0 0:08.93 /usr/local/app/service_name/bin/src/index.js: worker process 90565 username 20 0 734m 36m 14m S 0.3 0.0 0:08.77 /usr/local/app/service_name/bin/src/index.js: worker process 90457 username 20 0 735m 36m 14m S 0.0 0.0 0:08.31 /usr/local/app/service_name/bin/src/index.js: worker process 90387 username 20 0 740m 36m 14m S 0.0 0.0 0:07.59 /usr/local/app/service_name/bin/src/index.js: worker process 90573 username 20 0 728m 35m 14m S 0.0 0.0 0:09.06 /usr/local/app/service_name/bin/src/index.js: worker process 90472 username 20 0 728m 35m 14m S 0.0 0.0 0:08.94 /usr/local/app/service_name/bin/src/index.js: worker process 90313 username 20 0 588m 27m 13m S 0.0 0.0 0:00.46 /usr/local/app/service_name/bin/src/index.js: master process
由于 %MEM 这一列的数值在容器内部看不出具体的内存占用，都是显示的 0.0，所以需要查看 VIRT, RES 和 SHR 这三个值，它们的含义可以在这里查看： https://www.orchome.com/298
我们更关心 RES，RES 的含义是指进程虚拟内存空间中已经映射到物理内存空间的那部分的大小，因此可以发现，一个 worker process 占用了 35 ~ 38M 之间的内存大小，一共有 48 个 worker process， 一个 master process。
48 个 worker process 是怎么来的呢？通过查询 CPU 的逻辑个数，可以看到确实是 48 个。
# 总核数 = 物理CPU个数 X 每颗物理CPU的核数 # 总逻辑CPU数 = 物理CPU个数 X 每颗物理CPU的核数 X 超线程数 # 查看物理CPU个数 cat /proc/cpuinfo| grep "physical id"| sort| uniq| wc -l # 查看每个物理CPU中core的个数(即核数) cat /proc/cpuinfo| grep "cpu cores"| uniq # 查看逻辑CPU的个数 cat /proc/cpuinfo| grep "processor"| wc -l
控制进程数
由于对 Taf 平台不是很熟悉，了解到在 taf 上面运行 NodeJS 需要对应的 package： @tars/node-agent ，查了一下官网的使用文档： https://tarscloud.github.io/TarsDocs/dev/tars.js/tars-node-agent.html
有一个 -i 的配置，代表 instances
-i, –instances
node-agent 采用 Node.js 原生的 Cluster 模块来实现负载均衡。
可在此配置 node-agent 启动的子进程（业务进程）数量：
未配置（或配置为 auto 、 0 ），启动的子进程数量等于 CPU 物理核心 个数。
配置为 max ，启动的子进程数量等于 CPU 个数（所有核心数）。
如果 node-agent 是由 tarsnode 启动的，会自动读取TARS配置文件中的 tars.application.client.asyncthread 配置节。
也可通过 TARS平台 -> 编辑服务 -> 异步线程数 进行调整。
https://tarscloud.github.io/TarsDocs/dev/tars.js/tars-node-agent.html
通过这个 package 启动 Taf 上的 NodeJs 服务，同时开启负载均衡的能力，由于没有配置具体的子进程（业务进程）数量，所以默认就是用了 CPU 物理核心 个数，因为是 2 个 cpu 所以再 *2，一共生成了 48 个 ♂️，每个 worker process 都要占用内存，所以内存占用一直居高不下。
可以在「私有模板」里修改配置：
然后重启服务，查看内存占用：
可见 worker process 数量影响了内存占用，原先内存使用率的趋势图上会持续增长（刚开始也是因此怀疑内存泄漏），这个问题在降低了 worker process 后并没有体现出来，目前暂且忽略，后续会持续观察。
为了验证重复 console 和 worker process 的关系，在开启 2 个 worker process 的情况下，查看日志，确实是打印了 2 次。
总结
复盘一下这次的问题：
为什么没有及时发现？
可能和前端开发者的角色有一定关系，对于后端服务的一些特性不太敏感。也没有花精力去关注，或者说不知道，不了解。
是否可以提前避免？
可以有类似的告警机制提示 Node 服务的内存在上升趋势，获取我还没有熟悉透 Taf 平台的功能，后期摸索一下。
到此这篇关于NodeJs内存占用过高的排查的文章就介绍到这了,更多相关NodeJs内存占用过高内容请搜索脚本之家以前的文章或继续浏览下面的相关文章希望大家以后多多支持脚本之家！