CPU時間都去哪了:一步步定位數(shù)據(jù)庫代碼中的性能瓶頸
前言
最近接到技術(shù)支持部門的求助,說是有個客戶在測試我司數(shù)據(jù)庫某個版本的過程中發(fā)現(xiàn)明顯的性能問題,希望我們能夠幫忙盡快找到原因,并提供解決方案。經(jīng)過調(diào)查研究,最終確定是由CPU cache line “false sharing” 引起的問題。
鑒于網(wǎng)上類似的文章較少,并且這種問題往往在代碼中比較隱蔽,較難輕易發(fā)現(xiàn),所以在這里做個分享。如果碰巧對其他做類似工作的人有所啟發(fā),本人將非常高興。
背景介紹
這個客戶多年來一直使用我司的數(shù)據(jù)庫,目前打算升級到更高版本,但在對數(shù)據(jù)壓縮功能的測試中發(fā)現(xiàn),在某種情況下,在壓縮過的數(shù)據(jù)表上做全表掃描(table scan)所花費的時間會隨著并發(fā)的全表掃描任務(wù)數(shù)的增多而顯著增加,而未經(jīng)壓縮過的數(shù)據(jù)表則沒有這種現(xiàn)象。
數(shù)據(jù)壓縮是我們團隊多年前開發(fā)的一個功能,之前做過大量的代碼優(yōu)化,性能相對比較穩(wěn)定,實在不應(yīng)該會有這樣的問題,這也因此引起了我極大的興趣。
了解數(shù)據(jù)庫的人都知道,影響數(shù)據(jù)庫的性能的因素較多,比如服務(wù)器的硬件配置,數(shù)據(jù)庫的參數(shù)設(shè)置,數(shù)據(jù)的磁盤分布等,當(dāng)然,也不排除數(shù)據(jù)庫自身代碼的問題,不太容易一下定位到具體的原因。一般情況下,如果能通過數(shù)據(jù)庫調(diào)優(yōu)解決問題,就沒必要花費大量時間去調(diào)查數(shù)據(jù)庫源代碼,所以,在整個問題的調(diào)查研究過程中,我的原則是,先易后難,大膽猜想,逐項排除。
調(diào)查思路
客戶屬于金融行業(yè),對數(shù)據(jù)安全有嚴(yán)格的規(guī)定,根本不可能讓我訪問他們的數(shù)據(jù)庫系統(tǒng)去做分析,唯一的方法就是,先本地重現(xiàn)問題,然后調(diào)試。本地重現(xiàn)是個消耗體力和想象力的過程,索性經(jīng)過很多次的溝通和嘗試,終于重現(xiàn)了類似的現(xiàn)象。
1)數(shù)據(jù)庫使用問題 vs 數(shù)據(jù)庫代碼問題
在一開始確定這個問題是非常必要的,它將決定接下來所花費的時間和精力的大小。
跟客戶做了些溝通,發(fā)現(xiàn)他們對數(shù)據(jù)庫沒有比較深入的了解,所以,首先懷疑的是,有沒有可能他們的數(shù)據(jù)庫系統(tǒng)中的某些配置參數(shù)設(shè)置不合理,從而影響性能呢?
很快拿到了客戶的數(shù)據(jù)庫配置文件,逐一分析,并結(jié)合本地實驗,發(fā)現(xiàn)并無明顯的問題,唯一的一個問題是,某個跟數(shù)據(jù)壓縮統(tǒng)計信息相關(guān)的配置參數(shù)打開了,這個參數(shù)主要是在分析問題的時候使用的,生產(chǎn)環(huán)境是不建議打開的,立即關(guān)閉了這個配置參數(shù),在本地環(huán)境中重新測試了一下,發(fā)現(xiàn)性能有些改善。
立即建議客戶也做同樣的嘗試,很快得到反饋,性能有所提升,但還未達到他們的預(yù)期。
看樣子事情沒那么簡單,接下來開始傾向于認(rèn)為,可能數(shù)據(jù)庫代碼哪里出了問題。
2)鎖競爭 (lock contention)
在支持高并發(fā)的數(shù)據(jù)庫系統(tǒng)中,為了同步不同任務(wù)對一些關(guān)鍵資源的訪問,使用鎖是一種常見的方式,如spinlock,mutex等,但是,一旦發(fā)生嚴(yán)重的鎖競爭,將會極大影響數(shù)據(jù)庫系統(tǒng)的性能。雖然近些年lockless的呼聲很高,但是一個數(shù)據(jù)庫系統(tǒng)要完全做到lockless還是較難的,一般的策略是,對某些關(guān)鍵的,容易引起競爭的結(jié)構(gòu)或者模塊采用lockless的方式。所以,檢查鎖競爭是下一步的重點。
我司的這款數(shù)據(jù)庫雖然全球市場份額不大,但也是深耕該行業(yè)的老品牌,在國外的金融領(lǐng)域有口皆碑,在無數(shù)次市場檢驗的過程中,為了更好地分析各種問題,工程師們在系統(tǒng)中加入了關(guān)鍵信息的統(tǒng)計功能。
通過分析一些系統(tǒng)關(guān)鍵資源的統(tǒng)計信息,并未發(fā)現(xiàn)明顯的鎖競爭,或者資源競爭,尤其是跟數(shù)據(jù)壓縮相關(guān)的,所以,這個可能的原因排除掉。
3)CPU cache相關(guān)的問題
前兩個可能都排除了,現(xiàn)在需要重新審視下客戶的環(huán)境,尋找下一個可能的方向。
客戶的數(shù)據(jù)庫服務(wù)器有著不錯的硬件配置,CPU core夠多,內(nèi)存夠大,數(shù)據(jù)庫中也配置了幾十個引擎(engine),可以充分利用多CPU core提升并行任務(wù)的執(zhí)行能力。
此數(shù)據(jù)庫服務(wù)器是典型的NUMA(Non-Uniform Memory Access)架構(gòu),一個系統(tǒng)有多個CPU,每個CPU里面有多個core,每個CPU core有獨享的L1和L2 cache,同一個CPU 的cores共享L3 cache(Last Level Cache,LLC)。 cache的訪問延遲比主存要小很多,越靠近CPU,訪問延遲越小,處理器會根據(jù)不同的策略(Inclusive Policy,Exclusive Policy等)把數(shù)據(jù)緩存在不同級別的cache中,從而加快CPU訪問數(shù)據(jù)的速度,因為根據(jù)“數(shù)據(jù)局部性原理”,目前訪問的數(shù)據(jù)或者其相鄰數(shù)據(jù)很有可能在不久的將來會再次訪問到。
同時,cache的容量大小也比主存要小很多(如Interl處理器中的L1 data cache 大小為32k),如何優(yōu)化代碼使之有效利用cache提升系統(tǒng)性能一直一來都是個是熱門的話題,也是本問題接下來重點關(guān)注的一個方向。
收集線索
Linux系統(tǒng)自帶的perf工具是性能分析利器,熟悉系統(tǒng)性能分析的應(yīng)該都不會陌生。接下來將介紹如何使用這個工具一步步分析問題,并最終找到原因,我的主要的思路是,由大到小,由面到點,關(guān)注熱點。
“perf stat“能夠收集采樣周期內(nèi)關(guān)于某些事件(event)的統(tǒng)計信息并顯示出來,通過這些信息可以大致了解程序的運行狀況。這里重點關(guān)注的是CPU和data cache,當(dāng)然,也可以根據(jù)個人需要指定其它事件進行監(jiān)測。
- perf stat -e task-clock -e cycles -e stalled-cycles-frontend -e stalled-cycles-backend -e cache-misses -e L1-dcache-loads -e L1-dcache-load-misses -e L1-dcache-stores -e L1-dcache-store-misses -e L1-dcache-prefetches -e L1-dcache-prefetch-misses -e LLC-loads -e LLC-load-misses -p 29261 sleep 50
輸出里的一些數(shù)據(jù)比較有意思,需要重點關(guān)注的是,stalled CPU cycles超過了80%!
- 247906.038072 task-clock # 4.958 CPUs utilized
- 812171299976 cycles # 3.276 GHz [36.39%]
- 694124548218 stalled-cycles-frontend # 85.47% frontend cycles idle [36.40%]
- 668744885346 stalled-cycles-backend # 82.34% backend cycles idle [36.43%]
- 514323939 cache-misses # 2.075 M/sec [36.44%]
- 89260315424 L1-dcache-loads
- # 360.057 M/sec [36.41%]
- 872622317 L1-dcache-misses
- # 0.98% of all L1-dcache hits [36.39%]
- 35598131563 L1-dcache-stores
- # 143.595 M/sec [36.37%]
- 57219914 L1-dcache-misses
- # 0.231 M/sec [36.35%]
- <not counted> L1-dcache-prefetches
- 216934515 L1-dcache-misses
- # 0.875 M/sec [36.35%]
- 672308105 LLC-loads
- # 2.712 M/sec [36.35%]
- 458916465 LLC-misses
- # 68.26% of all LL-cache hits [36.34%]
接下來運行“perf record“ 收集性能數(shù)據(jù),并用“perf report“顯示,
- perf record -p 29261 -g sleep 50
- perf report > perf_record.out
通過查看各個函數(shù)消耗CPU時間的情況,發(fā)現(xiàn)占比***的前兩個“熱點“函數(shù)如下 (鑒于知識產(chǎn)權(quán)的原因,對函數(shù)名進行了一些修改,請勿對號入座),
- 65.73% s_dataserver s_dataserver [.] decompress__xxx_by_xxx
- |
- --- decompress__xxx_by_xxx
- |
- |--99.88%-- decompress_xxx_by_yyy
- | …
- 21.66% s_dataserver s_dataserver [.] decompress_xxx_by_yyy
很明顯,這是兩個解壓縮數(shù)據(jù)的函數(shù),由于全表掃描需要解壓縮所有數(shù)據(jù)行,檢查每一行是否符合查詢條件,所以解壓縮的函數(shù)消耗大量CPU時間也合情合理,但是消耗的CPU時間的占比確實有點高(這里先打個問號)。
接下來使用“perf annotate“查看指定函數(shù)內(nèi)代碼行的CPU資源消耗情況,
- perf annotate --symbol=decompress_xxx_by_yyy
有一條指令消耗了67.04%的CPU資源,(另一個熱點函數(shù)也是類似的情況),非??梢?,
- 0.21 : db69d1: 49 8b 00 mov (%r8),%rax
- 12.08 : db69d4: 49 0f bf d4 movswq %r12w,%rdx
- 0.05 : db69d8: 48 89 d9 mov %rbx,%rcx
- 0.00 : db69db: 48 0f bf 14 50 movswq (%rax,%rdx,2),%rdx
- 67.04 : db69e0: 49 8b 40 08 mov 0x8(%r8),%rax
- 8.64 : db69e4: 44 0f bf 0c 50 movswl (%rax,%rdx,2),%r9d
- 7.83 : db69e9: 48 8b 87 a8 02 00 00 mov 0x2a8(%rdi),%rax
通過解析匯編指令和源代碼比對,找到了這條可疑指令對應(yīng)的源代碼(由于知識產(chǎn)權(quán)的原因,對變量名進行了一些修改,請勿對號入座),
- new_index = decompressinfo->xxx_arrayC[decmpressinfo->xxx_arrayB[index]]
那條消耗CPU最多的匯編指令對應(yīng)的源代碼操作是,
- xxx_arrayC[temp_index]
看到這些,你可能會有諸多疑問,
- 這個decompressinfo是什么,有什么特別之處?
- 為什么如此簡單的一行代碼卻消耗了了大量的CPU時間?
- 為什么如此簡單的“數(shù)組“元素訪問也成了問題?
分析原因
為了更好地說明問題,下面給出decompressinfo對應(yīng)的數(shù)據(jù)結(jié)構(gòu),并稍微解釋下與之相關(guān)的背景知識。
- typedef struct xxx
- {
- /* Arrays of different types */
- TYPEA *arrayA;
- TYPEB *arrayB;
- TYPEC *arrayC;
- TYPED *arrayD;
- /* Other variables */
- short v1;
- short v2;
- int v3;
- .................
- } XXX;
- 該結(jié)構(gòu)體大小是48字節(jié)(僅列出了部分結(jié)構(gòu)體成員,已經(jīng)足夠幫助說明問題,請勿較真)。
- 該結(jié)構(gòu)體存放的是解壓縮數(shù)據(jù)需要的信息,這些信息在全表掃描過程中不會改變。
- 該結(jié)構(gòu)體的內(nèi)存來自于數(shù)據(jù)庫內(nèi)部的一個memory pool,解壓縮的時候也會從這里分配內(nèi)存,用于臨時存放解壓縮后的數(shù)據(jù)。
- 在構(gòu)造decompressinfo的時候,首先會分配一塊足夠大小的連續(xù)內(nèi)存,內(nèi)存的前48個字節(jié)用來存放其結(jié)構(gòu)體成員,然后,幾個成員指針分別指向剩余連續(xù)內(nèi)存的不同位置(具體位置取決于每個成員指針指向的“數(shù)組“的大小)。在本例中,其內(nèi)存布局如下,
雖然了解了這些信息,還是感覺似乎一切看起來都很正常,并無明顯不妥。
這里還需要再稍微提一下介于CPU和主存之間的cache,CPU訪問某個虛擬內(nèi)存地址處的數(shù)據(jù)時,會先嘗試cache,如果未***,便會把數(shù)據(jù)從主存加載到cache。從虛擬內(nèi)存地址到cache的映射有多種策略,如direct mapped,set associative,fully associative,硬件廠商使用較多的是set associative,這方面網(wǎng)上資料很多,本文不展開此話題。數(shù)據(jù)加載的最小單位為一個cache line,其大小隨硬件廠商不同有差異,目前使用較多的是64字節(jié)。這樣一來,加載到cache中的數(shù)據(jù)大小可能會大于實際訪問的數(shù)據(jù),造成的結(jié)果是,如果兩個并行任務(wù)工作在連續(xù)內(nèi)存上的相鄰區(qū)域,它們私有的數(shù)據(jù)可能會被加載到同一個cache line,雖然它們并無數(shù)據(jù)共享,這個現(xiàn)象叫做共享cache line。
結(jié)合上述知識,讓我們把decompressinfo放到更大的內(nèi)存空間,問題就變得稍微清楚些了,
簡單來講有如下幾點:
- decompressinfo所在內(nèi)存塊的開始地址和結(jié)束地址未必正好在一個cache line的起始處。
- arrayC距離整塊內(nèi)存的結(jié)束地址17字節(jié),有較大可能跟后續(xù)連續(xù)的內(nèi)存地址共享cache line。
- 如果后續(xù)連續(xù)的內(nèi)存分配給了一個執(zhí)行大量寫操作的任務(wù),每次寫操作將會引起該cache line 在其它CPU core的copy失效,其它CPU core在下次讀取該cache line的時候需要重新加載。這個現(xiàn)象稱為cache line的“false sharing”,對并發(fā)任務(wù)的性能有較大影響。
驗證結(jié)果
所有疑問似乎都有了合理的解釋,不過目前這都還只是猜想,需要實踐來檢驗。
立即優(yōu)化了相關(guān)代碼,調(diào)整了decompressinfo使用的內(nèi)存塊地址,使其cache line對齊,避免跟其它任務(wù)共享cache line。
在本地環(huán)境測試后,之前的問題基本消失,部分測試結(jié)果如下,
優(yōu)化前
- ------------------------------------------------------------------------------
- | 并發(fā)數(shù) | CPU 時間(ms) |
- ------------------------------------------------------------------------------
- 1 49475
- 2 111005 129663
- 5 165716 165751 173644 174187 197538
- 10 198619 203565 205815 206421 207255 215240 216244 218213 220795 242982
優(yōu)化后
- ------------------------------------------------------------------------------
- | 并發(fā)數(shù) | CPU 時間(ms) |
- ------------------------------------------------------------------------------
- 1 49872
- 2 50538 50531
- 5 50897 50912 50920 50963 50350
- 10 52581 52028 52752 52758 52399 52546 53494 52302 53056 52527
再次運行“perf annotate“,發(fā)現(xiàn)之前的問題行消耗的CPU已經(jīng)大幅降低,
- 0.07 : e145a4: 49 0f bf d4 movswq %r12w,%rdx ▒
- 0.31 : e145a8: 48 89 d9 mov %rbx,%rcx ▒
- 0.02 : e145ab: 48 0f bf 14 50 movswq (%rax,%rdx,2),%rdx ▒
- 12.19 : e145b0: 49 8b 40 08 mov 0x8(%r8),%rax ▒
- 0.01 : e145b4: 44 0f bf 0c 50 movswl (%rax,%rdx,2),%r9d ▒
- 18.52 : e145b9: 48 8b 87 a8 02 00 00 mov 0x2a8(%rdi),%rax ▒
- 0.00 : e145c0: 4c 89 d7 mov %r10,%rdi ▒
- 0.01 : e145c3: 8b 90 fc 4e 00 00 mov 0x4efc(%rax),%edx
- 0.00 : e145c9: 48 8b 45 28 mov 0x28(%rbp),%rax
再次運行“perf record;perf report”,之前的兩個熱點函數(shù)消耗的CPU也有所下降,
- 56.06% s_dataserver s_dataserver [.] decompress__xxx_by_xxx
- |
- --- decompress__xxx_by_xxx
- |
- |--99.38%-- decompress_xxx_by_yyy
- | …
- 7.69% s_dataserver s_dataserver [.] decompress_xxx_by_yyy
再次運行“perf stat”,也有不少有意思的發(fā)現(xiàn),
- stalled CPU cycles大幅減少,說明CPU得到了有效利用。
- L1-dcache-loads大幅增加,說明更多數(shù)據(jù)從延遲較低的L1 cache讀取。
- LLC-loads大幅減少,說明更少數(shù)據(jù)從延遲相對較高的L3 cache讀取。
- 246476.028262 task-clock # 4.929 CPUs utilized
- 805969061791 cycles # 3.270 GHz [36.37%]
- 177046399865 stalled-cycles-frontend # 21.97% frontend cycles idle [36.42%]
- 97824957888 stalled-cycles-backend # 12.14% backend cycles idle [36.44%]
- 171988020 cache-misses # 0.698 M/sec [36.45%]
- 495575868789 L1-dcache-loads
- # 2010.645 M/sec [36.42%]
- 647748719 L1-dcache-misses
- # 0.13% of all L1-dcache hits [36.38%]
- 192157290531 L1-dcache-stores
- # 779.619 M/sec [36.37%]
- 289881614 L1-dcache-misses
- # 1.176 M/sec [36.36%]
- <not counted> L1-dcache-prefetches
- 862945820 L1-dcache-misses
- # 3.501 M/sec [36.33%]
- 231608715 LLC-loads
- # 0.940 M/sec [36.33%]
- 124342470 LLC-misses
- # 53.69% of all LL-cache hits [36.33%]
- 50.001319609 seconds time elapsed
結(jié)束語
系統(tǒng)性能優(yōu)化是個非常有挑戰(zhàn)性的工作,是對一個人的全面考驗,包括合適工具的使用,代碼的熟悉程度,分析問題的能力,知識的廣度,還有豐富的想象力,但同時也是個非常有意思的經(jīng)歷,你將深刻認(rèn)識到細(xì)節(jié)的重要性,親身感受到小小優(yōu)化帶來的大幅性能提升。編輯于 2019-03-15