楔子

本章前面兩節(jié)生產(chǎn)案例分別側(cè)重于單一的 CPU 高和單一的內(nèi)存問(wèn)題，我們也給大家詳細(xì)展示了問(wèn)題的定位排查過(guò)程，那么實(shí)際上還有一類相對(duì)更復(fù)雜的場(chǎng)景——它本質(zhì)上是 V8 引擎的 GC 引發(fā)的問(wèn)題。

簡(jiǎn)單的給大家介紹下什么是 GC，GC 實(shí)際上是語(yǔ)言引擎實(shí)現(xiàn)的一種自動(dòng)垃圾回收機(jī)制，它會(huì)在設(shè)定的條件觸發(fā)時(shí)（比如堆內(nèi)存達(dá)到一定值）時(shí)查看當(dāng)前堆上哪些對(duì)象已經(jīng)不再使用，并且將這些沒(méi)有再使用到的對(duì)象所占據(jù)的空間釋放出來(lái)。許多的現(xiàn)代高級(jí)語(yǔ)言都實(shí)現(xiàn)了這一機(jī)制，來(lái)減輕程序員的心智負(fù)擔(dān)。

本書(shū)首發(fā)在 Github，倉(cāng)庫(kù)地址：https://github.com/aliyun-node/Node.js-Troubleshooting-Guide，云棲社區(qū)會(huì)同步更新。

GC 帶來(lái)的問(wèn)題

雖然上面介紹中現(xiàn)代語(yǔ)言的 GC 機(jī)制解放了程序員間接提升了開(kāi)發(fā)效率，但是萬(wàn)事萬(wàn)物都存在利弊，底層的引擎引入 GC 后程序員無(wú)需再關(guān)注對(duì)象何時(shí)釋放的問(wèn)題，那么相對(duì)來(lái)說(shuō)程序員也就沒(méi)辦法實(shí)現(xiàn)對(duì)自己編寫(xiě)的程序的精準(zhǔn)控制，它帶來(lái)兩大問(wèn)題：

• 代碼編寫(xiě)問(wèn)題引發(fā)的內(nèi)存泄漏
• 程序執(zhí)行的性能降低

內(nèi)存泄漏問(wèn)題我們已經(jīng)在上一節(jié)的生產(chǎn)案例中體驗(yàn)了一下，那么后者是怎么回事呢？

其實(shí)理解起來(lái)也很簡(jiǎn)單：原本一個(gè)程序全部的工作都是執(zhí)行業(yè)務(wù)邏輯，但是存在了 GC 機(jī)制后，程序總會(huì)在一定的條件下耗費(fèi)時(shí)間在掃描堆空間找出不再使用的對(duì)象上，這樣就變相降低了程序執(zhí)行業(yè)務(wù)邏輯的時(shí)間，從而造成了性能的下降，而且降低的性能和耗費(fèi)在 GC 上的時(shí)間，換言之即 GC 的次數(shù) * 每次 GC 耗費(fèi)的時(shí)間成正比。

問(wèn)題現(xiàn)象與原始分析

現(xiàn)在大家應(yīng)該對(duì) GC 有了一個(gè)比較整體的了解，這里我們可以看下 GC 引發(fā)的問(wèn)題在生產(chǎn)中的表現(xiàn)是什么樣的。在這個(gè)案例中，表象首先是?Node.js 性能平臺(tái)?上監(jiān)控到進(jìn)程的?CPU 達(dá)到 100%，但是此時(shí)服務(wù)器負(fù)載其實(shí)并不大，QPS 只有 100 上下，我們按照前面提到的處理 CPU 問(wèn)題的步驟抓取 CPU Profile 進(jìn)行分析可以看到：

