動態追蹤學習


動態追蹤技術原因

當碰到內核線程的資源使用異常時,很多常用的進程級性能工具,並不能直接用到內核線程上。這時,我們就可以使用內核自帶的 perf 來觀察它們的行為,找出熱點函數,進一步定位性能瓶頸。不過,perf 產生的匯總報告並不直觀,所以我通常也推薦用火焰圖來協助排查。

其實,使用 perf 對系統內核線程進行分析時,內核線程依然還在正常運行中,所以這種方法也被稱為動態追蹤技術。

動態追蹤技術,通過探針機制,來采集內核或者應用程序的運行信息,從而可以不用修改內核和應用程序的代碼,就獲得豐富的信息,幫你分析、定位想要排查的問題。

以往,在排查和調試性能問題時,我們往往需要先為應用程序設置一系列的斷點(比如使用GDB),然后以手動或者腳本(比如 GDB 的 Python 擴展)的方式,在這些斷點處分析應用程序的狀態。或者,增加一系列的日志,從日志中尋找線索。

不過,斷點往往會中斷應用的正常運行;而增加新的日志,往往需要重新編譯和部署。這些方法雖然在今天依然廣泛使用,但在排查復雜的性能問題時,往往耗時耗力,更會對應用的正常運行造成巨大影響。

此外,這類方式還有大量的性能問題。比如,出現的概率小,只有線上環境才能碰到。這種難以復現的問題,亦是一個巨大挑戰。

而動態追蹤技術的出現,就為這些問題提供了完美的方案:它既不需要停止服務,也不需要修改應用程序的代碼;所有一切還按照原來的方式正常運行時,就可以幫你分析出問題的根源。
同時,相比以往的進程級跟蹤方法(比如 ptrace),動態追蹤往往只會帶來很小的性能損耗(通常在 5% 或者更少)。

 

動態追蹤

說到動態追蹤(Dynamic Tracing),就不得不提源於 Solaris 系統的 DTrace。DTrace 是動態追蹤技術的鼻祖,它提供了一個通用的觀測框架,並可以使用 D 語言進行自由擴展。

DTrace 的工作原理如下圖所示。它的運行常駐在內核中,用戶可以通過 dtrace 命令,把 D 語言編寫的追蹤腳本,提交到內核中的運行時來執行。DTrace 可以跟蹤用戶態和內核態的所有事件,並通過一些列的優化措施,保證最小的性能開銷。

雖然直到今天,DTrace 本身依然無法在 Linux 中運行,但它同樣對 Linux 動態追蹤產生了巨大的影響。很多工程師都嘗試過把 DTrace 移植到 Linux 中,這其中,最著名的就是 RedHat 主推的 SystemTap。

同 DTrace 一樣,SystemTap 也定義了一種類似的腳本語言,方便用戶根據需要自由擴展。不過,不同於 DTrace,SystemTap 並沒有常駐內核的運行時,它需要先把腳本編譯為內核模塊,然后再插入到內核中執行。這也導致 SystemTap 啟動比較緩慢,並且依賴於完整的調試符號表。

總的來說,為了追蹤內核或用戶空間的事件,Dtrace 和 SystemTap 都會把用戶傳入的追蹤處理函數(一般稱為 Action),關聯到被稱為探針的檢測點上。這些探針,實際上也就是各種動態追蹤技術所依賴的事件源。

動態追蹤的事件源

根據事件類型的不同,動態追蹤所使用的事件源,可以分為靜態探針、動態探針以及硬件事件等三類。它們的關系如下圖所示:其中,硬件事件通常由性能監控計數器 PMC(Performance Monitoring Counter)產生,包括了各種硬件的性能情況,比如 CPU 的緩存、指令周期、分支預測等等。

