摘要：本文是關(guān)于我如何應(yīng)用基本性能分析技術(shù)，借助火焰圖做了一處小改進(jìn)，使得我們計(jì)算機(jī)集群的狀況獲得了倍的改善，并在第二年幫助節(jié)省了幾百萬(wàn)刀。最終，通過(guò)對(duì)平均大小在的事件進(jìn)行批量插入，我們的吞吐量獲得了的提高。

本文是關(guān)于我如何應(yīng)用基本性能分析技術(shù)，借助火焰圖做了一處小改進(jìn)，使得我們 Postgres 計(jì)算機(jī)集群的 CPU 狀況獲得了 10 倍的改善，并在第二年幫助 Heap 節(jié)省了幾百萬(wàn)刀。

針對(duì)用戶分析的索引數(shù)據(jù)

Heap 是一個(gè)用戶分析工具，它自動(dòng)捕捉每個(gè)用戶與網(wǎng)站或應(yīng)用進(jìn)行的交互行為。成功安裝于網(wǎng)站后，Heap 會(huì)自動(dòng)追蹤每個(gè)頁(yè)面的瀏覽量、點(diǎn)擊量、表單提交等信息。這樣每個(gè)網(wǎng)站擁有者可以針對(duì)不同子集的原始數(shù)據(jù)，使用 Heap 來(lái)執(zhí)行不同種類的聚合。

為了能夠?qū)o(wú)意義的原始數(shù)據(jù)有所洞見(jiàn)，Heap 能讓用戶根據(jù)原始數(shù)據(jù)自定義事件?！暗顷憽本褪且粋€(gè)例子，可以定義為“在 /login 頁(yè)面進(jìn)行表單提交”。

為了加快分析速度，我們用了一個(gè)非常規(guī)的索引策略，它基于 Postgres 的部分索引特性。部分索引就像一個(gè)普通的 Postgres 索引，不同點(diǎn)在于它只包含了滿足特定謂詞 (predicate) 的行，你可以把它想象成帶有 WHERE 條件的常規(guī)索引。針對(duì)每個(gè)用戶創(chuàng)建的事件定義，我們根據(jù)用戶的原始事件數(shù)據(jù)，創(chuàng)造了一個(gè)部分索引，并將其綁定在滿足定義的行上。每當(dāng)我們的 events 表格中插入一條新行，Postgres 會(huì)自動(dòng)將它與表內(nèi)現(xiàn)存的每條部分索引的謂詞進(jìn)行測(cè)試，并將其加入匹配的索引中。

針對(duì)每個(gè)事件定義，對(duì)應(yīng)的部分索引能讓它快速獲得所有的匹配事件，因?yàn)樗饕∏“藵M足定義的事件。你應(yīng)該閱讀我們這篇關(guān)于如何索引數(shù)據(jù)的博客，它更加深入地介紹了部分索引的相關(guān)內(nèi)容。

問(wèn)題初顯：異常的高 CPU 占用率

當(dāng)我們第一次運(yùn)用這條索引策略時(shí)，對(duì)比之前的策略，我們的 CPU 占用率有了大幅上升。我們認(rèn)為這是正常的現(xiàn)象，因?yàn)槲覀冚^大的客戶有著成千上萬(wàn)條索引，而為了支持基于 CSS 選擇器的過(guò)濾器，大部分的部分索引都包含了一個(gè)正則表達(dá)式過(guò)濾器。我們認(rèn)為由于正則表達(dá)式的求值極其耗時(shí)耗力，而每個(gè)插入的事件都要經(jīng)過(guò)上千條正則表達(dá)式的測(cè)試，這就成了高 CPU 占用率的合理解釋。盡管沒(méi)有明顯的證據(jù)表明這就是原因，但每個(gè)使用 Heap 的人都慢慢將它當(dāng)作了 CPU 占用率過(guò)高的合理解釋。它被看作是新索引策略帶來(lái)的根本妥協(xié)。

