免费注册!6月19-20日,「亚马逊云科技中国峰会」重磅来袭! 了解详情
写点什么

当 NodeJS 遇上 OOM

  • 2019-11-20
  • 本文字数:3179 字

    阅读完需:约 10 分钟

当 NodeJS 遇上 OOM

前言

无论是 Java 中的 java.lang.OutOfMemoryError,还是 ASP.NET 中的 System.OutOfMemoryException ,偶尔一次内存泄漏对于传统的后端工程师来讲可谓是司空见惯的事情。


然而在 Node 编程中这个问题似乎并不常见或者说由于使用 Process Managers(进程管理器)做守护、重启,掩盖了这个问题的存在。之前一直是“此漏只应 Java 有,Node 哪的几回闻”的心态,直到在一次测试环境中遇到它。

难以发现的 OOM

// 让我们从一条日志说起...qnc:pm2-messenger process exitwith code: 1
复制代码


“早上刚部署的服务,怎么中午访问就 404 了?“(一个莫名其妙令人悲伤的故事…)


完全的出乎意料,这是个用 nohup npx启动的 node 测试服务。难道是代码有 BUG 产生了“致命”异常导致进程退出了?于是开始了我的找寻真理(BUG)之旅!


首先想到的是监听尽可能多的进程事件!


// Node官方文档关于Exit Codes有一条如下:// 1 Uncaught Fatal Exception - There was an uncaught exception, and it was not handled by a domain or an 'uncaughtException' event handler.
process.on('uncaughtException', (err, origin) => { console.error(err, origin)})
// 俩小时之后,进程退出,日志并没有异常捕获相关的输
复制代码


进程退出总有个信号啥的吧,肯定是我的监听还不够!


function handle(signal) {  console.log(`Received ${signal}`);}
process.on('SIGINT', handle);process.on('SIGHUP', handle);process.on('SIGBREAK', handle);process.on('SIGTERM', handle);
// 能用的都用上了,又是俩小时,日志无果
复制代码


一时间毫无头绪,进程总不该是被 kill 掉的吧?有人登机器杀进程?不该这么无聊啊!不是人为难道是操作系统干的?


从系统日志(/var/log/messages)中有了重大发现:


kernel: node invoked oom-killer: gfp_mask=0x200da, order=0, oom_score_adj=0kernel: node cpuset=/ mems_allowed=0... (此处省略若干行内存日志)...(还有进程列表日志)kernel:Out of memory: Kill process 12562(node) score 786or sacrifice childkernel:Killed process 12573(node) total-vm:660944kB, anon-rss:76872kB, file-rss:0kB
复制代码


至此,终于识得庐山真面目,NodeJS 遇上了 OOM!


从日志可以看出 node 触发了 oom-killer,然后系统报告了当时的内存及进程详细情况,为了保护系统正常运转最终选择 kill node(process 12562)。Linux 的内存分配和管理比较有意思,感兴趣的同学可以扒一扒相关的关键词深入学习下(overcommit-accounting)。


大致上对于单个进程的内存管理来说,系统会按照特定算法不断给进程 打分,并加入用户设定的 oom_score_adj 进行加权计算,最终得出 oom_score,得分最高者会在系统发生 OOM 的时候被终止。其它系统如 Android、IOS 也有类似的机制。

问题定位与排查

结合上面的日志我们大致知道问题应该出在 node 对内存的使用上,接下来要进行的就是具体问题的定位。首先想到的就是分析 Heap Profiler

分析 Heap Profiler

我们设定每分钟收集一次 Heap Profiler 数据,最终在被 kill 之前得到一些记录文件:


11M 18:3518-35-profile.heapsnapshot11M 18:3618-36-profile.heapsnapshot...12M 19:0119-1-profile.heapsnapshot12M 19:0219-2-profile.heapsnapshot
复制代码


可以看出从 18:35-19:02,我们的服务存活时长约半小时。通过 Chrome DevTools 对以上文件分析,我们选取服务开始(18:35)和结束前(19:02)两次采集的数据进行对比:



按照 Size Delta 排序后,可以看到变化最大的是 Node/SimpleWriteWrap