靜態探針,是指事先在代碼中定義好,並編譯到應用程序或者內核中的探針。這些探針只有在開啟探測功能時,才會被執行到;未開啟時並不會執行。常見的靜態探針包括內核中的跟蹤點(tracepoints)和 USDT(Userland Statically Defined Tracing)探針。

  • 跟蹤點(tracepoints),實際上就是在源碼中插入的一些帶有控制條件的探測點,這些探測點允許事后再添加處理函數。比如在內核中,最常見的靜態跟蹤方法就是 printk,即輸出日志。Linux 內核定義了大量的跟蹤點,可以通過內核編譯選項,來開啟或者關閉。
  • USDT 探針,全稱是用戶級靜態定義跟蹤,需要在源碼中插入 DTRACE_PROBE() 代碼,並編譯到應用程序中。不過,也有很多應用程序內置了 USDT 探針,比如 MySQL、PostgreSQL等。

動態探針,則是指沒有事先在代碼中定義,但卻可以在運行時動態添加的探針,比如函數的調用和返回等。動態探針支持按需在內核或者應用程序中添加探測點,具有更高的靈活性。常見的動態探針有兩種,即用於內核態的 kprobes 和用於用戶態的 uprobes。

  • kprobes 用來跟蹤內核態的函數,包括用於函數調用的 kprobe 和用於函數返回的kretprobe。
  • uprobes 用來跟蹤用戶態的函數,包括用於函數調用的 uprobe 和用於函數返回的uretprobe。

注意,kprobes 需要內核編譯時開啟 CONFIG_KPROBE_EVENTS;而 uprobes則需要內核編譯時開啟 CONFIG_UPROBE_EVENTS。

動態追蹤機制

而在這些探針的基礎上,Linux 也提供了一系列的動態追蹤機制,比如 ftrace、perf、eBPF 等。

ftrace 最早用於函數跟蹤,后來又擴展支持了各種事件跟蹤功能。ftrace 的使用接口跟我們之前提到的 procfs 類似,它通過 debugfs(4.1 以后也支持 tracefs),以普通文件的形式,向用戶空間提供訪問接口。

這樣,不需要額外的工具,你就可以通過掛載點(通常為 /sys/kernel/debug/tracing 目錄)內的文件讀寫,來跟 ftrace 交互,跟蹤內核或者應用程序的運行事件。

perf 是我們的老朋友了,我們在前面的好多案例中,都使用了它的事件記錄和分析功能,這實際上只是一種最簡單的靜態跟蹤機制。你也可以通過 perf ,來自定義動態事件(perf probe),只關注真正感興趣的事件。

eBPF 則在 BPF(Berkeley Packet Filter)的基礎上擴展而來,不僅支持事件跟蹤機制,還可以通過自定義的 BPF 代碼(使用 C 語言)來自由擴展。所以,eBPF 實際上就是常駐於內核的運行時,可以說就是 Linux 版的 DTrace。

 

ftrace

ftrace 通過 debugfs(或者 tracefs),為用戶空間提供接口。所以使用 ftrace,往往是從切換到 debugfs 的掛載點開始。

cd /sys/kernel/debug/tracing
$ ls
README                      instances            set_ftrace_notrace  trace_marker_raw
available_events            kprobe_events        set_ftrace_pid      trace_options
...

如果這個目錄不存在,則說明你的系統還沒有掛載 debugfs,你可以執行下面的命令來掛載它:

mount -t debugfs nodev /sys/kernel/debug

ftrace 提供了多個跟蹤器,用於跟蹤不同類型的信息,比如函數調用、中斷關閉、進程調度等。具體支持的跟蹤器取決於系統配置,你可以執行下面的命令,來查詢所有支持的跟蹤器:

cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

這其中,function 表示跟蹤函數的執行,function_graph 則是跟蹤函數的調用關系,也就是生成直觀的調用關系圖。這便是最常用的兩種跟蹤器。
除了跟蹤器外,使用 ftrace 前,還需要確認跟蹤目標,包括內核函數和內核事件。其中,

  • 函數就是內核中的函數名。
  • 而事件,則是內核源碼中預先定義的跟蹤點。

同樣地,可以執行下面的命令,來查詢支持的函數和事件:

cat available_filter_functions
$ cat available_events

ls 命令會通過 open 系統調用打開目錄文件,而 open 在內核中對應的函數名為do_sys_open。

