身為一個SRE，工作中經常會遇到各種奇奇怪怪的服務異常問題。這些問題在staging（測試環境）沒有發現，但放到真實的生產環境就會碰到，最關鍵的是難以復現，某些問題可能是幾個月才會復現。
初次碰到可能會手忙腳亂，暴力的解決手段是將機器拉下線，然後開始專家會診，但是脫離了線上真實環境，沒有線上真實流量，某些問題可能不好復現了，這種方式還不是特別適合。
如何找到病因
大部分情況，其實我們已經可以通過top，pidstat等命令定位到具體是哪一個服務出的問題。當然重啟服務可以解決60%以上的服務異常問題，但是重啟後會丟失現場。
重啟一時爽，一直重啟就不爽了。還是需要定位到具體的問題。我還是希望知道底病根在哪，最好直接告訴我哪個具體函式，哪條語句導致的問題或者bug。最差也得知道是大致什麼節點的什麼型別故障
很多人可能會想到GDB。雖然這些工具很偉大，但是這應該不適合我們sre在已經服務已經發病的情況下使用，因為線上的服務不能被中止。GDB在除錯過程中設定斷點會發出SIGSTOP訊號，這會讓被除錯程式進入T (TASK_STOPPED or TASK_TRACED)暫停狀態或跟蹤狀態。同時 GDB 所基於的 ptrace 這種很古老的系統呼叫，其中的坑和問題也非常多。
比如 ptrace 需要改變目標除錯程式的父親，還不允許多個除錯者同時分析同一個程式，而且不太熟悉GDB的人可能會把程式除錯掛了，這種互動式的追蹤過程通常不考慮生產安全性，也不在乎效能損耗。另外提一下，strace也是基於ptrace的，所以strace也是對效能不友好的。
那麼就要提到動態追蹤技術了，動態追蹤技術通常通過探針這樣的機制發起查詢。動態追蹤一般來說是不需要應用目標來配合的，隨時隨地，按需採集，而且它非常大的優勢為效能消耗極小（通常5%或者更低的水平）。
動態追蹤
動態追蹤的工具很多，systemtap，perf，ftrace，sysdig，dtrace，eBPF等，由於我們的線上伺服器是Linux系統，且核心版本沒有那麼激進的使用最新的版本，所以我還是比較傾向於使用perf或者systemtap。就我個人而言，perf無疑是我的最愛了。
動態追蹤的事件源根據事件型別不同，主要分為三類。靜態探針， 動態探針以及硬體事件。
靜態探針：事先在程式碼中定義好的一類，已經編譯進應用程式或核心中的探針。常見的有 tracepoints（這是散落在核心原始碼中的一些hook，使能後一旦特定的程式碼被執行到時就會被觸發）還有USDT探針。
動態探針：事先沒有在程式碼中定義，但是可以在執行時動態載入，比如函式返回值等。常見的有uprobes（跟蹤使用者態函式）和kprobes（跟蹤核心態函式）。
硬體事件：一般由PMC產生，比如intel的CPU，一般會內建統計效能的暫存器（Hardware Prefirmance Counter）。
想要檢視可觸發的取樣事件可以通過 perf list 去展示
複製程式碼$ perf listList of pre-defined events (to be used in -e):branch-instructions OR cpu/branch-instructions/ [Kernel PMU event]branch-misses OR cpu/branch-misses/ [Kernel PMU event]... ...複製程式碼可以看下perf是支援很多事件的（注：由於線上伺服器核心版本不是最新的，所以這裡看到的有些少）
複製程式碼$ perf list | wc -l1196複製程式碼其主要分這幾大類（不同的版本可能看到的不一樣），HardWare Event，SoftWare Event，Kernel Tracepoint Event，User Statically-Defined Tracing (USDT)，Dynamic Tracing。
HardWare Event
就是上面提到的PMC，通過這些內容可以獲取到cpu週期，2級快取命中等事件，其實這些有些太過底層，在實際業務中並用不到這些的。
SoftWare Event
軟體事件是區別硬體事件的，比如缺頁，上下文切換等。
Kernel Tracepoint Event
核心追蹤點事件一般就是我們能想到的一些核心事件。Linux核心中定義了大量的跟蹤點，在程式碼層面就被編譯進核心，如TCP，檔案系統，磁碟I/O，系統呼叫，隨機數產生等等了。
User Statically-Defined Tracing (USDT)
與核心追蹤點事件類似，只不過是使用者級的，需要在原始碼中插入DTRACE_PROBE()程式碼，其實不少軟體都已經實現了，如Oracle。且一般在編譯的時候使用 ./configure --with-dtrace。如下所示是加上探測器的一段程式碼，在<sys/sdt.h>中加入的了DTRACE_PROBE() 巨集的引用
複製程式碼#include <sys/sdt.h>...voidmain_look(void){ ... query = wait_for_new_query(); DTRACE_PROBE2(myserv, query__receive, query->clientname, query->msg); process_query(query) ...}複製程式碼Dynamic Tracing
動態追蹤。當核心編譯時開啟CONFIG_KPROBES和CONFIG_UPROBES就可以使用動態的跟蹤。有了這些，我們就可以通過新增探針，來追蹤一個應用程式的核心呼叫，如開啟檔案，傳送tcp報文。
複製程式碼$ perf probe --add 'do_sys_open filename:string'$ perf record -e probe:do_sys_open -aR -p ${Service PID}$ perf script -i perf.data複製程式碼當然了，perf有很多的用法，下面大致介紹一下。
有了perf，我還可以對應用程式發生的系統呼叫做一次詳細的剖析。有了這些可以深層次的分析一個程式碼的呼叫關係。就像下面一樣，壓縮檔案發生的是大量的read和write
複製程式碼複製程式碼# perf stat -e 'syscalls:sys_enter_*' gzip file 2>&1 | awk '$1 != 0' Performance counter stats for 'gzip file': 1 syscalls:sys_enter_utimensat 1 syscalls:sys_enter_unlink 3 syscalls:sys_enter_newfstat 1 syscalls:sys_enter_lseek 2,180 syscalls:sys_enter_read 4,337 syscalls:sys_enter_write 3 syscalls:sys_enter_access 1 syscalls:sys_enter_fchmod 1 syscalls:sys_enter_fchown ... 2.309268546 seconds time elapsed複製程式碼亦或者通過perf trace 去跟蹤某個程式的系統呼叫。比starce好用多了。事實上前面也提到過strace是對效能很不友好的。這裡可以看下，gzip同樣的檔案，相同的操作，被strace後，執行總是慢一些。我試了很多次，perf的追蹤總是在2.3s左右，而strace就是2.9s左右。
複製程式碼# time strace -c gzip file% time seconds usecs/call calls errors syscall------ ----------- ----------- --------- --------- ---------------- 67.69 0.125751 29 4337 write 27.36 0.050826 23 2180 read 4.12 0.007661 7661 1 unlink 0.20 0.000377 94 4 openat 0.12 0.000231 77 3 3 access 0.08 0.000157 22 7 close ...------ ----------- ----------- --------- --------- ----------------100.00 0.185767 6568 4 totalreal 0m2.919suser 0m0.669ssys 0m2.263s複製程式碼perf最強大的還是 perf record,它支援先記錄，後檢視，記錄完成後通過perf report檢視。比如我想記錄某個應用程式的IO情況。以SimpleHTTPServer為例，可以看到當從SimpleHTTPServer下載檔案時的讀磁碟的呼叫。
複製程式碼複製程式碼$ perf record -e block:block_rq_issue -ag -p ${Service PID}$ perf report -i perf.dataSamples: 105 of event 'block:block_rq_issue', Event count (approx.): 105 Children Self Trace output- 0.95% 0.95% 8,0 R 0 () 24895224 + 1024 [python] 0 __GI___libc_read tracesys sys_read vfs_read do_sync_read xfs_file_aio_read xfs_file_buffered_aio_read generic_file_aio_read page_cache_async_readahead ondemand_readahead __do_page_cache_readahead ... ...複製程式碼或者是對一個應用服務程式進行全方位的追蹤
複製程式碼perf record -F 99 -ag -p ${Service PID} -- sleep 10複製程式碼然後通過perf report -i perf.data 來進行分析
複製程式碼Samples: 21 of event 'cpu-clock', Event count (approx.): 5250000 Children Self Command Shared Object Symbol- 76.19% 0.00% python [kernel.vmlinux] [k] system_call - system_call - 28.57% sys_recvfrom SYSC_recvfrom - sock_recvmsg + 23.81% inet_recvmsg - 4.76% security_socket_recvmsg selinux_socket_recvmsg sock_has_perm avc_has_perm_flags + 23.81% sys_sendto + 19.05% sys_shutdown + 4.76% sys_newstat複製程式碼這裡的分析結果顯示分為四列其中 Overhead 是我們需要關注的，因為這個比例佔用的多的話，證明該程式的大部分時間都在處理這個事件。其次是Symbol，也就是函式名，未知的話會用16進製表示的。
perf stat 也是一個不錯的程式效能分析工具，在上面的例子中，我通過perf stat記錄了某個程式的系統呼叫。它可以提供一個整體情況和彙總資料。
下面這個是一個瘋狂的C程式碼。可以看出，這是一個瘋狂的迴圈。
複製程式碼複製程式碼複製程式碼複製程式碼複製程式碼複製程式碼複製程式碼void longa(){ int i,j; for(i = 0; i < 10000000000000000; i++) j=i;}void foo1(){ int i; for(i = 0; i< 1000; i++) longa();}int main(void){ foo1();}複製程式碼編譯後使用一下 perf stat
複製程式碼$ perf stat ./a.out Performance counter stats for './a.out': 30249.723058 task-clock (msec) # 1.000 CPUs utilized 150 context-switches # 0.005 K/sec 2 cpu-migrations # 0.000 K/sec 113 page-faults # 0.004 K/sec <not supported> cycles <not supported> instructions <not supported> branches <not supported> branch-misses 30.260523538 seconds time elapsed複製程式碼可以看出，這是一個cpu密集型程式，會大量耗費cpu的計算資源。
更多的例子可以到 大神brendan gregg的部落格上看到，不僅僅是磁碟情況，還有更多奇妙的例子。
部落格地址：http://www.brendangregg.com/perf.html
雖然可以通過 $ perf record -ag -p ${Service PID} 來記錄追蹤一個程式的所有事件，但是需要注意的是，動態追蹤需要除錯符號，這些除錯符號諸如函式和變數的地址，資料結構和記憶體佈局，對映回原始碼的抽象實體的名稱等等，如果沒有的話，將看到一堆16進位制地址。這是很痛苦的。
而我們這裡大部分應用都是java服務，java服務是跑在jvm裡的。如果直接使用record看到的全是vm引擎符號，這些只能讓我們看到諸如gc一類的資訊，看不到具體某個java的類和方法，不過可以通過 開源的 perf-map-agent，它通過虛擬機器維護的 /tmp/perf-PID.map來進行符號的轉換。但是由於x86上的hotspot省略了frame pointer，所以就算轉換了符號，可能還是不能顯示完整的堆疊。不過在JDK 8u60+可以通過新增-XX:+PreserveFramePointer。同樣java的動態追蹤可以參考大神brendan gregg的部落格。
部落格地址：
http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html#Java
當所需要的工具安裝好且都配置完成後，可以使用如下命令對java服務進行動態追蹤其呼叫過程。
複製程式碼複製程式碼複製程式碼git clone --depth=1 https://github.com/brendangregg/FlameGraphperf record -F 99 -a -g -- sleep 30; ./FlameGraph/jmapsperf script > out.stacks01cat out.stacks01 | ./FlameGraph/stackcollapse-perf.pl | grep -v cpu_idle | \ ./FlameGraph/flamegraph.pl --color=java --hash > out.stacks01.svg複製程式碼同樣，systemtap也十分厲害的動態追蹤框架，它把使用者提供的指令碼，轉換為核心模組來執行，用來監測和跟蹤核心行為。
systemtap就不在這裡多做介紹了，有興趣的朋友可以去systemtap官網看看，這裡有許多現成的指令碼，如網路監控（監控tcp的連線，監控核心丟包的源頭等），磁碟監控（io監控，每個應用的讀寫時間等）等等。
相較於perf，systemtap的一個巨大的優勢是systemtap是可程式設計的，想追蹤什麼寫個指令碼就ok了，目前perf也在支援可程式設計計劃，eBPF的補丁計劃加上後，perf會變得更加強大。
systemtap官網教程：
https://sourceware.org/systemtap/SystemTap_Beginners_Guide/useful-systemtap-scripts.html
一次故障的動態追蹤過程
就在前不久，一陣急促的簡訊報警湧來，是線上伺服器的load告警了，我開始掃碼登陸伺服器，熟練的使用 top -c 觀察著線上伺服器的指標。
大致現象我沒有截圖，口述一下吧，有2個服務的cpu使用率達到300%，wa有些高，我懷疑到是程式bug了瘋狂讀磁碟。於是使用iotop，檢視io情況，可以看到總體的寫磁碟速度是 135M/s 。而讀請求幾乎是0 ，這是怎麼回事，這幾個服務在瘋狂寫資料？不應該吧，這幾個服務似乎沒有這麼大的寫磁碟需求啊，如果有，應該就是日誌了。在看日誌前，先 perf record -ag -p ${Service Pid} 記錄服務的狀態。檢視了應用服務的日誌，訊息佇列似乎處理出錯了，日誌量巨大且繁雜，各種日誌都有。到底哪裡有問題呢？雖然已經定位到故障可能和訊息佇列有關，但是還不能確定是哪裡的問題。
中斷 perf record 後，我利用上面提到的方法，匯出火焰圖。
可以看到應用程式主要在做拋異常、網路相關呼叫、gc、寫磁碟的操作。除了已知的操作外，問題服務的其餘大量操作都集中在網路的資料包收發上，再結合之前看到訊息佇列的相關報錯，應該定位是網路連線訊息佇列出的問題，應該訊息佇列連不上了，而程式碼有重試機制。
根據猜測，再到日誌中找線索，果然是這個問題。如果是在大海般的日誌中撈出有用的日誌資訊可能還需要些時間吧，這裡需要提一下，傳統的埋點多了不好，少了也不好，總歸是比較難以權衡的。（因為該java服務沒有開啟PreserveFramePointer，所以看不到java程式碼級的呼叫）於是很快的完成了故障的定位，接下來就好辦了，哪裡有問題治哪裡。
PS：perf 和 systemtap 的使用我這裡只是很粗淺的介紹了一下，大神brendan gregg有詳細部落格去介紹動態追蹤的每一個細節。開源社群也有很多動態追蹤的擴充套件，如春哥在OpenResty的效能追蹤上有很多十分讚的工具，同時我表示十分讚歎OpenResty的強大。我在動態追蹤的路上還是一個初級學習者，遠遠比不上春哥等大神級別的人物，如果有什麼錯誤也請指正。
參考文獻：
http://www.brendangregg.com/FlameGraphs/cpuflamegraphs.html#Java
http://openresty.org/posts/dynamic-tracing/#rd?utm_source=tuicool&utm_medium=referral
http://www.brendangregg.com/perf.html
https://zhuanlan.zhihu.com/p/34511018
https://www.ibm.com/developerworks/cn/linux/l-cn-perf1/
文章首發於小米運維公眾號，原文請戳：《淺談動態追蹤技術》