用 perf 和 SystemTap 跟蹤 MongoDB 訪問超時

事情的起因是我們為 LeanCloud 結構化存儲後端搭建了一個實驗性質的小集群，使用了 MongoDB 3.0 和 WiredTiger 引擎。該集群在平穩運行了幾個月後的某一天突然開始出現大量不明原因的超時。

按常規套路，我首先懷疑到 io，但是檢查 iostat、dstat 和 iotop 之後便排除了這一可能。況且我們給 MongoDB 用的是 Intel 企業級 SSD，也不太可能在這裡出問題。

再 top 看了一下，CPU 佔用 200% 上下，機器本身是 12 cores / 24 threads，處理這個 load 應該非常輕鬆。內存 64G，mongod 用掉了近一半，剩下一半被 page cache 佔用著，也符合 MongoDB 官方推薦的標準。

然後從 MongoDB 的日誌中發現與慢查詢相關的數字非常奇怪，讀寫鎖的佔用都很小（幾十個us），也正常使用了索引（IXSCAN、IDHACK)，可是最後查詢的完成時間都是幾千 ms 甚至一萬 ms 以上。

CPU、IO、內存都不缺，但是性能就是上不去，那很可能就是單線程瓶頸和鎖的問題了。再次打開 top 按下 H 切換到線程模式，果然看到有一個線程佔用了 100% 的 CPU。

於是下意識地 strace 上去，發現這個線程只調用了一個 syscall：futex。所以，有什麼東西是單線程處理並且還拿著鎖……pstack 一下，只給了一個函數名 __evict_server。再沒有更多的信息了。

1. perf

先讓 perf 來打頭陣。perf top 一下，看看系統內實時的 CPU 消耗（原圖丟了，拿個湊數）：

再選擇 Annotate，找出熱點（可以精確到 CPU 指令）：

對應著源碼

如果你關注的程序有調試符號並且能根據調試符號找到源碼，那麼 perf 會在相關的指令旁邊顯示源碼。

此時能看出大部分的 CPU 都消耗在鏈表遍歷上了。

追鏈表是個非常緩存不友好的行為，另外還能看到有個字元串的解引用也會佔用大量的 CPU，這裡只可能是 cache-miss 了。

perf stat -e cache-references,cache-misses -p <TID> 一下那個線程，發現絕大部分都是 cache-miss。（沒法上圖，忘記保存了）。

關於 CPU cache，有一個非常有意思的頁面，可以感性地認識一下內存相對於緩存有多慢。

通過 perf list 可以看到 perf 具體能統計哪些指標

# 硬體（CPU 中的 Performance Monitor Unit）指標nbranch-instructions # 執行的跳轉指令數nbranch-misses # 分支預測失敗數nbus-cycles # 不知道……（以下用 - 代替）ncache-misses # 緩存未命中ncache-references # 緩存訪問數ncpu-cycles or cycles # CPU 時鐘周期數ninstructions # 執行的指令數nref-cycles # - （跟 bus-cycles 有些亂糟的關係）nstalled-cycles-frontend # CPU 前端等待（前端是指取指/解碼、分支預測、訪存等等東西，後端是指執行指令的過程）nn# 軟體指標nalignment-faults # 對齊錯誤，x86/x64 會自動處理訪存不對齊，所以不用關注nbpf-output # 跟 eBPF 有關，不知道是幹啥的ncontext-switches or cs # 上下文切換數（程序被調度走了）ncpu-clock # CPU 時鐘（這裡是軟體統計的，不如上面的准)ncpu-migrations # CPU 遷移（程序從 CPU1 執行，但是被調度到 CPU2 上去了）ndummy # -nemulation-faults # -nmajor-faults # 主要缺頁錯誤（需要的頁不在內存中，要去磁碟上取出再填進去）nminor-faults # 次要缺頁錯誤（需要的頁在內存中，只是缺頁表項，填上頁表項就好了）npage-faults OR faults # == major-faults + minor-faultsntask-clock # -nn# 硬體指標（Hardware cache event）nL1-dcache-load-misses # L1 數據緩存未命中nL1-dcache-loads # L1 數據緩存訪問數nL1-dcache-prefetch-misses # L1 數據緩存預取未命中nL1-dcache-store-misses # L1 數據緩存RFO未命中（RFO: read-for-ownership，讀取並且失效這個緩存）nL1-dcache-stores # L1 數據緩存RFOnL1-icache-load-misses # L1 指令緩存未命中nLLC-load-misses # LLC: Last Level Cache，即 L2/L3 緩存。nLLC-loads # 這些根據上面的說明看名子應該能知道是什麼nLLC-prefetch-misses # 就不再一個個解釋了nLLC-prefetches #nLLC-store-misses #nLLC-stores #nbranch-load-misses # BPU 緩存未命中（BPU：Branch Processing Unit)nbranch-loads # 與分支預測有關的緩存ndTLB-load-misses # 數據 TLB 緩存未命中（TLB: Translation Lookaside Buffer）ndTLB-loads # TLB 是頁表的緩存，用來加速虛擬地址->物理地址(VA->PA)轉換的ndTLB-store-misses # 同不一個個解釋了……ndTLB-stores #niTLB-load-misses # 指令 TLB 緩存未命中niTLB-loads #nnode-load-misses # 本地訪存未命中，需要跨 NUMA node（其實就是 CPU）訪存 nnode-loads # 訪存數（這裡訪存數跟 LLC miss 對不上號，因為 LLC miss 後可能會跨 core 取到緩存）nnode-prefetch-misses #nnode-prefetches #nnode-store-misses #nnode-stores #n