十月左右，隨著數(shù)據(jù)量的持續(xù)增長(zhǎng)，問(wèn)題開(kāi)始出現(xiàn)：高峰時(shí)間無(wú)法消化所有信息。有時(shí)候新事件需要花費(fèi)數(shù)小時(shí)才能顯示在 Heap 儀表板上，而這對(duì)一個(gè)實(shí)時(shí)分析工具而言完全不可理喻。拋開(kāi)通過(guò)花錢解決問(wèn)題的常規(guī)路線，我想動(dòng)手嘗試優(yōu)化 Heap 的信息吞吐量問(wèn)題。

用火焰圖對(duì) CPU 占用情況可視化

此前我鮮有調(diào)試此類性能問(wèn)題的經(jīng)驗(yàn)。在搜索了一陣后，我看到了大牛 Brendan Gregg 寫的一篇關(guān)于火焰圖的文章?；鹧鎴D是 Brendan Gregg 發(fā)明的一種可視化方法，用于快速查看哪些部分正在占用 CPU。創(chuàng)建火焰圖的第一步是使用 Linux perf 工具從進(jìn)程堆棧中取樣：

perf record -p $(pid of process) -F 99 -g -- sleep 60

它會(huì)對(duì)指定的進(jìn)程堆棧以每秒 99 次的速度，進(jìn)行持續(xù)一分鐘的取樣，并將數(shù)據(jù)寫入 perf.data 數(shù)據(jù)文件中。這樣，你就可以從 Brendan Gregg 的火焰圖數(shù)據(jù)庫(kù)中運(yùn)行以下命令，對(duì)文件進(jìn)行分析并生成火焰圖：

perf script | ./stackcollapse-perf.pl > out.perf-folded ./flamegraph.pl out.perf-folded > flame-graph.svg

我最初創(chuàng)建的火焰圖之一是 Postgres 的后端進(jìn)程。因?yàn)槲覀兪褂昧诉B接池，一個(gè)簡(jiǎn)單的后端進(jìn)程要服務(wù)多項(xiàng)請(qǐng)求。由于我們運(yùn)行的最多的請(qǐng)求是 INSERTs，Postgres 后端進(jìn)程的火焰圖能夠讓我們清楚地看到，事件插入數(shù)據(jù)庫(kù)時(shí)的 CPU 占用情況。在 pid 中對(duì)來(lái)自 pg_stat_activity 的 Postgres 進(jìn)程運(yùn)行以上命令后，我獲得了下面這張火焰圖：

對(duì)于新手而言，火焰圖可能非常難以理解。Brendan Gregg 給出以下解釋幫助我們理解一張火焰圖：

X 軸顯示堆棧剖面群體，以字母順序排序（而不是時(shí)間的流逝），Y 軸顯示堆棧深度。每個(gè)方塊框代表了一個(gè)堆棧幀。幀越寬，代表了它在堆棧中出現(xiàn)的頻率越高。頂端顯示了 CPU 正在運(yùn)行的進(jìn)程，下面是歷史進(jìn)程。顏色通常而言并不重要，它們是隨機(jī)分配的，用來(lái)區(qū)分不同的框架。

從火焰圖中可以清楚地看到，大約 55% 的 CPU 時(shí)間花在了 ExecOpenIndices 上（圖中行右側(cè)區(qū)域的大黃色條）。視線上移一點(diǎn)，可以看到大部分的時(shí)間被兩個(gè)不同的功能所消耗，它們是 BuildIndexInfo 和 index_open。BuildIndexInfo 調(diào)用了 RelationGetIndexPredicate，而后者花費(fèi)了 ~20% 的總 CPU 時(shí)間。這樣來(lái)看，大部分時(shí)間都花在了 RelationGetIndexPredicate 上。

仔細(xì)查看 RelationGetIndexPredicate 的源代碼，它的作用是解析和優(yōu)化部分索引謂詞。這就解釋了為什么 RelationGetIndexPredicate 耗費(fèi)了如此大量的時(shí)間，因?yàn)橄啾葘?duì)已解析表達(dá)式進(jìn)行求值，解析二進(jìn)制表達(dá)式要更加困難。

