在前面的文章中，我提到了我們會用 ftrace 來解決問題顶伞，在開始之前亭珍，我先聊聊外面大牛們是如何用 ftrace 來解決問題的，第一個例子枝哄，顯而易見肄梨，就是 Brendan Gregg 的。在 Ftrace: The hidden ligh switch 這篇文章中挠锥，Gregg 寫到他是如何用基于 ftrace 定制的工具 perf tools 來解決一個問題的众羡，這里，我并不準(zhǔn)備完全翻譯這篇文章蓖租，主要是會說說粱侣，他解決問題的時候步驟，用到的相關(guān)工具蓖宦，以及詳細(xì)說明下這些工具是如何實現(xiàn)的齐婴。
首先來說說他遇到的問題，在 Netflix 里面稠茂，他們升級了一次 Ubuntu 的系統(tǒng)柠偶，然后就發(fā)現(xiàn) Cassandra 數(shù)據(jù)庫的 I/O 使用量急劇膨脹情妖，I/O 使用膨脹有很多原因，譬如緩存缺失诱担，record 的大小膨脹毡证，readahead 膨脹等，但到底是哪一個呢蔫仙？
iosnoop
首先料睛，Gregg 使用 iosnoop 工具進(jìn)行檢查，iosnoop 用來跟蹤 I/O 的詳細(xì)信息摇邦，當(dāng)然也包括 latency恤煞，結(jié)果如下：
# ./iosnoop -ts
STARTs ENDs COMM PID TYPE DEV BLOCK BYTES LATms
13370264.614265 13370264.614844 java 8248 R 202,32 1431244248 45056 0.58
13370264.614269 13370264.614852 java 8248 R 202,32 1431244336 45056 0.58
13370264.614271 13370264.614857 java 8248 R 202,32 1431244424 45056 0.59
13370264.614273 13370264.614868 java 8248 R 202,32 1431244512 45056 0.59
[...]
# ./iosnoop -Qts
STARTs ENDs COMM PID TYPE DEV BLOCK BYTES LATms
13370410.927331 13370410.931182 java 8248 R 202,32 1596381840 45056 3.85
13370410.927332 13370410.931200 java 8248 R 202,32 1596381928 45056 3.87
13370410.927332 13370410.931215 java 8248 R 202,32 1596382016 45056 3.88
13370410.927332 13370410.931226 java 8248 R 202,32 1596382104 45056 3.89
[...]
上面看不出來啥，一個繁忙的 I/O施籍，勢必會帶來高的 latency居扒。我們來說說 iosnoop 是如何做的。
iosnoop 主要是處理的 block 相關(guān)的 event法梯，主要是：
-
block:block_rq_issue- I/O 發(fā)起的時候的事件 -
block:block_rq_complete- I/O 完成事件 -
block:block_rq_insert- I/O 加入隊列的時間
如果使用了 -Q 參數(shù)，我們對于 I/O 開始事件就用 block:block_rq_insert犀概，否則就用的 block:block_rq_issue 立哑。下面是我用 FIO 測試 trace 的輸出：
fio-30749 [036] 5651360.257707: block_rq_issue: 8,0 WS 4096 () 1367650688 + 8 [fio]
<idle>-0 [036] 5651360.257768: block_rq_complete: 8,0 WS () 1367650688 + 8 [0]
我們根據(jù) 1367650688 + 8 能找到對應(yīng)的 I/O block sector，然后根據(jù) issue 和 complete 的時間就能知道 latency 了姻灶。
tpoint
為了更好的定位 I/O 問題铛绰，Gregg 使用 tpoint 來追蹤 block_rq_insert，如下：
# ./tpoint -H block:block_rq_insert
Tracing block:block_rq_insert. Ctrl-C to end.
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
java-16035 [000] 13371565.253582: block_rq_insert: 202,16 WS 0 () 550505336 + 88 [java]
java-16035 [000] 13371565.253582: block_rq_insert: 202,16 WS 0 () 550505424 + 56 [java]
java-8248 [007] 13371565.278372: block_rq_insert: 202,32 R 0 () 660621368 + 88 [java]
java-8248 [007] 13371565.278373: block_rq_insert: 202,32 R 0 () 660621456 + 88 [java]
java-8248 [007] 13371565.278374: block_rq_insert: 202,32 R 0 () 660621544 + 24 [java]
java-8249 [007] 13371565.311507: block_rq_insert: 202,32 R 0 () 660666416 + 88 [java]
[...]
然后也跟蹤了實際的堆棧:
# ./tpoint -s block:block_rq_insert 'rwbs ~ "*R*"' | head -1000
Tracing block:block_rq_insert. Ctrl-C to end.
java-8248 [005] 13370789.973826: block_rq_insert: 202,16 R 0 () 1431480000 + 8 [java]
java-8248 [005] 13370789.973831: <stack trace>
=> blk_flush_plug_list
=> blk_queue_bio
=> generic_make_request.part.50
=> generic_make_request
=> submit_bio
=> do_mpage_readpage
=> mpage_readpages
=> xfs_vm_readpages
=> read_pages
=> __do_page_cache_readahead
=> ra_submit
=> do_sync_mmap_readahead.isra.24
=> filemap_fault
=> __do_fault
=> handle_pte_fault
=> handle_mm_fault
=> do_page_fault
=> page_fault
java-8248 [005] 13370789.973831: block_rq_insert: 202,16 R 0 () 1431480024 + 32 [java]
java-8248 [005] 13370789.973836: <stack trace>
=> blk_flush_plug_list
=> blk_queue_bio
=> generic_make_request.part.50
[...]
tpoint 的實現(xiàn)比較簡單产喉，譬如上面的 block:block_rq_insert捂掰，它直接會找 events/block/block_rq_insert 是否存在，如果存在曾沈，就是找到了對應(yīng)的 event这嚣。然后給這個 event 的 enable 文件寫入 1，如果我們要開啟堆棧塞俱，就往 options/stacktrace 里面也寫入 1姐帚。
從上面的堆棧可以看到障涯，有 readahead 以及 page fault 了罐旗。在 Netflix 新升級的 Ubuntu 系統(tǒng)里面，默認(rèn)的 direct map page size 是 2 MB唯蝶，而之前的 系統(tǒng)是 4 KB九秀，另外就是默認(rèn)的 readahead 是 2048 KB，老的系統(tǒng)是 128 KB粘我」难眩看起來慢慢找到問題了。
funccount
為了更好的看函數(shù)調(diào)用的次數(shù)，Gregg 使用了 funccount 函數(shù)友酱，譬如檢查 submit_bio ：
# ./funccount -i 1 submit_bio
Tracing "submit_bio"... Ctrl-C to end.
FUNC COUNT
submit_bio 27881
FUNC COUNT
submit_bio 28478
# ./funccount -i 1 filemap_fault
Tracing "filemap_fault"... Ctrl-C to end.
FUNC COUNT
filemap_fault 2203
FUNC COUNT
filemap_fault 3227
[...]
上面可以看到晴音，有 10 倍的膨脹。對于 funccount 腳本缔杉，主要是需要開啟 function profile 功能锤躁，也就是給 function_profile_enabled 文件寫入 1，當(dāng)打開之后或详，就會在 trace_stat 目錄下面對相關(guān)的函數(shù)進(jìn)行統(tǒng)計系羞，可以看到 function0，function1 這樣的文件霸琴，0 和 1 就是對應(yīng)的 CPU椒振。cat 一個文件:
cat function0
Function Hit Time Avg s^2
-------- --- ---- --- ---
schedule 56 12603274 us 225058.4 us 4156108562 us
do_idle 51 4750521 us 93147.47 us 5947176878 us
call_cpuidle 51 4748981 us 93117.27 us 5566277250 us
就能知道各個函數(shù)的 count 了。
funcslower
為了更加確定系統(tǒng)的延遲是先前堆棧上面看到的函數(shù)引起的梧乘，Gregg 使用了 funcslower 來看執(zhí)行慢的函數(shù)：
# ./funcslower -P filemap_fault 1000
Tracing "filemap_fault" slower than 1000 us... Ctrl-C to end.
0) java-8210 | ! 5133.499 us | } /* filemap_fault */
0) java-8258 | ! 1120.600 us | } /* filemap_fault */
0) java-8235 | ! 6526.470 us | } /* filemap_fault */
2) java-8245 | ! 1458.30 us | } /* filemap_fault */
[...]
可以看到澎迎，filemap_fault 這個函數(shù)很慢。對于 funcslower选调，我們主要是用 tracing_thresh 來進(jìn)行控制夹供，給這個文件寫入 threshold，如果函數(shù)的執(zhí)行時間超過了 threshold仁堪，就會記錄哮洽。
funccount (again)
Gregg 根據(jù)堆棧的情況，再次對 readpage 和 readpages 進(jìn)行統(tǒng)計
# ./funccount -i 1 '*mpage_readpage*'
Tracing "*mpage_readpage*"... Ctrl-C to end.
FUNC COUNT
mpage_readpages 364
do_mpage_readpage 122930
FUNC COUNT
mpage_readpages 318
do_mpage_readpage 110344
[...]
仍然定位到是 readahead 的寫放大引起弦聂，但他們已經(jīng)調(diào)整了 readahead 的值鸟辅，但并沒有起到作用。
kprobe
因為 readahead 并沒有起到作用莺葫，所以 Gregg 準(zhǔn)備更進(jìn)一步匪凉，使用 dynamic tracing。他注意到上面堆棧的函數(shù) __do_page_cache_readahead() 有一個 nr_to_read 的參數(shù)捺檬，這個參數(shù)表明的是每次 read 需要讀取的 pages 的個數(shù)洒缀，使用 kprobe：
# ./kprobe -H 'p:do __do_page_cache_readahead nr_to_read=%cx'
Tracing kprobe m. Ctrl-C to end.
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
java-8714 [000] 13445354.703793: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8716 [002] 13445354.819645: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8734 [001] 13445354.820965: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8709 [000] 13445354.825280: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
[...]
可以看到，每次 nr_to_read 讀取了 512 （200 的 16 進(jìn)制）個 pages欺冀。在上面的例子树绩，他并不知道 nr_to_read 實際的符號是多少，于是用 %cx 來猜測的隐轩，也真能蒙對饺饭，太猛了。
關(guān)于 kprobe 的使用职车，具體可以參考 kprobetrace 文檔瘫俊，kprobe 解析需要 trace 的 event 之后鹊杖，會將其寫入到 kprobe_events 里面，然后在 events/kprobes/<EVENT>/ 進(jìn)行對應(yīng)的 enable 和 filter 操作扛芽。
funcgraph
為了更加確認(rèn)骂蓖，Gregg 使用 funcgraph 來看 filemap_fault 的實際堆棧，來看 nr_to_read 到底是從哪里傳進(jìn)來的川尖。
# ./funcgraph -P filemap_fault | head -1000
2) java-8248 | | filemap_fault() {
2) java-8248 | 0.568 us | find_get_page();
2) java-8248 | | do_sync_mmap_readahead.isra.24() {
2) java-8248 | 0.160 us | max_sane_readahead();
2) java-8248 | | ra_submit() {
2) java-8248 | | __do_page_cache_readahead() {
2) java-8248 | | __page_cache_alloc() {
2) java-8248 | | alloc_pages_current() {
2) java-8248 | 0.228 us | interleave_nodes();
2) java-8248 | | alloc_page_interleave() {
2) java-8248 | | __alloc_pages_nodemask() {
2) java-8248 | 0.105 us | next_zones_zonelist();
2) java-8248 | | get_page_from_freelist() {
2) java-8248 | 0.093 us | next_zones_zonelist();
2) java-8248 | 0.101 us | zone_watermark_ok();
2) java-8248 | | zone_statistics() {
2) java-8248 | 0.073 us | __inc_zone_state();
2) java-8248 | 0.074 us | __inc_zone_state();
2) java-8248 | 1.209 us | }
2) java-8248 | 0.142 us | prep_new_page();
2) java-8248 | 3.582 us | }
2) java-8248 | 4.810 us | }
2) java-8248 | 0.094 us | inc_zone_page_state();
找到了一個比較明顯的函數(shù) max_sane_readahead登下。對于 funcgraph，主要就是將需要關(guān)注的函數(shù)放到 set_graph_function 里面叮喳，然后在 current_tracer 里面開啟 function_graph被芳。
kprobe (again)
然后，Gregg 繼續(xù)使用 kprobe 來 trace max_sane_readahead 函數(shù)馍悟，這次不用猜測寄存器了畔濒，直接用 $retval 來看返回值:
# ./kprobe 'r:m max_sane_readahead $retval'
Tracing kprobe m. Ctrl-C to end.
java-8700 [000] 13445377.393895: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8723 [003] 13445377.396362: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8701 [001] 13445377.398216: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8738 [000] 13445377.399793: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8728 [000] 13445377.408529: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
[...]
發(fā)現(xiàn)仍然是 0x200 個 pages，然后他在發(fā)現(xiàn)锣咒，readahead 的屬性其實是在 file_ra_state_init 這個函數(shù)就設(shè)置好了侵状，然后這個函數(shù)是在文件打開的時候調(diào)用的。但他在進(jìn)行 readahead tune 的時候毅整，一直是讓 Cassandra 運行著趣兄，也就是無論怎么改 readahead，都不會起到作用毛嫉，于是他把 Cassandra 重啟诽俯，問題解決了妇菱。
# ./kprobe 'r:m max_sane_readahead $retval'
Tracing kprobe m. Ctrl-C to end.
java-11918 [007] 13445663.126999: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.128329: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.129795: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.131164: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
[...]
這次只會讀取 0x80 個 pages 了承粤。
小結(jié)
上面就是一個完完整整使用 ftrace 來定位問題的例子，可以看到闯团，雖然 Linux 系統(tǒng)在很多時候?qū)ξ覀兪且粋€黑盒辛臊，但是有了 ftrace，如果在黑暗中開啟了一盞燈房交，能讓我們朝著光亮前行彻舰。我們內(nèi)部也在基于 ftrace 做很多有意思的事情，如果你感興趣候味，歡迎聯(lián)系我 tl@pingcap.com刃唤。
