高性能：7-可用於CPU分析的BPF工具【bpf performance tools讀書筆記】

可用於CPU分析的BPF工具，見下圖標註的這些命令

下表的這些工具備些是屬於BCC或者bpftrace，或爲這本書建立的。一些工具同時出如今BCC和bpftrace中。下表出了本節介紹的工具的來源(BT是bpftrace的縮寫。)

 

Tool 工具名稱	Source 來源	Target 功效/目標	Description 描述
execsnoop	BCC/BT	Sched	Lists new   process execution 列出新進程的執行
exitsnoop	BCC	Sched	Shows process   lifespan and exit reason 顯示進程壽命和退出緣由
runqlat	BCC/BT	Sched	Summarizes CPU   run queue latency 總結CPU運行隊列延遲狀況
runqlen	BCC/BT	Sched	Summarizes CPU   run queue length 總結CPU運行隊列長度
runqslower	BCC	Sched	Prints run   queue waits slower than a threshold 打印等待時間慢於閾值的運行隊列(單位us)
cpudist	BCC	Sched	Summarizes   on-CPU time 彙總on-CPU的時間
cpufreq	Book	CPUs	Samples CPU   frequency by process 按進程採樣CPU頻率
profile	BCC	CPUs	Samples CPU   stack traces 採樣CPU堆棧跟蹤
offcputime	BCC/book	Sched	Summarizes   off-CPU stack traces and times 彙總off-CPU堆棧跟蹤和時間
syscount	BCC/BT	Syscalls	Counts system   calls by type and process 按類型和過程統計syscall系統調用
argdist	BCC	Syscalls	Can be used   for syscall analysis 能夠用於系統調用分析
trace	BCC	Syscalls	Can be used   for syscall analysis 能夠用於系統調用分析
funccount	BCC	Software	Counts   function calls 計算函數調用
softirqs	BCC	Interrupts	Summarizes   soft interrupt time 彙總軟中斷時間
hardirqs	BCC	Interrupts	Summarizes   hard interrupt time 彙總硬中斷時間
smpcalls	Book	Kernel	Times SMP   remote CPU calls 統計SMP遠程CPU調用的時間
llcstat	BCC	PMCs	Summarizes LLC   hit ratio by process 按進程彙總LLC命中率

execsnoop

經過exec() syscall 系統調用來跟蹤新進程。

能夠發現消耗CPU資源的短暫進程的問題，還能夠用於調試軟件的執行，包括應用程序啓動腳本。

該工具捕獲了用戶使用SSH登陸系統並啓動了包括sshd、groups、mesg在內的進程的瞬間。它還顯示了來自系統活動記錄器sar的過程，包括將指標寫入其日誌，包括sa1和sadc。

 

咱們可使用execsnoop查找消耗資源的高速率的短時間進程，一般它們可能運行時間很短很難經過top之類的來發現，可是使用execsnoop很容易發現它。

execsnoop已用於調試許多生產問題，例如：來自後臺做業的干擾，應用程序啓動緩慢或失敗，容器啓動緩慢或失敗，等等。

 

execsnoop的工做原理：

跟蹤execve系統調用(經常使用的exec(2)變體)，並顯示execve(2)參數和返回值的詳細信息。這將捕獲遵循fork(2)/clone(2)-> exec(2)順序的新進程，以及 re-exec(2)的進程。

 

有個特殊狀況：一些應用程序在不調用exec(2)的狀況下建立新進程，例如，在使用fork(2)或單獨克隆(2)建立工做進程池時。由於它們不調用execve(2)，因此execsnoop輸出中不包括這些。這種狀況應該不常見:應用程序應該建立工做線程池，而不是進程。 【舉例子： 咱們登陸到redis-cli後再執行的其它的命令，execsnoop就沒法抓取到】

 

因爲進程執行速率預計相對較低(<1000/秒)，所以該工具的開銷能夠忽略不計。

 

這裏再介紹一個來自Netflix的一個真實問題，我使用execnoop進行了調試。這發生在一個用於微基準測試的服務器上，可是基準測試結果顯示出太多的差別是不可信任的。當系統被認爲是空閒的時候，我運行了execnoop，發現它不是！這些程序每啓動一秒鐘，就會擾亂咱們的基準。結果發現，這是一個配置錯誤的服務，它試圖每秒鐘啓動一次，失敗，而後從新啓動。一旦服務被停用，這些進程就中止了(正如使用execnoop所確認的那樣)，而後基準數就變得一致了。

 

 

 