現(xiàn)在我們?cè)倏纯词Ｏ禄ㄔ?ExecOpenIndices 上的時(shí)間。其中大部分剩余時(shí)間花在了 index_open 上?？瓷先?index_open 先調(diào)用了 relation_open，后者又調(diào)用了 RelationIdGetRelation。從 RelationIdGetRelation 的源代碼文件中，可以看到它的作用是查找不同關(guān)系的元數(shù)據(jù)（本次問(wèn)題中它主要用于查找部分索引）。根據(jù) RelationGetIndexPredicate 和 RelationIdGetRelation 消耗的時(shí)間，看起來(lái) Postgres 花費(fèi)了更多的時(shí)間用于獲取和解析部分索引謂詞，而不是對(duì)其求值。

實(shí)施修復(fù)

看了不同函數(shù)的源代碼，可以發(fā)現(xiàn)存在著大量的緩存。在 RelationGetIndexPredicate中，Postfres 先檢測(cè)是否已抽取謂詞并立即返回它。

RelationIdGetRelation 先使用 RelationIdCacheLookup 來(lái)檢查關(guān)系源數(shù)據(jù)是否已經(jīng)過(guò)計(jì)算并緩存。通常情況下，索引元數(shù)據(jù)只需要經(jīng)歷一次獲取和解析，剩下的時(shí)間都是從緩存中讀取。

不幸的是，因?yàn)槲覀兠看螌⒁粋€(gè)事件寫入數(shù)以萬(wàn)計(jì)的不同表格，緩存出了問(wèn)題。Postgres 有一個(gè)服務(wù)請(qǐng)求的進(jìn)程池，并且每個(gè)進(jìn)程都有多帶帶的緩存。這些進(jìn)程對(duì)每次插入都分配了輪詢 (round-robin)。由于共享的模式中現(xiàn)存上萬(wàn)張基礎(chǔ)表格，每次插入事件時(shí)，很有可能將兩次事件插入同一進(jìn)程的同一張表中，也就是說(shuō)索引元數(shù)據(jù)幾乎無(wú)法在執(zhí)行插入時(shí)進(jìn)行緩存。因此，Postgres 幾乎每次都需要在插入事件時(shí)，獲取并解析目的表格的索引元數(shù)據(jù)。

根據(jù)這一點(diǎn)，我們可以做一個(gè)簡(jiǎn)單的改進(jìn)：與其將每個(gè)事件多帶帶插入表格，我們可以對(duì)需要插入相同表格的事件進(jìn)行一次批量插入。通過(guò)運(yùn)行一個(gè)簡(jiǎn)單的命令來(lái)批量插入事件，Postgres 就只需要在每次批處理時(shí)獲取和解析索引元數(shù)據(jù)。我們之前本想進(jìn)行批量插入以減少執(zhí)行計(jì)數(shù)，但不是出于節(jié)省 CPU 資源的目的，因?yàn)槲覀兗僭O(shè)所有的 CPU 都要用于對(duì)索引謂詞求值。

批量插入的初始基準(zhǔn)顯示 CPU 占用率得到了 10x 的縮減。得知了這一結(jié)果，我們開(kāi)始在生產(chǎn)中測(cè)試批量插入。最終，通過(guò)對(duì)平均大小在 ~50 的事件進(jìn)行批量插入，我們的吞吐量獲得了 10x 的提高。這是對(duì)不同 Kafka 部分的吞吐量傳輸延遲時(shí)間，進(jìn)行批處理前后的對(duì)比：左邊的單位是延遲時(shí)間 (latency time)。我們能夠在幾分鐘內(nèi)清理完一個(gè)小時(shí)的積壓 (backlog)。

在實(shí)行批處理后，我又生成了一張插入事件的火焰圖：

這一次圖上顯示大部分的時(shí)間都?xì)w于 ExecQual（中間的紅條），而根據(jù)源碼，而它是作用是對(duì)部分索引謂詞進(jìn)行求值，也就是說(shuō)這一次 Postgres 將大量的 CPU 用在了正途上。

我在半年前發(fā)現(xiàn)了這個(gè)問(wèn)題。自此，我們不需要給集群增加額外的 CPU，而且看起來(lái)以后的幾個(gè)月也不用這樣做。我只是運(yùn)用了基本的性能分析就有如此成效，沒(méi)花什么力氣就獲得了 10 倍的收益。