找到了熱點，下一步就是給 MongoDB 打上補丁，目的主要是優化緩存，修改很小：

1. 將遍歷鏈表能用到的東西都放在一個 cache line 里。

2. 因為字元串的那個解引用僅僅判斷了一個類型（通過與 "file:" 比較），所以將 name 的前 4 個位元組作為一個 uint32 嵌在鏈表中，可以減少一次 cache miss。實際上觀察了一下所有的 item 都是 file 類型。

具體補丁可以看這裡。

2. SystemTap

那麼，打過補丁之後，性能提升了多少？或者說，我想知道每次 __evict_clear_all_walks （__evict_server 調用了這個函數）具體耗費了多上時間？貌似 perf 不太擅長做這個（如果我說的不對還請指出來）。

那麼這時候就可以用 SystemTap 了：

global timesnnprobe process("/usr/bin/mongod").function("__evict_clear_all_walks").return {n times <<< gettimeofday_us() - @entry(gettimeofday_us())n}nnprobe timer.s(1) {n print(@hist_linear(times, 16000, 36000, 500))n}n

直方圖左邊的數字是函數執行的時間，單位是 us，右邊是落在這個區間內的次數。

【打補丁前】

value |-------------------------------------------------- countn16400 |@ 4n16600 |@@@@ 14n16800 |@@@@ 13n17000 | 1n17200 |@ 5n17400 |@@@ 10n17600 |@ 3n17800 |@@@@@@@@ 24n18000 |@@@@@@@@@@@@@@@@@@@@@ 63n18200 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 92n18400 |@@@@@@@@@@@@@@@@@ 53n18600 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 80n18800 |@@@@@@@@ 26n19000 |@@@@@@@@@@@@@ 39n19200 |@@@@@@@@ 24n19400 |@@@@ 12n19600 |@ 3n19800 |@ 5n20000 | 2n20200 |@@ 7n20400 |@@@ 11n20600 |@@@ 9n20800 |@@ 8n21000 |@@@ 11n21200 |@@@@@@@ 21n21400 |@@@@@@@ 22n21600 |@@@@@@@@@@@@@@@@@@@@ 60n21800 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 121n22000 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 131n22200 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 95n22400 |@@@@@@@@@@@@@@@@@@@@ 61n22600 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 81n22800 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 87n23000 |@@@@@@@@@@@@@@@@@@@@@@ 67n23200 |@@@@@@@@@@@@@@@@ 50n23400 |@@@@@ 15n23600 |@ 4n23800 |@ 4n24000 | 2n

【打補丁後】

4900 | 6n 5000 |@@@@@@@ 295n 5100 |@@@@@@@@@@@ 430n 5200 |@ 55n 5300 | 17n 5400 | 25n 5500 | 30n 5600 | 13n 5700 | 16n 5800 | 19n 5900 | 8n 6000 | 9n 6100 | 16n 6200 | 14n 6300 |@ 67n 6400 |@@@@ 175n 6500 |@@@@@@@ 293n 6600 |@@ 109n 6700 |@@ 78n 6800 |@@ 89n 6900 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1864n 7000 |@@@@ 171n 7100 | 29n 7200 | 22n 7300 | 8n

SystemTap 是目前 Linux 最強大的 tracer/profiler，可以跟蹤內核以及用戶態程序中的任意函數、syscall、語句甚至指令，還可以跟蹤 DTrace 的 USDT（寫在代碼中的預定義的 trace point，比如剛才提到的 MongoDB 補丁代碼中的那句 DTRACE_PROBE(proton, dhandle_not_file)。

這裡插播一個腦洞（來源忘掉了）：

如果希望看到 SSL 連接里的數據，通常的方法會比較煩，配證書做中間人什麼的，遇到線上問題也不太可能停機搞，這時可以用 SystemTap hook 住 OpenSSL 的 SSL_READ 和 SSL_WRITE，直接得到 SSL 連接內收發的數據。

4. perf 火焰圖 & SystemTap 跟蹤鎖爭搶

經過了剛才的修改，MongoDB 的性能有一些改善，但是還是會定期出現超時的情況。這一次我們用 perf 畫一下超時的火焰圖：

$ sudo perf record -a -g -F 997 -- sleep 30n$ git clone https://github.com/brendangregg/FlameGraphn$ sudo perf script | n FlameGraph/stackcollapse-perf.pl | n FlameGraph/flamegraph.pl n > flame.svgn

? SVG版（可交互）

在火焰圖上可以看到，__evict_server 佔用了很大一部分 CPU（要包含 __evict_clear_walk，因為編譯優化，以及截圖的時候沒有調試符號），除此之外，右邊的是處理查詢請求佔用的 CPU，那麼左邊的 __ckpt_server 是什麼鬼？

看了源碼，發現跟 WiredTiger 的 checkpointing 過程有關，總之就是一個數據落盤的過程。聽起來好複雜的一個過程，那麼有理由猜測它跟 __evict_server 一樣也會拿著一些鎖，跟處理請求的線程爭搶。

那麼，用 SystemTap 來確認一下（腳本取自這裡，做了些很小的修改）：

global FUTEX_WAIT = 0 /*, FUTEX_WAKE = 1 */nglobal FUTEX_PRIVATE_FLAG = 128 /* linux 2.6.22+ */nglobal FUTEX_CLOCK_REALTIME = 256 /* linux 2.6.29+ */nnglobal lock_waits # long-lived stats on (tid,lock) blockage elapsed timenglobal process_names # long-lived pid-to-execname mappingnnprobe syscall.futex.return {n if (($op & ~(FUTEX_PRIVATE_FLAG|FUTEX_CLOCK_REALTIME)) != FUTEX_WAIT) nextn process_names[pid()] = execname()n elapsed = gettimeofday_us() - @entry(gettimeofday_us())n lock_waits[pid(), $uaddr] <<< elapsedn}nnprobe end {n foreach ([pid+, lock] in lock_waits)n printf ("%s[%d] lock %p contended %d times, avg %d max %d min %d usn",n process_names[pid], pid, lock, @count(lock_waits[pid,lock]),n @avg(lock_waits[pid,lock]),n @max(lock_waits[pid,lock]),n @min(lock_waits[pid,lock]))n}n

經整理的結果：

0x3964500 contended 640 times, avg 4652783 max 20910627 min 1 usn0x3964400 contended 7833 times, avg 172389 max 20631809 min 1 usn0x1c38b60 contended 264 times, avg 400212 max 4135264 min 2 usn0x7f65a88ac8ec contended 3194 times, avg 100692 max 102941 min 33363 usn0x396a800 contended 54 times, avg 21390 max 44599 min 8 usn0x1c38484 contended 112 times, avg 15309 max 34762 min 155 usn0x3543100 contended 3 times, avg 2964 max 5175 min 1694 usn0x1c2ee40 contended 455 times, avg 14 max 4379 min 0 usn0x1c4b660 contended 213 times, avg 113 max 4176 min 1 usn0x7fb6cc14bee0 contended 45 times, avg 50 max 1536 min 1 usn0x363dec0 contended 86 times, avg 48 max 1116 min 1 usn0x1c3ff00 contended 12 times, avg 196 max 961 min 18 usn0x3846c48 contended 6 times, avg 157 max 843 min 9 usn0x7f65a88aca24 contended 20 times, avg 580 max 810 min 406 usn0x1c4b1a0 contended 17 times, avg 36 max 497 min 1 usn0x7fb6cd1cc990 contended 786 times, avg 22 max 459 min 0 usn......n

然後找可疑的鎖，用這個腳本可以找到相應的 stacktrace:

probe syscall.futex {n if($uaddr == $1) {n print_ubacktrace()n exit()n }n}n

這裡同樣是結果丟掉了…… 拿一個演示數據參考一下吧。

這裡實際上是 mmap 引擎的 MongoDB 在爭搶某一個鎖。