但是就算这个对象数量增加导致 Size 有所增加,堆内存总量也只占服务器内存很小一部分!



看完这个统计我决定再试试其它办法,更直观的反馈 Node 进程的内存使用。

监控 Node 进程的内存使用

Node 提供 process.memoryUsage() 这个可以实时查看进程的内存使用情况。和之前采集数据的方法一样,我们仍然设定每分钟收集一次数据,最终在被 kill 之前得到如下输出:


21:29- {"rss":279068672,"heapTotal":64028672,"heapUsed":23900184,"external":4878125}21:30- {"rss":436371456,"heapTotal":64552960,"heapUsed":23961712,"external":4878125}...21:51- {"rss":1082859520,"heapTotal":68345856,"heapUsed":34035624,"external":6653587}21:52- {"rss":1110204416,"heapTotal":61808640,"heapUsed":14772912,"external":718143}
复制代码


对比服务开始(21:29)和结束前(21:52)的日志可以看到 rss(Resident Set Size)从 270MB 飙到了 1.1GB 左右。


同时我也从系统层面对 Node 进程使用的资源进行了监控:



可以很直观的看出在两分钟内,CPU 使用率一直较高,内存(MEM)使用更是从 7% 直线上升到 54%,而且还呈现继续增加的态势!根据排查到的数据以及前文提及的 Linux 内存管理机制,问题已经非常明显——Node 进程占用资源过多导致发生 OOM 时被系统终止。事实上无论是哪个进程触发 oom_killer,系统都会选择终止消耗资源过多的进程。

如何解决

解铃还须系铃人,看来得仔细翻翻代码了!


...forkedProcess.send(xxObject) // 好在demo代码并不多,最终定位到这一行。注释掉这行之后整个世界都安静了。...
复制代码


难道是 nodejs 本身的 bug?随手查了下 nodejsissue 发现确实有人反馈过类似的<Memory leak due to process.fork()? #15651>,但是已经两年前的事情并不能解释我的问题。发送消息这个功能肯定是要保留的,接下来把目光转到接收消息的子进程中继续分析。


名为 forkedProcess 的子进程里通过监听消息进行了写文件的操作,且文件数量较多,频次也比较高。此时我们再看前文分析 Heap Profiler 快照文件,Node/SimpleWriteWrap 前后变化的原因昭然若揭。一个有趣的现象—— 子进程里消息监听的处理,影响了父进程的资源消耗(CPU、内存)! 想来也是,通过消息监听的机制注册事件,当消息派发的时候代码同步执行还是在一个进程里。


接下来尝试优化下程序逻辑。出于功能需求,写文件的数量无法减少,只能想办法减少写操作的频次。这里频次依赖消息事件的触发无法直接限定。先尝试性的设定写操作每隔一分钟就冷却一分钟(即第一分钟按照原来逻辑进行写操作,第二分钟完全停止写操作,如此反复),一个周期内的资源消耗情况如下:



可以很明显的看出来,一开始程序运行的内存使用量逐渐升高,从某一时刻(写操作停止)内存使用量开始快速降低直到恢复稳定。同时整个过程中产生的内存占用既然能被 GC 回收,也就证明没有发生内存泄漏!从恢复速度上看 NodeGC 表现也是比较出色的。尽管现在的硬盘写入速度普遍较高(机械盘 100 多 MB/S,固态盘 400 多 MB/S),但是当多个文件并发高频次的写入时,操作系统还是有很大压力。


在调整了写文件逻辑后我的服务得以平稳运行!虽然我们可以使用各类进程管理器来守护 Node 进程,在其被终止的时候不断重启,但终究会有很大风险。互联网时代,数据无价!服务的每一次异常终止都有可能产生不可估量的影响,真心推荐大家在对待问题时能审慎、笃行。

NodeJS 服务端运维的一些启示

  • 进行 I/O 操作时避免文件数量过多,避免写入频次过高。

  • 加强系统运维意识,通过 dmesg 或者系统的 log 记录(如 kernlog、messages)定期检查服务运行状态。

  • 新服务要进行性能测试,实时监控运行时的资源变化及 oom_score(可以从 /proc/进程 ID /oomscore 获取),评估是否根据实际情况调整 oom_score_adj。


作者介绍


马涛,2013 年加入去哪儿网技术团队,目前在目的地事业部,负责 H5、小程序类应用开发。个人对移动端技术领域和前后端工程化有浓厚兴趣,勇于探索实践追求极致。


本文转载自公众号 Qunar 技术沙龙(ID:QunarTL)。


原文链接


https://mp.weixin.qq.com/s?__biz=MzA3NDcyMTQyNQ==&mid=2649263171&idx=1&sn=105168ddbc2297827e2c0ad928e6bc00&chksm=87675dbdb010d4ab2eac9b6084f1930b6e79329d96d83acff104c6efe451a1fbd2a4d2b5dd6c&token=2032634643&lang=zh_CN#rd


2019-11-20 08:004244

评论

发布
暂无评论
发现更多内容

Tapdata Cloud 版本上新!率先支持数据校验、类型映射等6大新功能

tapdata

MySQL nosql schema

我遇到的那些工长

escray

生活记录 8月日更

AlphaFold2“登陆”北鲲云平台,云计算助力科研大放异彩

北鲲云

细思极恐!Alibaba新产SpringBoot深度历险(嵩山版)开源

Java 编程 架构 面试 架构师

游戏开发者的通关之旅,华为AGC for Games带来了什么?

叶落便知秋

The Data Way Vol.3|做到最后只能删库跑路?DBA 能做的还有很多

SphereEx

数据库 开源

项目中全局变量的灵活用法 12/100 发布文章

CodeNongXiaoW

Google官方bazel构建工具的安装

Changing Lin

8月日更

GitHub获120w+star的JDK源码剖析手册,竟出自Alibaba高管之手?

Java 架构 面试 程序人生 Alibaba

致远互联2021年中报:扎根协同的广阔天地,撸起袖子加油干

海比研究院

FL Studio中钢琴卷帘窗的工具的使用

懒得勤快

微信开源C/C++ RPC框架PhxRPC

OpenIM

融云 X-Live 系列直播启动,遇见通信的无限可能

融云 RongCloud

开发者 音视频 通信 融云 即时通信

新时代大视频产业的底座,视频云创变了什么?

阿里云CloudImagine

阿里云 直播技术 视频制作 视频流 视频云

程序员应该专注技术还是转管理?

石云升

职业规划 职场经验 8月日更

分享 10 个高星的创意项目!

程序员鱼皮

Java Python 数据库 大前端 Go 语言

百分点感知智能实验室:语音识别技术发展阶段探究

百分点科技技术团队

语音识别 百分点科技 感知智能

跨越AI天堑时:行动代号“盘古大模型”

脑极体

netty系列之:自建客户端和HTTP服务器交互

程序那些事

Java Netty 程序那些事

深入了解RocketMQ之过滤器

邱学喆

bloomfilter TAG过滤 SQL92

架构实战营模块1作业

^_^

架构实战营

区块链盲盒游戏app软件开发|盲盒游戏软件介绍

量化系统19942438797

区块链 智能合约 盲盒

百分点大数据技术团队:BI嵌入式分析实践

百分点科技技术团队

BI 百分点科技 嵌入式分析

读书笔记 -《数据密集型应用系统设计》- 数据编码

KayTin

不用手机,如何让猫给你打视频电话丨日常小技

声网

物联网 目标检测 目标跟踪

架构设计-模块一

逝水流

架构

ipfs矿机是什么?ipfs矿机挖出的币能交易吗?

区块链 分布式存储 ipfs挖矿 ipfs矿机 filecoin挖矿

疫情下的人生百态

6979阿强

图计算 GraphScope 新冠

webrtc 即时带宽评估器(BitrateEstimator)

webrtc developer

WebRTC

AI加持数据管理服务DAS,让数据库运维更“聪明”,DBA更轻松

华为云数据库小助手

GaussDB dba 华为云DAS 华为云数据库

算法毕业总结

Geek_Gu

当 NodeJS 遇上 OOM_语言 & 开发_马涛_InfoQ精选文章