這次的問(wèn)題顯然是 Garbage Collector 耗費(fèi)的 CPU 太多了，也就是 GC 的問(wèn)題。實(shí)際上絕大部分的 GC 機(jī)制引發(fā)的問(wèn)題往往表象都是反映在 Node.js 進(jìn)程的 CPU 上，而本質(zhì)上這類問(wèn)題可以認(rèn)為是引擎的 GC 引起的問(wèn)題，也可以理解為內(nèi)存問(wèn)題，我們看下這類問(wèn)題的產(chǎn)生流程：

• 堆內(nèi)存不斷達(dá)到觸發(fā) GC 動(dòng)作的預(yù)設(shè)條件
• 進(jìn)程不斷觸發(fā) GC 操作
• 進(jìn)程 CPU 飆高

而且 GC 問(wèn)題不像之前的 ejs 模板渲染引發(fā)的問(wèn)題，就算我們?cè)?CPU Profile 中可以看到這部分的耗費(fèi)，但是想要優(yōu)化解決這個(gè)問(wèn)題基本是無(wú)從下手的，幸運(yùn)的是 Node.js 提供了（其實(shí)是 V8 引擎提供的）一系列的啟動(dòng) Flag 能夠輸出進(jìn)程觸發(fā) GC 動(dòng)作時(shí)的相關(guān)日志以供開(kāi)發(fā)者進(jìn)行分析：

• --trace_gc:?一行日志簡(jiǎn)要描述每次 GC 時(shí)的時(shí)間、類型、堆大小變化和產(chǎn)生原因
• --trace_gc_verbose:?結(jié)合 --trace_gc 一起開(kāi)啟的話會(huì)展示每次 GC 后每個(gè) V8 堆空間的詳細(xì)狀況
• --trace_gc_nvp:?每一次 GC 的一些詳細(xì)鍵值對(duì)信息，包含 GC 類型，暫停時(shí)間，內(nèi)存變化等信息

加粗的 Flag 意味著我們需要在啟動(dòng)應(yīng)用前加上才能在運(yùn)行時(shí)生效，這部分的日志實(shí)際上是一個(gè)文本格式，可惜的是 Chrome devtools 原生并不支持 GC 日志的解析和結(jié)果展示，因此需要大家獲取到以后進(jìn)行對(duì)應(yīng)的按行解析處理，當(dāng)然我們也可以使用社區(qū)提供?v8-gc-log-parser?這個(gè)模塊直接進(jìn)行解析處理，對(duì)這一塊有興趣的同學(xué)可以看?@joyeeCheung?在 JS Interactive 的分享:?Are Your V8 Garbage Collection Logs Speaking To You?，這里不詳細(xì)展開(kāi)。

更好的 GC 日志展示

雖然 Chrome devtools 并不能直接幫助我們解析展示 GC 日志的結(jié)果，但是?Node.js 性能平臺(tái)?其實(shí)給大家提供了更方便的動(dòng)態(tài)獲取線上運(yùn)行進(jìn)程的 GC 狀態(tài)信息以及對(duì)應(yīng)的結(jié)果展示，換言之，開(kāi)發(fā)者無(wú)需在運(yùn)行你的 Node.js 應(yīng)用前開(kāi)啟上面提到的那些 Flag 而仍然可以在想要獲取到 GC 信息時(shí)通過(guò)控制臺(tái)拿到 3 分鐘內(nèi)的 GC 數(shù)據(jù)。

對(duì)應(yīng)在這個(gè)案例中，我們可以進(jìn)入平臺(tái)的應(yīng)用實(shí)例詳情頁(yè)面，找到 GC 耗費(fèi)特別大的進(jìn)程，然后點(diǎn)擊?GC Trace?抓取 GC 數(shù)據(jù)：

這里默認(rèn)會(huì)抓取 3 分鐘的對(duì)應(yīng)進(jìn)程的 GC 日志信息，等到結(jié)束后生成的文件會(huì)顯示在?文件?頁(yè)面：

此時(shí)點(diǎn)擊?轉(zhuǎn)儲(chǔ)?即可上傳到云端以供在線分析展示了，如下圖所示：