root@[redacted]:/home/ubuntu/bwang# stap n -d /lib/x86_64-linux-gnu/libpthread-2.19.so n -d /usr/bin/mongod n futex-bt.stp 0x3964188 | n c++filtnn0x7f7d711e9f1c : __lll_lock_wait+0x1c/0x30 [/lib/x86_64-linux-gnu/libpthread-2.19.so]n0x7f7d711e5649 : _L_lock_909+0xf/0x1b [/lib/x86_64-linux-gnu/libpthread-2.19.so] n0x7f7d711e5470 : __pthread_mutex_lock+0x70/0x23a [/lib/x86_64-linux-gnu/libpthread-2.19.so] n0xa22c90 : mongo::LockManager::unlock(mongo::LockRequest*)+0x70/0x4f0 [/usr/bin/mongod]n0xa311a1 : mongo::LockerImpl<true>::_unlockImpl(mongo::FastMapNoAlloc<mongo::ResourceId, mongo::LockRequest, 16>::IteratorImpl<mongo::FastMapNoAlloc<mongo::ResourceId, mongo::LockRequest, 16>, mongo::LockRequest>&)+0x111/0x4b0 [/usr/bin/mongod]n0xa31b41 : mongo::LockerImpl<true>::unlock(mongo::ResourceId)+0x191/0x260 [/usr/bin/mongod] n0xa22029 : mongo::Lock::DBLock::~DBLock()+0x19/0x40 [/usr/bin/mongod]n0x93a7c8 : mongo::AutoGetCollectionForRead::~AutoGetCollectionForRead()+0x58/0xa0 [/usr/bin/mongod]n0x91cd25 : mongo::GlobalCursorIdCache::timeoutCursors(mongo::OperationContext*, int)+0x175/0x340 [/usr/bin/mongod]n0x946850 : mongo::ClientCursorMonitor::run()+0xb0/0x120 [/usr/bin/mongod]n0x10ca1e4 : mongo::BackgroundJob::jobBody()+0x144/0x450[/usr/bin/mongod]n0x11a44ff : thread_proxy+0x6f/0x290 [/usr/bin/mongod] n0x7f7d711e3184 : start_thread+0xc4/0x330 [/lib/x86_64-linux-gnu/libpthread-2.19.so] n0x7f7d702d537d : 0x7f7d702d537d [/lib/x86_64-linux-gnu/libc-2.19.so+0xfa37d/0x3c0000]n

可以看到爭搶特定鎖的線程的完整調用棧被列印了出來。

在當時的分析中，能發現 __ckpt_server 同樣爭搶了 __evict_server 的鎖，不過這裡看不到了。

然後到這裡分析就結束了…… 因為線上的影響還在，我們就回滾成 mmap 引擎了（哭

我們仍然在調研這個問題，有進展再更新。

5. BONUS：perf & SystemTap 與 Node.js

這裡與 MongoDB 就沒關係了。因為我們的雲引擎大部分用戶都在用 Node.js，所以就 Node.js 特別的寫一點。

node 有參數 --perf-basic-prof 可以生成 perf 可以讀的 map 文件，有了這個 JIT 的代碼也能畫出火焰圖，還能標註到源自哪個 js 文件！性能分析、調查實例為什麼卡死，用這個非常合適！

? SVG版（可交互）

node 還提供了幾個 USDT，可以在 這裡 看到。

probe node_http_server_request = process("node").mark("http__server__request")n{n remote = user_string($arg3);n port = $arg4;n method = user_string($arg5);n url = user_string($arg6);n fd = $arg7;nn probestr = sprintf("%s(remote=%s, port=%d, method=%s, url=%s, fd=%d)",n $$name,n remote,n port,n method,n url,n fd);n}nn# 上面這些是從 nodejs 里拿的，實際上把 `node.stp` 文件放在 tapset 文件夾中，就不用複製過來了nnprobe node_http_server_request {n println(probestr);n}n

效果：

$ sudo stap -v ./test.stpn......nhttp__server__request(remote=127.0.0.1, port=37164, method=GET, url=/1.1, fd=14)nhttp__server__request(remote=127.0.0.1, port=37172, method=GET, url=/, fd=14)nhttp__server__request(remote=127.0.0.1, port=37174, method=GET, url=/, fd=14)nhttp__server__request(remote=127.0.0.1, port=37176, method=GET, url=/, fd=14)nhttp__server__request(remote=127.0.0.1, port=37178, method=GET, url=/, fd=14)nhttp__server__request(remote=127.0.0.1, port=37180, method=GET, url=/, fd=14)nhttp__server__request(remote=127.0.0.1, port=37182, method=GET, url=/, fd=14)n^CPass 5: run completed in 0usr/30sys/24800real ms.n

6. 相關的資料

• SystemTap 的資料可以去 OpenResty 的 repo 里找，裡面有很多針對 nginx 的腳本，可以在學習 SystemTap 的時候同時深入理解一下 nginx。

• 可以關注一下 余峰的博客，裡面也有一些 SystemTap 的內容。

• perf 和其他的 Linux tracer （eBPF、ftrace 等等）可以看 Brendan Gregg 的博客（強烈推薦）。

推薦閱讀：