第一步就是把要跟蹤的函數設置為 do_sys_open:

echo do_sys_open > set_graph_function

第二步,配置跟蹤選項,開啟函數調用跟蹤,並跟蹤調用進程:

echo function_graph > current_tracer
$ echo funcgraph-proc > trace_options

第三步,也就是開啟跟蹤:

echo 1 > tracing_on

第四步,執行一個 ls 命令后,再關閉跟蹤:

ls
$ echo 0 > tracing_on

實際測試代碼如下:

# cat available_tracers
blk function_graph wakeup_dl wakeup_rt wakeup function nop
# cat available_events|head
kvmmmu:kvm_mmu_pagetable_walk
kvmmmu:kvm_mmu_paging_element
kvmmmu:kvm_mmu_set_accessed_bit
kvmmmu:kvm_mmu_set_dirty_bit
kvmmmu:kvm_mmu_walker_error
kvmmmu:kvm_mmu_get_page
kvmmmu:kvm_mmu_sync_page
kvmmmu:kvm_mmu_unsync_page
kvmmmu:kvm_mmu_prepare_zap_page
kvmmmu:mark_mmio_spte

# echo do_sys_open > set_graph_function
# echo funcgraph-proc > trace_options
-bash: echo: write error: Invalid argument
# echo function_graph > current_tracer
# echo funcgraph-proc > trace_options
# echo 1 > tracing_on
# ls
available_events            dynamic_events            kprobe_events    saved_cmdlines       set_ftrace_pid      timestamp_mode    trace_stat
available_filter_functions  dyn_ftrace_total_info     kprobe_profile   saved_cmdlines_size  set_graph_function  trace             tracing_cpumask
available_tracers           enabled_functions         max_graph_depth  saved_tgids          set_graph_notrace   trace_clock       tracing_max_latency
buffer_percent              events                    options          set_event            snapshot            trace_marker      tracing_on
buffer_size_kb              free_buffer               per_cpu          set_event_pid        stack_max_size      trace_marker_raw  tracing_thresh
buffer_total_size_kb        function_profile_enabled  printk_formats   set_ftrace_filter    stack_trace         trace_options     uprobe_events
current_tracer              instances                 README           set_ftrace_notrace   stack_trace_filter  trace_pipe        uprobe_profile
# echo 0 > tracing_on

第五步,也是最后一步,查看跟蹤結果:

cat trace
# tracer: function_graph
#
# CPU  TASK/PID         DURATION                  FUNCTION CALLS
# |     |    |           |   |                     |   |   |   |
 0)    ls-12276    |               |  do_sys_open() {
 0)    ls-12276    |               |    getname() {
 0)    ls-12276    |               |      getname_flags() {
 0)    ls-12276    |               |        kmem_cache_alloc() {
 0)    ls-12276    |               |          _cond_resched() {
 0)    ls-12276    |   0.049 us    |            rcu_all_qs();
 0)    ls-12276    |   0.791 us    |          }
 0)    ls-12276    |   0.041 us    |          should_failslab();
 0)    ls-12276    |   0.040 us    |          prefetch_freepointer();
 0)    ls-12276    |   0.039 us    |          memcg_kmem_put_cache();
 0)    ls-12276    |   2.895 us    |        }
 0)    ls-12276    |               |        __check_object_size() {
 0)    ls-12276    |   0.067 us    |          __virt_addr_valid();
 0)    ls-12276    |   0.044 us    |          __check_heap_object();
 0)    ls-12276    |   0.039 us    |          check_stack_object();
 0)    ls-12276    |   1.570 us    |        }
 0)    ls-12276    |   5.790 us    |      }
 0)    ls-12276    |   6.325 us    |    }
...

實際測試代碼如下:

# cat trace|head -n 100
# tracer: function_graph
#
# CPU  TASK/PID         DURATION                  FUNCTION CALLS
# |     |    |           |   |                     |   |   |   |
   0)   ls-9986     |               |  do_sys_open() {
   0)   ls-9986     |               |    getname() {
.......
   0)   ls-9986     |               |            dput() {
   0)   ls-9986     |               |              _cond_resched() {
   0)   ls-9986     |   0.184 us    |                rcu_all_qs();
   0)   ls-9986     |   0.535 us    |              }
   0)   ls-9986     |   0.954 us    |            }
   0)   ls-9986     |   9.782 us    |          }
   