最后點(diǎn)擊這里的?分析?按鈕，即可看到 AliNode 定制后的 GC 信息分析結(jié)果的展現(xiàn)：

結(jié)果展示中，可以比較方便的看到問(wèn)題進(jìn)程的 GC 具體次數(shù)，GC 類型以及每次 GC? 的耗費(fèi)時(shí)間等信息，方便我們進(jìn)一步的分析定位。比如這次問(wèn)題的 GC Trace 結(jié)果分析圖中，我們可以看到紅圈起來(lái)的幾個(gè)重要信息：

• GC 總暫停時(shí)間高達(dá) 47.8s，大頭是?Scavenge
• 3min 的 GC 追蹤日志里面，總共進(jìn)行了 988 次的?Scavenge?回收
• 每次 Scavenge 耗時(shí)均值在 50 ~ 60ms 之間

從這些解困中我們可以看到此次 GC 案例的問(wèn)題點(diǎn)集中在 Scavenge 回收階段，即新生代的內(nèi)存回收。那么通過(guò)翻閱 V8 的 Scavenge 回收邏輯可以知道，這個(gè)階段觸發(fā)回收的條件是：Semi?space allocation failed。

這樣就可以推測(cè)，我們的應(yīng)用在壓測(cè)期間應(yīng)該是在新生代頻繁生成了大量的小對(duì)象，導(dǎo)致默認(rèn)的 Semi space 總是處于很快被填滿從而觸發(fā) Flip 的狀態(tài)，這才會(huì)出現(xiàn)在 GC 追蹤期間這么多的 Scavenge 回收和對(duì)應(yīng)的 CPU 耗費(fèi)，這樣這個(gè)問(wèn)題就變?yōu)槿绾稳?yōu)化新生代的 GC 來(lái)提升應(yīng)用性能。

優(yōu)化新生代 GC

通過(guò)平臺(tái)提供的 GC 數(shù)據(jù)抓取和結(jié)果分析，我們知道可以去嘗試優(yōu)化新生代的 GC 來(lái)達(dá)到提升應(yīng)用性能的目的，而新生代的空間觸發(fā) GC 的條件又是其空間被占滿，那么新生代的空間大小由 Flag?--max-semi-space-size?控制，默認(rèn)為 16MB，因此我們自然可以想到要可以通過(guò)調(diào)整默認(rèn)的 Semi space 的值來(lái)進(jìn)行優(yōu)化。

這里需要注意的是，控制新生代空間的 Flag 在不同的 Node.js 版本下并不是一樣的，大家具體可以查看當(dāng)前的版本來(lái)進(jìn)行確認(rèn)使用。

在這個(gè)案例中，顯然是默認(rèn)的 16M 相對(duì)當(dāng)前的應(yīng)用來(lái)說(shuō)顯得比較小，導(dǎo)致 Scavenge 過(guò)于頻繁，我們首先嘗試通過(guò)啟動(dòng)時(shí)增加 --max-semi-space-size=64 這個(gè) Flag 來(lái)將默認(rèn)的新生代使用到的空間大小從 16M 的值增大為 64M，并且在流量比較大而且進(jìn)程 CPU 很高時(shí)抓取 CPU Profile 觀察效果：

調(diào)整后可以看到?Garbage collector?階段 CPU 耗費(fèi)占比下降到 7% 左右，再抓取 GC Trace 并觀察其展示結(jié)果確認(rèn)是不是 Scavenge 階段的耗費(fèi)下降了：

顯然，Semi space 調(diào)大為 64M 后，Scavenge 次數(shù)從近 1000 次降低到 294 次，但是這種狀況下每次的 Scavenge 回收耗時(shí)沒(méi)有明顯增加，還是在 50 ~ 60ms 之間波動(dòng)，因此 3 分鐘的 GC 追蹤總的停頓時(shí)間從 48s 下降到 12s，相對(duì)應(yīng)的，業(yè)務(wù)的 QPS 提升了約 10%?左右。

