淺談動態追蹤技術

本文主要介紹了動態追蹤技術，並舉例說明動態追蹤技術的應用。

身爲一個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/

文章首發於小米運維公衆號，原文請戳：《淺談動態追蹤技術》