⇒  execsnoop --help

usage: execsnoop [-h] [-T] [-t] [-x] [-q] [-n NAME] [-l LINE]

                 [--max-args MAX_ARGS]

 

Trace exec() syscalls

 

optional arguments:

  -h, --help            show this help message and exit

  -T, --time            include time column on output (HH:MM:SS)

  -t, --timestamp       include timestamp on output

  -x, --fails           include failed exec()s

  -q, --quote           Add quotemarks (") around arguments.

  -n NAME, --name NAME  only print commands matching this name (regex), any arg

  -l LINE, --line LINE  only print commands where arg contains this line (regex)

  --max-args MAX_ARGS   maximum number of arguments parsed and displayed,defaults to 20

 

examples:

    ./execsnoop           # trace all exec() syscalls

    ./execsnoop -x        # include failed exec()s

    ./execsnoop -T        # include time (HH:MM:SS)

    ./execsnoop -t        # include timestamps

    ./execsnoop -q        # add "quotemarks" around arguments

    ./execsnoop -n main   # only print command lines containing "main"

    ./execsnoop -l tpkg   # only print command where arguments contains "tpkg"

 

 

exitsnoop

exitsnoop是一個BCC工具，可跟蹤進程退出的時間，顯示進程的使用期限和退出緣由。期限是從進程建立到終止的時間，而且包括CPU的開啓和關閉時間。

像execsnoop同樣，exitsnoop能夠幫助調試短時間進程的問題，並提供不一樣的信息來幫助理解此類工做負載。例如：

 

 

此輸出顯示退出了許多短時間進程，例如cmake，sh和make,這代表一個軟件版本正在運行。1.00秒後，sleep進程成功退出(退出代碼0)，而因爲KILL信號，另外一個sleep進程在7.31秒後退出。這也捕獲了221.25秒後退出的「 DOM Worker」線程。

 

該工具經過檢測 sched:sched_process_exit 跟蹤點及其參數來工做，而且還使用bpf_get_current_task()，以即可以從任務結構中讀取開始時間(不穩定的接口詳細信息)。因爲此跟蹤點不多觸發，所以該工具的開銷能夠忽略不計。

 

本人的實戰截圖：

runqlat

runqlat是一個BCC和bpftrace工具，用於測量CPU調度程序延遲，一般稱爲運行隊列延遲(即便再也不使用運行隊列實現)。這對於識別和量化CPU飽和問題頗有用，在CPU飽和問題中，對CPU資源的需求超出了服務能力。runqlat度量的指標是每一個線程(任務)等待其打開CPU所花費的時間。

 

下圖顯示了在48核CPU生產API實例上運行的BCC runqlat在系統範圍內的CPU利用率約爲42％(能夠用top命令查看到CPU的利用率)。runqlat的參數爲10 1，表示以設置10秒間隔，僅輸出一次：

此輸出代表，在大多數狀況下，線程等待的時間少於15微秒，直方圖中的模式介於2到15微秒之間。這是相對較快的(健康系統的一個示例)，而且對於運行在42％CPU利用率上的系統來講是預期的。在此示例中，有時運行隊列延遲高達8到16毫秒存儲桶，但這些異常值是異常的。

 

runqlat的原理：

經過檢測調度程序喚醒和上下文切換事件來肯定從喚醒到運行的時間。注意： 這些事件在繁忙的生產系統上可能很是頻繁，每秒超過一百萬個事件。即便對BPF進行了優化，以這些速率，即便每一個事件增長一微秒也會致使明顯的開銷。須要當心使用runqlat這個工具。

示例：若是您在一個10核的系統上的上下文切換速率爲1M/sec，則每一個上下文切換增長1微秒將消耗10％的CPU資源(計算方法: 100％×(1×1000000/10×1000000) )。有關BPF開銷的一些實際測量值，請參見第18章，每一個事件一般小於一微秒。

一個使用runqlat診斷案例

在一個36核CPU的構建服務器進行軟件構建操做，其中並行做業的數量被錯誤地設置爲72，從而致使CPU超載。觀測到的截圖以下：

如今的分佈是三模態，最慢的模式以8到16毫秒的桶爲中心.這顯示了線程的大量等待(小於15微秒內算健康指標)。

能夠直接從其餘工具和指標中識別出此特定問題。例如，sar能夠顯示CPU利用率(-u)和運行隊列指標(-q)

能夠看到，當前系統 CPU idle空閒爲0， 全負荷工做。 另外， runq-sz平均運行隊列大小爲72(包括正在運行和可運行)，也大幅超過了可用的36個CPU。

runqlen

runqlen是一個BCC和bpftrace工具，用於對CPU運行隊列的長度進行採樣，計算有多少任務在等待輪到他們，並將其顯示爲線性直方圖。這能夠用來進一步描述運行隊列延遲的問題或做爲更便宜的近似值。

 

下圖顯示了在48個CPU生產API實例上運行的BCC的runqlet，該實例在系統範圍內的CPU利用率約爲42％(與先前在runqlat中顯示的實例相同)。runqlen的參數爲 10 1，以設置10秒間隔，僅輸出一次：

這代表在大多數狀況下，運行隊列長度爲零，這意味着線程無需等待輪到他們。

 

我將運行隊列長度描述爲輔助性能指標，將運行隊列延遲描述爲主要性能。與長度不一樣，延遲會直接和成比例地影響性能。想象一下在雜貨店加入結賬行。對您來講更重要的是：線路的長度或您實際花費的等待時間？runqlat更重要。那麼，爲何要使用runqlen？

 

首先，可使用runqlen進一步描述在runqlat中發現的問題，並解釋延遲如何變高。其次，runqlen採用99赫茲的定時採樣，而runqlat跟蹤調度程序事件。與runqlat的調度程序跟蹤相比，此定時採樣的開銷可忽略不計。對於24x7全天候監控，最好先使用runqlen來識別問題(由於運行起來更便宜)，而後再使用runqlat臨時量化延遲。

四線程，一個CPU的一個示例：

在此示例中，將四個繁忙線程的CPU工做負載綁定到CPU0。執行runqlen -C以顯示每一個CPU的直方圖：

CPU 0上的運行隊列長度爲三個：一個線程在CPU上等待三個線程。此每一個CPU的輸出對於檢查調度程序平衡很是有用。

 

 

小實驗：

咱們執行5次這個單行命令taskset -c 0 sh -c 'while :; do :; done' & ，這個循環操做綁定在cpu0上運行，而後執行 runqlen能夠看到以下結果，明顯能夠看到cpu0上有不少運行隊列的堆積，而cpu1上堆積基本都是0。

runqslower

runqslower是一個BCC工具，它列出了運行隊列等待時間超過可配置閾值的實例，並顯示了遭受等待時間及其持續時間的過程。

 

如下示例來自當前在系統範圍內以45％CPU利用率運行的48 CPU生產API實例：

此輸出代表，在13秒的時間內，   有10個運行隊列等待時間超過默認閾值10000微秒(10毫秒)的狀況。對於具備55％空閒CPU餘量的服務器來講，這彷佛使人驚訝，但這是一個繁忙的多線程應用程序，在調度程序能夠將線程遷移到空閒CPU以前，運行隊列可能不平衡。該工具能夠確認受影響的應用程序。

 

該工具當前經過將kprobes用於內核函數ttwu_do_wakeup()，wake_up_new_task()和finish_task_switch() 來工做。未來的版本應使用相似於runqlat的bpftrace版本的代碼切換到調度程序跟蹤點。開銷與runqlat類似；因爲kprobes的成本，即便在runqslower不輸出任何輸出的狀況下，它也會在繁忙的系統上引發明顯的開銷。

cpudist

cpudist是一個BCC工具，用於顯示每一個線程喚醒的CPU時間分佈。這可用於幫助表徵CPU工做負載，爲之後的調整和設計決策提供詳細信息。

例如，從一個48 核CPU生產實例中：

此輸出代表生產應用程序一般僅在CPU上花費很短的時間：從0到127微秒。

 

下面的圖，這是一個CPU繁重的工做負載，具備比可用CPU更多的繁忙線程，而且具備以毫秒(-m)爲單位的直方圖：

如今有一種CPU持續時間從4到15毫秒的模式：這極可能是線程耗盡了調度程序的時間量，而後遇到了非自願的上下文切換。

 

該工具用於幫助瞭解Netflix的生產變化，其中機器學習應用程序開始運行的速度快了三倍。perf命令用於顯示上下文切換速率已下降，而cpudist用於解釋其影響：應用程序如今一般在上下文切換之間運行兩到四毫秒，而更早的時候只能在0到3微秒之間運行，而後再被上下文切換中斷。

 

注意：

cpudist經過跟蹤調度程序上下文切換事件來工做，該事件在繁忙的生產工做負載上很是頻繁(超過一百萬個事件/秒)。與runqlat同樣，此工具的開銷可能很大，所以請謹慎使用。

root@dba-test:~|⇒  cpudist --help

usage: cpudist [-h] [-O] [-T] [-m] [-P] [-L] [-p PID] [interval] [count]

 

Summarize on-CPU time per task as a histogram.

 

positional arguments:

  interval            output interval, in seconds

  count               number of outputs

 

optional arguments:

  -h, --help          show this help message and exit

  -O, --offcpu        measure off-CPU time   # 只顯示CPU之外的時間，而不是CPU上的時間

  -T, --timestamp     include timestamp on output

  -m, --milliseconds  millisecond histogram

  -P, --pids          print a histogram per process ID  # 每一個進程打印一個直方圖

  -L, --tids          print a histogram per thread ID

  -p PID, --pid PID   trace this PID only

 

examples:

    cpudist              # summarize on-CPU time as a histogram

    cpudist -O           # summarize off-CPU time as a histogram

    cpudist 1 10         # print 1 second summaries, 10 times

    cpudist -mT 1        # 1s summaries, milliseconds, and timestamps

    cpudist -P           # show each PID separately

    cpudist -p 185       # trace PID 185 only

cpufreq

這是個bpftrace腳本文件，不在BCC工具集內。 我的認爲只要大體瞭解下這個命令便可。

 

cpufreq對CPU頻率進行採樣，並將其顯示爲系統範圍的直方圖，並帶有每一個進程的名稱直方圖。這僅適用於更改頻率的CPU縮放調節器，例如節電，並可用於肯定應用程序運行的時鐘速度。

profile

profile是一個BCC工具，它以必定的時間間隔對堆棧跟蹤進行採樣，並報告堆棧跟蹤的頻率計數。這是BCC中瞭解CPU消耗的最有用的工具，由於它總結了消耗CPU資源的幾乎全部代碼路徑。因爲事件率固定爲能夠調整的採樣率，所以它也能夠以相對可忽略的開銷使用。

根據profile的結果，咱們能夠繪製火焰圖

$ profile -af 30 > out.stacks01

$ git clone https://github.com/brendangregg/FlameGraph

$ cd FlameGraph

$ ./flamegraph.pl --color=java < ../out.stacks01 > out.svg

而後便可輸出一幅火焰圖。

使profile與其餘CPU探查器不一樣的緣由在於，爲了提升效率，此頻率計數是在內核空間中計算的。其餘基於內核的探查器，例如perf，會將每一個採樣的堆棧跟蹤發送到用戶空間，在該用戶跟蹤中將其後處理爲摘要。這可能會佔用大量CPU資源，而且取決於調用，它還可能涉及文件系統和磁盤I/O來記錄樣本。profile避免了這些費用。

root@dba-test:~|⇒ profile --help

usage: profile [-h] [-p PID | -L TID] [-U | -K] [-F FREQUENCY | -c COUNT] [-d]

               [-a] [-I] [-f] [--stack-storage-size STACK_STORAGE_SIZE]

               [-C CPU]

               [duration]

 

Profile CPU stack traces at a timed interval

 

positional arguments:

  duration              duration of trace, in seconds

 

optional arguments:

  -h, --help            show this help message and exit

  -p PID, --pid PID     profile process with this PID only

  -L TID, --tid TID     profile thread with this TID only

  -U, --user-stacks-only    show stacks from user space only (no kernel space stacks)

  -K, --kernel-stacks-only   show stacks from kernel space only (no user space stacks)

  -F FREQUENCY, --frequency FREQUENCY     sample frequency, Hertz

  -c COUNT, --count COUNT  sample period, number of events

  -d, --delimited       insert delimiter between kernel/user stacks

  -a, --annotations     add _[k] annotations to kernel frames

  -I, --include-idle    include CPU idle stacks

  -f, --folded          output folded format, one line per stack (for flame graphs)

  --stack-storage-size STACK_STORAGE_SIZE

                        the number of unique stack traces that can be stored and displayed (default 16384)

  -C CPU, --cpu CPU     cpu number to run profile on

 

examples:

    ./profile             # profile stack traces at 49 Hertz until Ctrl-C

    ./profile -F 99       # profile stack traces at 99 Hertz

    ./profile -c 1000000  # profile stack traces every 1 in a million events

    ./profile 5           # profile at 49 Hertz for 5 seconds only

    ./profile -f 5        # output in folded format for flame graphs

    ./profile -p 185      # only profile process with PID 185

    ./profile -L 185      # only profile thread with TID 185

    ./profile -U          # only show user space stacks (no kernel)

    ./profile -K          # only show kernel space stacks (no user)

offcputime

offcputime是一個BCC和bpftrace工具，用於總結阻塞線程和關閉CPU所花費的時間，並顯示堆棧跟蹤信息以說明緣由。

對於CPU分析，此工具說明了爲何線程未在CPU上運行。

與profile對應；在它們之間，它們顯示了線程在系統上花費的所有時間：使用profile的CPU時間和使用offcputime的CPU時間。

offcputime已用於查找各類生產問題，包括查找在鎖獲取中阻塞的意外時間以及負責的堆棧跟蹤。

注意：

offcputime經過檢測上下文切換並記錄從線程離開CPU到返回CPU的時間以及堆棧跟蹤來工做。爲了提升效率，在內核上下文中對時間和堆棧跟蹤進行了頻率計數。可是，上下文切換事件可能會很是頻繁，而且對於繁忙的生產工做負載，此工具的開銷可能會變得很是大(例如，> 10％)。該工具最好只在短期內運行，以最大程度地減小生產影響。

offCPU time火焰圖

與profile同樣，offcputime的輸出可能很是冗長，以致於您能夠發現最好將它做爲火焰圖進行檢查。能夠將offcputime可視化爲非CPU時間火焰圖。

 

相關繪圖的命令以下：

# offcputime -fKu 5 > out.offcputime01.txt

$ flamegraph.pl --hash --bgcolors=blue --title="Off-CPU Time Flame Graph" < out.offcputime01.txt > out.offcputime01.svg

funccount

funccount是一種BCC工具，能夠對函數和其餘事件進行頻率計數。

它可用於爲軟件CPU使用狀況提供更多上下文，顯示調用哪些函數以及調用頻率。profile可能可以顯示某個功能在CPU上很熱，但沒法解釋爲何：該功能是否運行緩慢，或者每秒是否被簡單調用了數百萬次。

 

TIPS：profile不能輕易解釋這一點。包括profile在內的探查器對CPU指令指針進行採樣，所以與該函數的反彙編進行比較可能會顯示該函數是卡在循環中仍是被調用屢次。

 

例如，經過匹配以 tcp_ 開頭的功能，能夠對繁忙的生產實例上的內核TCP功能進行頻率計數：

可使用-i 1 使其每1秒輸出一次。例如，較早的profile輸出顯示函數get_page_from_freelist()在CPU上很熱。是由於它常常被調用仍是由於它運行緩慢？能夠用以下命令來測量其每秒速率：

這經過使用函數的動態跟蹤來進行：內核函數使用kprobes，用戶級函數使用uprob。此工具的開銷與功能的速率有關。某些函數(例如malloc() 和get_page_from_freelist() )每每會頻繁發生，所以對其進行跟蹤可能會大大下降目標應用程序的速度，超過10％，請謹慎使用。

softirqs

softirqs是一個BCC工具，它顯示了花費在soft IRQ(軟中斷)所花費的時間。

能夠經過不一樣的工具輕鬆得到系統範圍的軟中斷時間。例如，mpstat將其顯示爲％soft。也有 /proc/softirqs 顯示軟IRQ事件的計數。

BCC softirqs工具的不一樣之處在於，它能夠顯示每一個軟IRQ的時間，而不是事件計數。

 

例如，從一個48 CPU生產實例和一個10秒的跟蹤中：

此輸出顯示，花費在net_rx花費的時間最多，總計1358毫秒。這很重要，由於在該48 CPU系統上，它佔CPU時間的3％。

 

softirqs經過使用irq:softirq_enter和irq:softirq_exit跟蹤點來工做。該工具的開銷與事件發生率有關，這對於繁忙的生產系統和較高的網絡數據包發生率可能會很高。謹慎使用並檢查開銷。

hardirqs

hardirqs是一個BCC工具，它顯示了花費在hard IRQ(硬中斷)所花費的時間。

硬中斷中的系統級時間能夠從其餘工具輕鬆得到。例如，mpstat將其顯示爲％irq。也有 /proc/interrupts 顯示hard IRQ事件的計數。

 

BCC hardirqs工具的不一樣之處在於，它能夠顯示每一個硬IRQ的時間，而不是事件計數。

下面是mpstat -P ALL 1 的部分截圖(這臺ecs的負載很低)

hardirqs能夠提供CPU分析器不可見的CPU使用狀況信息。有關缺乏硬件PMU的雲實例的性能分析，請參見第6.2.4節的內部部分。