NodeJs內(nèi)存占用過(guò)高的排查實(shí)戰(zhàn)記錄
前言
一次線上容器擴(kuò)容引發(fā)的排查，雖然最后查出并不是真正的 OOM 引起的，但還是總結(jié)記錄一下其中的排查過(guò)程，整個(gè)過(guò)程像是破案，一步步尋找蛛絲馬跡，一步步驗(yàn)證出結(jié)果。
做這件事的意義和必要性個(gè)人覺(jué)得有這么幾個(gè)方面吧：
- 從程序員角度講：追求代碼極致，不放過(guò)問(wèn)題，務(wù)必保證業(yè)務(wù)的穩(wěn)定性這幾個(gè)方面
- 從資源角度講：就是為了降低無(wú)意義的資源開(kāi)銷(xiāo)
- 從公司角度講：降低服務(wù)器成本，給公司省錢(qián)
環(huán)境：騰訊 Taf 平臺(tái)上運(yùn)行的 NodeJs 服務(wù)。
問(wèn)題起因
最開(kāi)始是因?yàn)橐粋€(gè)定時(shí)功能上線后，線上的容器自動(dòng)進(jìn)行了擴(kuò)容，由于 NodeJs 服務(wù)本身只有一些接口查詢和 socket.io 的功能，一沒(méi)大流量，二沒(méi)高并發(fā)的一個(gè)服務(wù)居然需要擴(kuò)容 8 個(gè)容器（一個(gè)容器分配的是 2G 的內(nèi)存），想到這里懷疑是內(nèi)存泄漏了。同時(shí)日志中偶發(fā)的看到內(nèi)存不足。
擴(kuò)容原因
問(wèn)了運(yùn)維同學(xué)查到是由于內(nèi)存占用到臨界值導(dǎo)致的擴(kuò)容。
負(fù)載情況
首先排除一下是不是因?yàn)榉?wù)壓力過(guò)大導(dǎo)致的內(nèi)存占用升高，可能這是一種正常的業(yè)務(wù)現(xiàn)象。
通過(guò)監(jiān)測(cè)，發(fā)現(xiàn)流量和 CPU 占用都不是很高，甚至可以說(shuō)是很低，那么這么高的內(nèi)存占用是屬于不正常的現(xiàn)象的。
因?yàn)槭莾?nèi)存原因?qū)е碌?，而且有逐步持續(xù)上升的現(xiàn)象，所以就聯(lián)想到了內(nèi)存泄漏這個(gè)方向，常用的做法是打印「堆快照」即 heapsnapshot 文件。
進(jìn)入容器：
go 節(jié)點(diǎn)名稱
進(jìn)入 NodeJs 項(xiàng)目的文件夾
/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);
});
受限于容器內(nèi)使用 lrzsz 命令直接傳輸文件很慢，因此需要使用 scp 命令傳輸?shù)揭慌_(tái)靜態(tài)資源服務(wù)器上，可以通過(guò)瀏覽器進(jìn)行下載的。
scp 1620374489828.heapsnapshot username@ip:/data/static/snapshot
對(duì)比 heapsnapshot
在服務(wù)啟動(dòng)后，和運(yùn)行一段時(shí)間后的生成兩次快照內(nèi)容，對(duì)比后的排序也只能大致看到 Websocket Socket 這些關(guān)鍵字。
進(jìn)一步展開(kāi)也無(wú)法定位到是否由某個(gè)函數(shù)引起的。
從快照里面似乎找不到什么線索，由于整個(gè)工程的業(yè)務(wù)量代碼并不是很大，因此逐行 review 排查，但是似乎也沒(méi)有什么異常的寫(xiě)法會(huì)引起 oom，其實(shí)業(yè)務(wù)代碼小還好，如果是個(gè)大工程的話，這種做法沒(méi)有性價(jià)比，還是需要通過(guò)一些診斷手段來(lái)排查，而不是直接去 codereview。
反復(fù)打印了幾次快照，看了幾遍后，還是看到 websocket 這些字眼，因而考慮到是否是因?yàn)?socket 鏈接未釋放導(dǎo)致的問(wèn)題呢？
Google 關(guān)鍵字搜了一下 WebSocket memory leak ，還真有，解決方案是加上 perMessageDeflate ，禁用壓縮。目前低版本的 socket-io 默認(rèn)是開(kāi)啟的，于是我加了之后觀察了一段時(shí)間的內(nèi)存占用，并未有明顯的下跌，發(fā)布后，內(nèi)存占用依舊很高。
配置語(yǔ)法：
require('socket.io').listen(server, {perMessageDeflate: false});
客戶端發(fā)送的請(qǐng)求中含有這個(gè)字段：
首先這個(gè)參數(shù)是用來(lái)壓縮數(shù)據(jù)的，client 端默認(rèn)是開(kāi)啟，server 端是關(guān)閉的，出于某些原因，開(kāi)啟后會(huì)導(dǎo)致內(nèi)存和性能的消耗，官方建議是考慮后再?zèng)Q定是否開(kāi)啟。但是低版本的 socket-io 是開(kāi)啟的，比如 ^2.3.0 的版本（貌似是 bug，后續(xù)版本已經(jīng)改為默認(rèn)關(guān)閉）。
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
開(kāi)啟后，內(nèi)存仍舊居高不下。
console.log
另外一個(gè)現(xiàn)象就是現(xiàn)有的 Node 服務(wù)會(huì)打印一些日志，翻了一些網(wǎng)上的 NodeJs 內(nèi)存泄漏的文章，有看到 console 日志輸出導(dǎo)致的泄漏的情況，因此注釋掉 console 之后繼續(xù)觀察內(nèi)存占用，結(jié)果仍舊是內(nèi)存高占用。
線索到這里似乎就斷掉了，沒(méi)有頭緒了。
日志
過(guò)了一天后，無(wú)意中看了一下日志文件，由于服務(wù)啟動(dòng)的時(shí)候會(huì)打印一些啟動(dòng)日志，發(fā)現(xiàn)有重復(fù)輸出的情況：
說(shuō)明有重復(fù)運(yùn)行的情況，為了驗(yàn)證這一猜想，使用 top 命令查看。
TOP 命令
同時(shí)還想看一下具體的內(nèi)存占用。發(fā)現(xiàn)居然有這么多的 worker process ，根據(jù)當(dāng)前業(yè)務(wù)的實(shí)際使用情況不應(yīng)該只有 2 ~ 4 個(gè)就夠了么，為什么要開(kāi)這么多的子進(jìn)程。
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 這一列的數(shù)值在容器內(nèi)部看不出具體的內(nèi)存占用，都是顯示的 0.0，所以需要查看 VIRT, RES 和 SHR 這三個(gè)值，它們的含義可以在這里查看： https://www.orchome.com/298
我們更關(guān)心 RES，RES 的含義是指進(jìn)程虛擬內(nèi)存空間中已經(jīng)映射到物理內(nèi)存空間的那部分的大小，因此可以發(fā)現(xiàn)，一個(gè) worker process 占用了 35 ~ 38M 之間的內(nèi)存大小，一共有 48 個(gè) worker process， 一個(gè) master process。
48 個(gè) worker process 是怎么來(lái)的呢？通過(guò)查詢 CPU 的邏輯個(gè)數(shù)，可以看到確實(shí)是 48 個(gè)。
# 總核數(shù) = 物理CPU個(gè)數(shù) X 每顆物理CPU的核數(shù) # 總邏輯CPU數(shù) = 物理CPU個(gè)數(shù) X 每顆物理CPU的核數(shù) X 超線程數(shù) # 查看物理CPU個(gè)數(shù) cat /proc/cpuinfo| grep "physical id"| sort| uniq| wc -l # 查看每個(gè)物理CPU中core的個(gè)數(shù)(即核數(shù)) cat /proc/cpuinfo| grep "cpu cores"| uniq # 查看邏輯CPU的個(gè)數(shù) cat /proc/cpuinfo| grep "processor"| wc -l
控制進(jìn)程數(shù)
由于對(duì) Taf 平臺(tái)不是很熟悉，了解到在 taf 上面運(yùn)行 NodeJS 需要對(duì)應(yīng)的 package： @tars/node-agent ，查了一下官網(wǎng)的使用文檔： https://tarscloud.github.io/TarsDocs/dev/tars.js/tars-node-agent.html
有一個(gè) -i 的配置，代表 instances
-i, –instances
node-agent 采用 Node.js 原生的 Cluster 模塊來(lái)實(shí)現(xiàn)負(fù)載均衡。
可在此配置 node-agent 啟動(dòng)的子進(jìn)程（業(yè)務(wù)進(jìn)程）數(shù)量：
未配置（或配置為 auto 、 0 ），啟動(dòng)的子進(jìn)程數(shù)量等于 CPU 物理核心 個(gè)數(shù)。
配置為 max ，啟動(dòng)的子進(jìn)程數(shù)量等于 CPU 個(gè)數(shù)（所有核心數(shù)）。
如果 node-agent 是由 tarsnode 啟動(dòng)的，會(huì)自動(dòng)讀取TARS配置文件中的 tars.application.client.asyncthread 配置節(jié)。
也可通過(guò) TARS平臺(tái) -> 編輯服務(wù) -> 異步線程數(shù) 進(jìn)行調(diào)整。
https://tarscloud.github.io/TarsDocs/dev/tars.js/tars-node-agent.html
通過(guò)這個(gè) package 啟動(dòng) Taf 上的 NodeJs 服務(wù)，同時(shí)開(kāi)啟負(fù)載均衡的能力，由于沒(méi)有配置具體的子進(jìn)程（業(yè)務(wù)進(jìn)程）數(shù)量，所以默認(rèn)就是用了 CPU 物理核心 個(gè)數(shù)，因?yàn)槭?2 個(gè) cpu 所以再 *2，一共生成了 48 個(gè) ♂️，每個(gè) worker process 都要占用內(nèi)存，所以內(nèi)存占用一直居高不下。
可以在「私有模板」里修改配置：
然后重啟服務(wù)，查看內(nèi)存占用：
可見(jiàn) worker process 數(shù)量影響了內(nèi)存占用，原先內(nèi)存使用率的趨勢(shì)圖上會(huì)持續(xù)增長(zhǎng)（剛開(kāi)始也是因此懷疑內(nèi)存泄漏），這個(gè)問(wèn)題在降低了 worker process 后并沒(méi)有體現(xiàn)出來(lái)，目前暫且忽略，后續(xù)會(huì)持續(xù)觀察。
為了驗(yàn)證重復(fù) console 和 worker process 的關(guān)系，在開(kāi)啟 2 個(gè) worker process 的情況下，查看日志，確實(shí)是打印了 2 次。
總結(jié)
復(fù)盤(pán)一下這次的問(wèn)題：
為什么沒(méi)有及時(shí)發(fā)現(xiàn)？
可能和前端開(kāi)發(fā)者的角色有一定關(guān)系，對(duì)于后端服務(wù)的一些特性不太敏感。也沒(méi)有花精力去關(guān)注，或者說(shuō)不知道，不了解。
是否可以提前避免？
可以有類似的告警機(jī)制提示 Node 服務(wù)的內(nèi)存在上升趨勢(shì)，獲取我還沒(méi)有熟悉透 Taf 平臺(tái)的功能，后期摸索一下。
到此這篇關(guān)于NodeJs內(nèi)存占用過(guò)高的排查的文章就介紹到這了,更多相關(guān)NodeJs內(nèi)存占用過(guò)高內(nèi)容請(qǐng)搜索腳本之家以前的文章或繼續(xù)瀏覽下面的相關(guān)文章希望大家以后多多支持腳本之家！
相關(guān)文章
npm報(bào)錯(cuò)"A?complete?log?of?this?run?can?be?found?
這篇文章主要給大家介紹了關(guān)于npm報(bào)錯(cuò)"A?complete?log?of?this?run?can?be?found?in:"的解決辦法,文中通過(guò)實(shí)例代碼介紹的非常詳細(xì),對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值,需要的朋友可以參考下2023-04-04
這篇文章主要介紹了Node.js如何在項(xiàng)目中操作MySQL，從而實(shí)現(xiàn)數(shù)據(jù)的查詢、插入、更新和刪除等操作，感興趣的小伙伴可以跟隨小編一起學(xué)習(xí)一下2022-01-01
這篇文章主要討論并驗(yàn)證了node.js中的forEach()是同步還是異步，思路和方法分享給大家，有需要的小伙伴可以參考下。2015-01-01
這篇文章主要介紹了Node.js 如何利用異步提升任務(wù)處理速度，小編覺(jué)得挺不錯(cuò)的，現(xiàn)在分享給大家，也給大家做個(gè)參考。一起跟隨小編過(guò)來(lái)看看吧2019-01-01
Nodejs下運(yùn)行JS代碼有兩種方式,一種是在Node.js的交互環(huán)境下運(yùn)行,另外一種是把代碼寫(xiě)入文件中,然后用node命令執(zhí)行文件代碼,下面這篇文章主要給大家介紹了關(guān)于node環(huán)境執(zhí)行js文件的相關(guān)資料,需要的朋友可以參考下2023-02-02
這篇文章主要介紹了Nodejs中的require函數(shù)的具體使用方法，小編覺(jué)得挺不錯(cuò)的，現(xiàn)在分享給大家，也給大家做個(gè)參考。一起跟隨小編過(guò)來(lái)看看吧2019-04-04
Node.js服務(wù)端實(shí)戰(zhàn)之服務(wù)啟動(dòng)過(guò)程詳解
這篇文章主要為大家介紹了Node.js服務(wù)端實(shí)戰(zhàn)之服務(wù)啟動(dòng)過(guò)程詳解，有需要的朋友可以借鑒參考下，希望能夠有所幫助，祝大家多多進(jìn)步，早日升職加薪2022-12-12
在本篇文章中我們給大家分享了關(guān)于Node.js讀寫(xiě)中文內(nèi)容文件操作的相關(guān)知識(shí)點(diǎn)內(nèi)容，有需要的朋友們可以學(xué)習(xí)下。2018-10-10
詳解用node.js實(shí)現(xiàn)簡(jiǎn)單的反向代理
本篇文章主要介紹了詳解用node.js實(shí)現(xiàn)簡(jiǎn)單的反向代理，小編覺(jué)得挺不錯(cuò)的，現(xiàn)在分享給大家，也給大家做個(gè)參考。一起跟隨小編過(guò)來(lái)看看吧2017-06-06
下面小編就為大家分享一篇Mac中安裝nvm的教程，具有很好的參考價(jià)值，希望對(duì)大家有所幫助。一起跟隨小編過(guò)來(lái)看看吧2017-12-12