在最后得到的輸出中:

  • 第一列表示運行的 CPU;
  • 第二列是任務名稱和進程 PID;
  • 第三列是函數執行延遲;
  • 最后一列,則是函數調用關系圖。

你可以看到,函數調用圖,通過不同級別的縮進,直觀展示了各函數間的調用關系。

當然,我想你應該也發現了 ftrace 的使用缺點——五個步驟實在是麻煩,用起來並不方便。不過,不用擔心, trace-cmd 已經幫你把這些步驟給包裝了起來。這樣,你就可以在同一個命令行
工具里,完成上述所有過程。

你可以執行下面的命令,來安裝 trace-cmd :

# Ubuntu
$ apt-get install trace-cmd
# CentOS
$ yum install trace-cmd

安裝好后,原本的五步跟蹤過程,就可以簡化為下面這兩步:

trace-cmd record -p function_graph -g do_sys_open -O funcgraph-proc ls
$ trace-cmd report
...
              ls-12418 [000] 85558.075341: funcgraph_entry:                   |  do_sys_open() {
              ls-12418 [000] 85558.075363: funcgraph_entry:                   |    getname() {
              ls-12418 [000] 85558.075364: funcgraph_entry:                   |      getname_flags() {
              ls-12418 [000] 85558.075364: funcgraph_entry:                   |        kmem_cache_alloc() {
              ls-12418 [000] 85558.075365: funcgraph_entry:                   |          _cond_resched() {
              ls-12418 [000] 85558.075365: funcgraph_entry:        0.074 us   |            rcu_all_qs();
              ls-12418 [000] 85558.075366: funcgraph_exit:         1.143 us   |          }
              ls-12418 [000] 85558.075366: funcgraph_entry:        0.064 us   |          should_failslab();
              ls-12418 [000] 85558.075367: funcgraph_entry:        0.075 us   |          prefetch_freepointer();
              ls-12418 [000] 85558.075368: funcgraph_entry:        0.085 us   |          memcg_kmem_put_cache();
              ls-12418 [000] 85558.075369: funcgraph_exit:         4.447 us   |        }
              ls-12418 [000] 85558.075369: funcgraph_entry:                   |        __check_object_size() {
              ls-12418 [000] 85558.075370: funcgraph_entry:        0.132 us   |          __virt_addr_valid();
              ls-12418 [000] 85558.075370: funcgraph_entry:        0.093 us   |          __check_heap_object();
              ls-12418 [000] 85558.075371: funcgraph_entry:        0.059 us   |          check_stack_object();
              ls-12418 [000] 85558.075372: funcgraph_exit:         2.323 us   |        }
              ls-12418 [000] 85558.075372: funcgraph_exit:         8.411 us   |      }
              ls-12418 [000] 85558.075373: funcgraph_exit:         9.195 us   |    }
...

實際測試代碼如下:

# trace-cmd report|head -n 100
CPU 0 is empty
cpus=2
              ls-10015 [001]  3232.717769: funcgraph_entry:        1.802 us   |  mutex_unlock();
              ls-10015 [001]  3232.720548: funcgraph_entry:                   |  do_sys_open() {
              ls-10015 [001]  3232.720549: funcgraph_entry:                   |    getname() {
              ls-10015 [001]  3232.720549: funcgraph_entry:                   |      getname_flags() {
              ls-10015 [001]  3232.720549: funcgraph_entry:                   |        kmem_cache_alloc() {
              ls-10015 [001]  3232.720550: funcgraph_entry:                   |          _cond_resched() {
              ls-10015 [001]  3232.720550: funcgraph_entry:        0.206 us   |            rcu_all_qs();
              ls-10015 [001]  3232.720550: funcgraph_exit:         0.724 us   |          }
              ls-10015 [001]  3232.720550: funcgraph_entry:        0.169 us   |          should_failslab();
              ls-10015 [001]  3232.720551: funcgraph_entry:        0.177 us   |          memcg_kmem_put_cache();
              ls-10015 [001]  3232.720551: funcgraph_exit:         1.792 us   |        }
              ls-10015 [001]  3232.720551: funcgraph_entry:                   |        __check_object_size() {
              ls-10015 [001]  3232.720552: funcgraph_entry:        0.167 us   |          check_stack_object();
              ls-10015 [001]  3232.720552: funcgraph_entry:        0.207 us   |          __virt_addr_valid();
              ls-10015 [001]  3232.720552: funcgraph_entry:        0.212 us   |          __check_heap_object();
              ls-10015 [001]  3232.720553: funcgraph_exit:         1.286 us   |        }
              ls-10015 [001]  3232.720553: funcgraph_exit:         3.744 us   |      }
              ls-10015 [001]  3232.720553: funcgraph_exit:         4.134 us   |    }

trace-cmd 的輸出跟上述 cat trace 的輸出是類似的。

通過這個例子我們知道,想要了解某個內核函數的調用過程時,使用 ftrace ,就可以跟蹤到它的執行過程。

perf

perf 的功能

  • perf 可以用來分析 CPU cache、CPU 遷移、分支預測、指令周期等各種硬件事件;
  • perf 也可以只對感興趣的事件進行動態追蹤
  • 先對事件進行采樣,然后再根據采樣數,評估各個函數的調用頻率

perf例子

1.內核函數 do_sys_open 的例子

很多人只看到了 strace 簡單易用的好處,卻忽略了它對進程性能帶來的影響。

從原理上來說,strace 基於系統調用 ptrace 實現,這就帶來了兩個問題:

  • 由於 ptrace 是系統調用,就需要在內核態和用戶態切換。當事件數量比較多時,繁忙的切換必然會影響原有服務的性能;
  • ptrace 需要借助 SIGSTOP 信號掛起目標進程。這種信號控制和進程掛起,會影響目標進程的行為。

在性能敏感的應用(比如數據庫)中,我並不推薦你用 strace (或者其他基於 ptrace 的性能工具)去排查和調試。

在 strace 的啟發下,結合內核中的 utrace 機制, perf 也提供了一個 trace 子命令,是取代 strace 的首選工具。

相對於 ptrace 機制來說,perf trace 基於內核事件,自然要比進程跟蹤的性能好很多。

 

第二個 perf 的例子是用戶空間的庫函數

# 為/bin/bash添加readline探針
$ perf probe -x /bin/bash 'readline%return +0($retval):string’
 # 采樣記錄 $ perf record -e probe_bash:readline__return -aR sleep 5 # 查看結果 $ perf script bash 13348 [000] 93939.142576: probe_bash:readline__return: (5626ffac1610 <- 5626ffa46739) arg1="ls" # 跟蹤完成后刪除探針 $ perf probe --del probe_bash:readline__return

 

BPF

 

 上圖是BPF的位置和框架,需要注意的是kernel和user使用了buffer來傳輸數據,避免頻繁上下文切換。BPF虛擬機非常簡潔,由累加器、索引寄存器、存儲、隱式程序計數器組成

BPF只使用了4條虛擬機指令,就能提供非常有用的IP報文過濾

 

 1 (000) ldh      [12]                             // 鏈路層第12字節的數據(2字節)加載到寄存器,ethertype字段
 2 (001) jeq      #0x86dd          jt 2    jf 7    // 判斷是否為IPv6類型,true跳到2,false跳到7
 3 (002) ldb      [20]                             // 鏈路層第20字節的數據(1字節)加載到寄存器,IPv6的next header字段
 4 (003) jeq      #0x6             jt 10    jf 4    // 判斷是否為TCP,true跳到10,false跳到4
 5 (004) jeq      #0x2c            jt 5    jf 11   // 可能是IPv6分片標志,true跳到5,false跳到11
 6 (005) ldb      [54]                             // 我編不下去了...
 7 (006) jeq      #0x6             jt 10    jf 11   // 判斷是否為TCP,true跳到10,false跳到11
 8 (007) jeq      #0x800           jt 8    jf 11   // 判斷是否為IP類型,true跳到8,false跳到11
 9 (008) ldb      [23]                             // 鏈路層第23字節的數據(1字節)加載到寄存器,next proto字段
10 (009) jeq      #0x6             jt 10    jf 11   // 判斷是否為TCP,true跳到10,false跳到11
11 (010) ret      #262144                          // 返回true
12 (011) ret      #0                               // 返回0

應用

tcpdump 就是使用的bpf 過濾規則

 

eBPF

eBPF 就是 Linux 版的 DTrace,可以通過 C 語言自由擴展(這些擴展通過 LLVM 轉換為 BPF 字節碼后,加載到內核中執行)。相對於BPF做了一些重要改進,首先是效率,這要歸功於JIB編譯eBPF代碼;其次是應用范圍,從網絡報文擴展到一般事件處理;最后不再使用socket,使用map進行高效的數據存儲。

根據以上的改進,內核開發人員在不到兩年半的事件,做出了包括網絡監控、限速和系統監控。

目前eBPF可以分解為三個過程:

  • 以字節碼的形式創建eBPF的程序。編寫C代碼,將LLVM編譯成駐留在ELF文件中的eBPF字節碼。
  • 將程序加載到內核中,並創建必要的eBPF-maps。eBPF具有用作socket filter,kprobe處理器,流量控制調度,流量控制操作,tracepoint處理,eXpress Data Path(XDP),性能監測,cgroup限制,輕量級tunnel的程序類型。
  • 將加載的程序attach到系統中。根據不同的程序類型attach到不同的內核系統中。程序運行的時候,啟動狀態並且開始過濾,分析或者捕獲信息

源碼路徑:

bpf的系統調用:           kernel/bpf/syscall.c       
bpf系統調用的頭文件:include/uapi/linux/bpf.h 
入口函數:                   int bpf(int cmd, union bpf_attr *attr, unsigned int size)

 

eBPF命令

BPF_PROG_LOAD 驗證並且加載eBPF程序,返回一個新的文件描述符。
BPF_MAP_CREATE 創建map並且返回指向map的文件描述符
BPF_MAP_LOOKUP_ELEM 通過key從指定的map中查找元素,並且返回value值
BPF_MAP_UPDATE_ELEM 在指定的map中創建或者更新元素(key/value 配對)
BPF_MAP_DELETE_ELEM 通過key從指定的map中找到元素並且刪除
BPF_MAP_GET_NEXT_KEY 通過key從指定的map中找到元素,並且返回下個key值

 

eBPF 追蹤的工作原理:

 

 eBPF 的執行需要三步:

  • 從用戶跟蹤程序生成 BPF 字節碼;
  • 加載到內核中運行;
  • 向用戶空間輸出結果

 

SystemTap 和 sysdig

SystemTap 也是一種可以通過腳本進行自由擴展的動態追蹤技術。

在 eBPF 出現之前,SystemTap 是 Linux 系統中,功能最接近 DTrace 的動態追蹤機制

所以,從穩定性上來說,SystemTap 只在 RHEL 系統中好用,在其他系統中則容易出現各種異常問題。

當然,反過來說,支持 3.x 等舊版本的內核,也是 SystemTap 相對於 eBPF 的一個巨大優勢。

sysdig 則是隨着容器技術的普及而誕生的,主要用於容器的動態追蹤。

sysdig 匯集了一些列性能工具的優勢,可以說是集百家之所長。

這個公式來表示 sysdig 的特點: sysdig = strace + tcpdump + htop + iftop + lsof + docker inspect

 

如何選擇追蹤工具

  1. 在不需要很高靈活性的場景中,使用 perf 對性能事件進行采樣,然后再配合火焰圖輔助分析,就是最常用的一種方法;
  2. 而需要對事件或函數調用進行統計分析(比如觀察不同大小的 I/O 分布)時,就要用 SystemTap 或者 eBPF,通過一些自定義的腳本來進行數據處理

 


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM