NodeJs 内存占用过高排查记录

2021-06-25 10:36:25 浏览数 (1)

因为线上容器扩容引发的排查,虽然最后查出并不是真正的 OOM 引起的,但还是总结记录一下其中的排查过程,整个过程像是破案,一步步寻找蛛丝马迹,一步步验证出结果。

做这件事的意义和必要性个人觉得有这么几个方面吧:

  1. 从程序员角度讲:追求代码极致,不放过问题,务必保证业务的稳定性这几个方面
  2. 从资源角度讲:就是为了降低无意义的资源开销
  3. 从公司角度讲:降低服务器成本,给公司省钱

服务运行环境:腾讯 Taf 平台上运行的 NodeJs 服务。

问题起因

最开始是因为一个定时功能上线后,线上的容器自动进行了扩容,由于 NodeJs 服务本身只有一些接口查询和 socket.io 的功能,一没大流量,二没高并发的一个服务居然需要扩容 8 个容器(一个容器分配的是 2G 的内存),想到这里怀疑是内存泄漏了。同时日志中偶发的看到内存不足。

扩容原因

问了运维同学查到是由于内存占用到临界值导致的扩容。

负载情况

首先排除一下是不是因为服务压力过大导致的内存占用升高,因为这可能是一种正常的负载现象。

通过监测,发现流量和 CPU 占用都不是很高,甚至可以说是很低,那么这么高的内存占用是属于不正常的现象的。

因为是内存原因导致的,而且有逐步持续上升的现象,所以就联想到了内存泄漏这个方向,常用的做法是打印「堆快照」即 heapsnapshot文件。

进入容器:

代码语言:javascript复制
go 节点名称

进入 NodeJs 项目的文件夹

代码语言:javascript复制
/usr/local/app/taf/service_name/bin/src

生成快照:

代码语言:javascript复制
const heapdump = require('heapdump');
heapdump.writeSnapshot('./'   new Date().getTime()   '.heapsnapshot', function(err, filename) {
    console.log('dump written to', filename);
});

受限于容器内使用 lrzsz 命令直接传输文件很慢,因此需要使用 scp命令传输到一台静态资源服务器上,可以通过浏览器进行下载的。

代码语言:javascript复制
 scp 1620374489828.heapsnapshot username@ip:/data/static/snapshot

对比 heapsnapshot

在服务启动后,和运行一段时间后的生成两次快照内容,对比后的排序「Size Delta」也只能大致看到 Websocket Socket 这些关键字。

进一步展开也无法定位到是否由某个函数引起的。

从快照里面似乎找不到什么线索,由于整个工程的业务量代码并不是很大,因此逐行 review code 排查,但是似乎也没有什么异常的写法会引起 oom,回过头反思,业务代码小还好,如果是个大工程的话,这种做法没有性价比,还是需要通过一些诊断手段来排查,而不是直接去 codereview。

反复打印了几次快照,看了几遍后,还是看到 websocket 这些字眼,因而考虑到是否是因为 socket 链接未释放导致的问题呢?

Google 关键字搜了一下 WebSocket memory leak ,还真有,解决方案是加上perMessageDeflate,禁用压缩。目前低版本的 socket-io 默认是开启的,于是我加了之后观察了一段时间的内存占用,并未有明显的下跌,发布后,内存占用依旧很高。

配置语法:

代码语言:javascript复制
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 个就够了么,为什么要开这么多的子进程。

代码语言:javascript复制
  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 个。

代码语言:javascript复制
# 总核数 = 物理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,这个模块是平台帮你运行的,所以自己的项目里是没有 install 这个 package 的,查了一下官网的使用文档:https://tarscloud.github.io/TarsDocs/dev/tars.js/tars-node-agent.html

有一个 -i 的配置, instances

-i, –instances node-agent 采用 Node.js 原生的 Cluster 模块来实现负载均衡。 可在此配置 node-agent 启动的子进程(业务进程)数量: 未配置(或配置为 auto0),启动的子进程数量等于 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 个

0 人点赞