Linux性能優化實戰學習筆記：第五十講

時間 2019-11-06

原文原文鏈接

1、上節回顧

上一節，我以 ksoftirqd CPU 使用率高的問題爲例，帶你一塊兒學習了內核線程 CPU 使用率高時的分析方法。先簡單回顧一下。node

當碰到內核線程的資源使用異常時，不少經常使用的進程級性能工具，並不能直接用到內核線程上。這時，咱們就可使用內核自帶的 perf 來觀察它們的行爲，找出熱點函數，進一步定位性能瓶
頸。不過，perf 產生的彙總報告並不直觀，因此我一般也推薦用火焰圖來協助排查。緩存

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

動態追蹤技術，經過探針機制，來採集內核或者應用程序的運行信息，從而能夠不用修改內核和應用程序的代碼，就得到豐富的信息，幫你分析、定位想要排查的問題。框架

以往，在排查和調試性能問題時，咱們每每須要先爲應用程序設置一系列的斷點（好比使用GDB），而後以手動或者腳本（好比 GDB 的 Python 擴展）的方式，在這些斷點處分析應用程
序的狀態。或者，增長一系列的日誌，從日誌中尋找線索。函數

不過，斷點每每會中斷應用的正常運行；而增長新的日誌，每每須要從新編譯和部署。這些方法雖然在今天依然普遍使用，但在排查複雜的性能問題時，每每耗時耗力，更會對應用的正常運行
形成巨大影響。工具

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

而動態追蹤技術的出現，就爲這些問題提供了完美的方案：它既不須要中止服務，也不須要修改應用程序的代碼；全部一切還按照原來的方式正常運行時，就能夠幫你分析出問題的根源。
同時，相比以往的進程級跟蹤方法（好比 ptrace），動態追蹤每每只會帶來很小的性能損耗（一般在 5% 或者更少）。學習

既然動態追蹤有這麼多好處，那麼，都有哪些動態追蹤的方法，又該如何使用這些動態追蹤方法呢？今天，我就帶你一塊兒來看看這個問題。因爲動態追蹤涉及的知識比較多，我將分爲上、下兩
篇爲你講解，先來看今天這部份內容。測試

2、動態追蹤

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

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

雖然直到今天，DTrace 自己依然沒法在 Linux 中運行，但它一樣對 Linux 動態追蹤產生了巨大的影響。不少工程師都嘗試過把 DTrace 移植到 Linux 中，這其中，最著名的就是 RedHat 主推的 SystemTap。

同 DTrace 同樣，SystemTap 也定義了一種相似的腳本語言，方便用戶根據須要自由擴展。不過，不一樣於 DTrace，SystemTap 並無常駐內核的運行時，它須要先把腳本編譯爲內核模塊，
而後再插入到內核中執行。這也致使 SystemTap 啓動比較緩慢，而且依賴於完整的調試符號表。

總的來講，爲了追蹤內核或用戶空間的事件，Dtrace 和 SystemTap 都會把用戶傳入的追蹤處理函數（通常稱爲 Action），關聯到被稱爲探針的檢測點上。這些探針，實際上也就是各類動態追
蹤技術所依賴的事件源。

3、動態追蹤的事件源

根據事件類型的不一樣，動態追蹤所使用的事件源，能夠分爲靜態探針、動態探針以及硬件事件等三類。它們的關係以下圖所示：

其中，硬件事件一般由性能監控計數器 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。

4、動態追蹤機制

而在這些探針的基礎上，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。

除此以外，還有不少內核外的工具，也提供了豐富的動態追蹤功能。最多見的就是前面提到的SystemTap，咱們以前屢次使用過的 BCC（BPF Compiler Collection），以及經常使用於容器性能
分析的 sysdig 等。

而在分析大量事件時，使用咱們上節課提到的火焰圖，能夠將大量數據可視化展現，讓你更直觀發現潛在的問題。

接下來，我就經過幾個例子，帶你來看看，要怎麼使用這些機制，來動態追蹤內核和應用程序的執行狀況。如下案例仍是基於 Ubuntu 18.04 系統，一樣適用於其餘系統。

注意，如下全部命令都默認以 root 用戶運行，若是你用普通用戶身份登錄系統，請運行 sudo su root 命令切換到 root 用戶。

5、ftrace

咱們先來看 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 命令爲例，帶你一塊兒看看 ftrace 的使用方法。

爲了列出文件，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

實際測試代碼以下：

[root@luoahong tracing]# cat available_tracers
blk function_graph wakeup_dl wakeup_rt wakeup function nop
[root@luoahong tracing]# 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

[root@luoahong tracing]# echo do_sys_open > set_graph_function
[root@luoahong tracing]# echo funcgraph-proc > trace_options
-bash: echo: write error: Invalid argument
[root@luoahong tracing]# echo function_graph > current_tracer
[root@luoahong tracing]# echo funcgraph-proc > trace_options
[root@luoahong tracing]# echo 1 > tracing_on
[root@luoahong tracing]# 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
[root@luoahong tracing]# 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    |    }
...

實際測試代碼以下：

[root@luoahong tracing]# 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   |    }
...

實際測試代碼以下：

[root@luoahong ~]# 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 ，就能夠跟蹤到它的執行過程。