NodeJs內存占用過高的排查實戰記錄
前言
一次線上容器擴容引發的排查，雖然最後查出並不是真正的 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內存占用過高內容請搜索WalkonNet以前的文章或繼續瀏覽下面的相關文章希望大傢以後多多支持WalkonNet！
推薦閱讀：
- Nodejs搭建多進程Web服務器實現過程
- mac下徹底卸載node和npm方法步驟
- node獲取命令行中的參數詳解
- nodejs與瀏覽器中全局對象區別點總結
- Linux通過yum命令徹底刪除node.js並重新安裝