那么如果我們通過(guò) --max-semi-space-size 這個(gè) Flag 來(lái)繼續(xù)調(diào)大新生代使用到的空間，是不是可以進(jìn)一步優(yōu)化這個(gè)應(yīng)用的性能呢？此時(shí)嘗試?--max-semi-space-size=128 來(lái)從 64M 調(diào)大到 128M，在進(jìn)程 CPU 很高時(shí)繼續(xù)抓取 CPU Profile 來(lái)查看效果：

此時(shí)?Garbage collector?耗費(fèi)下降相比上面的設(shè)置為 64M 并不是很明顯，GC 耗費(fèi)下降占比不到 1%，同樣我們來(lái)抓取并觀察下 GC Trace 的結(jié)果來(lái)查看具體的原因：

很明顯，造成相比設(shè)置為 64M 時(shí) GC 占比提升不大的原因是：雖然此時(shí)進(jìn)一步調(diào)大了 Semi space 至 128M，并且 Scavenge 回收的次數(shù)確實(shí)從 294 次下降到 145 次，但是每次算法回收耗時(shí)近乎翻倍了，因此總收益并不明顯。

按照這個(gè)思路，我們?cè)偈褂?--max-semi-space-size=256 來(lái)將新生代使用的空間進(jìn)一步增大到 256M 再來(lái)進(jìn)行最后一次的觀察：

這里和調(diào)整為 128M 時(shí)是類似的情況： 3 分鐘內(nèi) Scavenge 次數(shù)從 294 次下降到 72 次，但是相對(duì)的每次算法回收耗時(shí)波動(dòng)到了 150ms 左右，因此整體性能并沒(méi)有顯著提升。

借助于性能平臺(tái)的 GC 數(shù)據(jù)抓取和結(jié)果展示，通過(guò)以上的幾次嘗試改進(jìn) Semi space 的值后，我們可以看到從默認(rèn)的 16M 設(shè)置到 64M 時(shí)，Node 應(yīng)用的整體 GC 性能是有顯著提升的，并且反映到壓測(cè) QPS 上大約提升了 10%；但是進(jìn)一步將 Semi space 增大到 128M 和 256M 時(shí)，收益確并不明顯，而且 Semi space 本身也是作用于新生代對(duì)象快速內(nèi)存分配，本身不宜設(shè)置的過(guò)大，因此這次優(yōu)化最終選取對(duì)此項(xiàng)目?最優(yōu)的運(yùn)行時(shí) Semi space 的值為 64M。

結(jié)尾

在本生產(chǎn)案例中，我們首先可以看到，項(xiàng)目使用的三方庫(kù)其實(shí)也并不總是在所有場(chǎng)景下都不會(huì)有 Bug 的（實(shí)際上這是不可能的），因此在遇到三方庫(kù)的問(wèn)題時(shí)我們要敢于去從源碼的層面來(lái)對(duì)問(wèn)題進(jìn)行深入的分析。

最后實(shí)際上在生產(chǎn)環(huán)境下通過(guò) GC 方面的運(yùn)行時(shí)調(diào)優(yōu)來(lái)提升我們的項(xiàng)目性能是一種大家不那么常用的方式，這也有很大一部分原因是應(yīng)用運(yùn)行時(shí) GC 狀態(tài)本身不直接暴露給開(kāi)發(fā)者。通過(guò)上面這個(gè)客戶案例，我們可以看到借助于?Node.js 性能平臺(tái)，實(shí)時(shí)感知 Node 應(yīng)用 GC 狀態(tài)以及進(jìn)行對(duì)應(yīng)的優(yōu)化，使得不改一行代碼提升項(xiàng)目性能變成了一件非常容易的事情。

原文鏈接
本文為云棲社區(qū)原創(chuàng)內(nèi)容，未經(jīng)允許不得轉(zhuǎn)載。

總結(jié)

以上是生活随笔為你收集整理的Node.js 应用故障排查手册 —— 综合性 GC 问题和优化的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。