CPU時間都去哪了：一步步定位數據庫代碼中的性能瓶頸
前言
最近接到技術支持部門的求助，說是有個客戶在測試我司數據庫某個版本的過程中發現明顯的性能問題，希望我們能夠幫忙盡快找到原因，并提供解決方案。經過調查研究，最終確定是由CPU cache line “false sharing” 引起的問題。
鑒于網上類似的文章較少，并且這種問題往往在代碼中比較隱蔽，較難輕易發現，所以在這里做個分享。如果碰巧對其他做類似工作的人有所啟發，本人將非常高興。
背景介紹
這個客戶多年來一直使用我司的數據庫，目前打算升級到更高版本，但在對數據壓縮功能的測試中發現，在某種情況下，在壓縮過的數據表上做全表掃描(table scan)所花費的時間會隨著并發的全表掃描任務數的增多而顯著增加，而未經壓縮過的數據表則沒有這種現象。
數據壓縮是我們團隊多年前開發的一個功能，之前做過大量的代碼優化，性能相對比較穩定，實在不應該會有這樣的問題，這也因此引起了我極大的興趣。
了解數據庫的人都知道，影響數據庫的性能的因素較多，比如服務器的硬件配置，數據庫的參數設置，數據的磁盤分布等，當然，也不排除數據庫自身代碼的問題，不太容易一下定位到具體的原因。一般情況下，如果能通過數據庫調優解決問題，就沒必要花費大量時間去調查數據庫源代碼，所以，在整個問題的調查研究過程中，我的原則是，先易后難，大膽猜想，逐項排除。
調查思路
客戶屬于金融行業，對數據安全有嚴格的規定，根本不可能讓我訪問他們的數據庫系統去做分析，唯一的方法就是，先本地重現問題，然后調試。本地重現是個消耗體力和想象力的過程，索性經過很多次的溝通和嘗試，終于重現了類似的現象。
1)數據庫使用問題 vs 數據庫代碼問題
在一開始確定這個問題是非常必要的，它將決定接下來所花費的時間和精力的大小。
跟客戶做了些溝通，發現他們對數據庫沒有比較深入的了解，所以，首先懷疑的是，有沒有可能他們的數據庫系統中的某些配置參數設置不合理，從而影響性能呢?
很快拿到了客戶的數據庫配置文件，逐一分析，并結合本地實驗，發現并無明顯的問題，唯一的一個問題是，某個跟數據壓縮統計信息相關的配置參數打開了，這個參數主要是在分析問題的時候使用的，生產環境是不建議打開的，立即關閉了這個配置參數，在本地環境中重新測試了一下，發現性能有些改善。
立即建議客戶也做同樣的嘗試，很快得到反饋，性能有所提升，但還未達到他們的預期。
看樣子事情沒那么簡單，接下來開始傾向于認為，可能數據庫代碼哪里出了問題。
2)鎖競爭 (lock contention)
在支持高并發的數據庫系統中，為了同步不同任務對一些關鍵資源的訪問，使用鎖是一種常見的方式，如spinlock，mutex等，但是，一旦發生嚴重的鎖競爭，將會極大影響數據庫系統的性能。雖然近些年lockless的呼聲很高，但是一個數據庫系統要完全做到lockless還是較難的，一般的策略是，對某些關鍵的，容易引起競爭的結構或者模塊采用lockless的方式。所以，檢查鎖競爭是下一步的重點。
我司的這款數據庫雖然全球市場份額不大，但也是深耕該行業的老品牌，在國外的金融領域有口皆碑，在無數次市場檢驗的過程中，為了更好地分析各種問題，工程師們在系統中加入了關鍵信息的統計功能。
通過分析一些系統關鍵資源的統計信息，并未發現明顯的鎖競爭，或者資源競爭，尤其是跟數據壓縮相關的，所以，這個可能的原因排除掉。
3)CPU cache相關的問題
前兩個可能都排除了，現在需要重新審視下客戶的環境，尋找下一個可能的方向。
客戶的數據庫服務器有著不錯的硬件配置，CPU core夠多，內存夠大，數據庫中也配置了幾十個引擎(engine)，可以充分利用多CPU core提升并行任務的執行能力。
此數據庫服務器是典型的NUMA(Non-Uniform Memory Access)架構，一個系統有多個CPU，每個CPU里面有多個core，每個CPU core有獨享的L1和L2 cache，同一個CPU 的cores共享L3 cache(Last Level Cache，LLC)。 cache的訪問延遲比主存要小很多，越靠近CPU，訪問延遲越小，處理器會根據不同的策略(Inclusive Policy，Exclusive Policy等)把數據緩存在不同級別的cache中，從而加快CPU訪問數據的速度，因為根據“數據局部性原理”，目前訪問的數據或者其相鄰數據很有可能在不久的將來會再次訪問到。
同時，cache的容量大小也比主存要小很多(如Interl處理器中的L1 data cache 大小為32k)，如何優化代碼使之有效利用cache提升系統性能一直一來都是個是熱門的話題，也是本問題接下來重點關注的一個方向。
收集線索
Linux系統自帶的perf工具是性能分析利器，熟悉系統性能分析的應該都不會陌生。接下來將介紹如何使用這個工具一步步分析問題，并最終找到原因，我的主要的思路是，由大到小，由面到點，關注熱點。
“perf stat“能夠收集采樣周期內關于某些事件(event)的統計信息并顯示出來，通過這些信息可以大致了解程序的運行狀況。這里重點關注的是CPU和data cache，當然，也可以根據個人需要指定其它事件進行監測。
- 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
輸出里的一些數據比較有意思，需要重點關注的是，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“ 收集性能數據，并用“perf report“顯示，
- perf record -p 29261 -g sleep 50
- perf report > perf_record.out
通過查看各個函數消耗CPU時間的情況，發現占比***的前兩個“熱點“函數如下 (鑒于知識產權的原因，對函數名進行了一些修改，請勿對號入座)，
- 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
很明顯，這是兩個解壓縮數據的函數，由于全表掃描需要解壓縮所有數據行，檢查每一行是否符合查詢條件，所以解壓縮的函數消耗大量CPU時間也合情合理，但是消耗的CPU時間的占比確實有點高(這里先打個問號)。
接下來使用“perf annotate“查看指定函數內代碼行的CPU資源消耗情況，
- perf annotate --symbol=decompress_xxx_by_yyy
有一條指令消耗了67.04%的CPU資源，(另一個熱點函數也是類似的情況)，非常可疑，
- 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
通過解析匯編指令和源代碼比對，找到了這條可疑指令對應的源代碼(由于知識產權的原因，對變量名進行了一些修改，請勿對號入座)，
- new_index = decompressinfo->xxx_arrayC[decmpressinfo->xxx_arrayB[index]]
那條消耗CPU最多的匯編指令對應的源代碼操作是，
- xxx_arrayC[temp_index]
看到這些，你可能會有諸多疑問，
- 這個decompressinfo是什么，有什么特別之處?
- 為什么如此簡單的一行代碼卻消耗了了大量的CPU時間?
- 為什么如此簡單的“數組“元素訪問也成了問題?
分析原因
為了更好地說明問題，下面給出decompressinfo對應的數據結構，并稍微解釋下與之相關的背景知識。
- typedef struct xxx
- {
- /* Arrays of different types */
- TYPEA *arrayA;
- TYPEB *arrayB;
- TYPEC *arrayC;
- TYPED *arrayD;
- /* Other variables */
- short v1;
- short v2;
- int v3;
- .................
- } XXX;
- 該結構體大小是48字節(僅列出了部分結構體成員，已經足夠幫助說明問題，請勿較真)。
- 該結構體存放的是解壓縮數據需要的信息，這些信息在全表掃描過程中不會改變。
- 該結構體的內存來自于數據庫內部的一個memory pool，解壓縮的時候也會從這里分配內存，用于臨時存放解壓縮后的數據。
- 在構造decompressinfo的時候，首先會分配一塊足夠大小的連續內存，內存的前48個字節用來存放其結構體成員，然后，幾個成員指針分別指向剩余連續內存的不同位置(具體位置取決于每個成員指針指向的“數組“的大小)。在本例中，其內存布局如下，
雖然了解了這些信息，還是感覺似乎一切看起來都很正常，并無明顯不妥。
這里還需要再稍微提一下介于CPU和主存之間的cache，CPU訪問某個虛擬內存地址處的數據時，會先嘗試cache，如果未***，便會把數據從主存加載到cache。從虛擬內存地址到cache的映射有多種策略，如direct mapped，set associative，fully associative，硬件廠商使用較多的是set associative，這方面網上資料很多，本文不展開此話題。數據加載的最小單位為一個cache line，其大小隨硬件廠商不同有差異，目前使用較多的是64字節。這樣一來，加載到cache中的數據大小可能會大于實際訪問的數據，造成的結果是，如果兩個并行任務工作在連續內存上的相鄰區域，它們私有的數據可能會被加載到同一個cache line，雖然它們并無數據共享，這個現象叫做共享cache line。
結合上述知識，讓我們把decompressinfo放到更大的內存空間，問題就變得稍微清楚些了，
簡單來講有如下幾點：
- decompressinfo所在內存塊的開始地址和結束地址未必正好在一個cache line的起始處。
- arrayC距離整塊內存的結束地址17字節，有較大可能跟后續連續的內存地址共享cache line。
- 如果后續連續的內存分配給了一個執行大量寫操作的任務，每次寫操作將會引起該cache line 在其它CPU core的copy失效，其它CPU core在下次讀取該cache line的時候需要重新加載。這個現象稱為cache line的“false sharing”，對并發任務的性能有較大影響。
驗證結果
所有疑問似乎都有了合理的解釋，不過目前這都還只是猜想，需要實踐來檢驗。
立即優化了相關代碼，調整了decompressinfo使用的內存塊地址，使其cache line對齊，避免跟其它任務共享cache line。
在本地環境測試后，之前的問題基本消失，部分測試結果如下，
優化前
- ------------------------------------------------------------------------------
- | 并發數 | CPU 時間（ms） |
- ------------------------------------------------------------------------------
- 1 49475
- 2 111005 129663
- 5 165716 165751 173644 174187 197538
- 10 198619 203565 205815 206421 207255 215240 216244 218213 220795 242982
優化后
- ------------------------------------------------------------------------------
- | 并發數 | 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“，發現之前的問題行消耗的CPU已經大幅降低，
- 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”，之前的兩個熱點函數消耗的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”，也有不少有意思的發現，
- stalled CPU cycles大幅減少，說明CPU得到了有效利用。
- L1-dcache-loads大幅增加，說明更多數據從延遲較低的L1 cache讀取。
- LLC-loads大幅減少，說明更少數據從延遲相對較高的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
結束語
系統性能優化是個非常有挑戰性的工作，是對一個人的全面考驗，包括合適工具的使用，代碼的熟悉程度，分析問題的能力，知識的廣度，還有豐富的想象力，但同時也是個非常有意思的經歷，你將深刻認識到細節的重要性，親身感受到小小優化帶來的大幅性能提升。編輯于 2019-03-15
