系統性能分析從入門到進階
作者 | 勿非
本文以系統為中心, 結合日常工作和用例, 由淺入深地介紹了效能分析的一些方法和體會, 希望對想了解系統性能分析的同學有所幫助。
入門篇
資源角度
USE
產品跑在系統的各種資源上面, 從系統資源的角度入門效能分析是個不錯的選擇, 我們以業界知名大牛 Brendan Gregg 的 USE 方法開始, USE 特點就是簡單有效適合入門, 用 Brendan 的話描述 USE 的效果:
I find it solves about 80% of server issues with 5% of the effort.
USE 從系統資源的角度, 包括但不限於 CPU, 記憶體, 磁碟, 網路等, 關注以下3個方面:
• Utilization (U): as a percent over a time interval. eg, "one disk is running at 90% utilization". 大多數情況可以合理推測利用率高可能會影響效能
• Saturation (S): as a queue length. eg, "the CPUs have an average run queue length of four". 資源競爭的激烈程度
• Errors (E). scalar counts. eg, "this network interface has had fifty late collisions". Errors 相對直觀
CPU
對於 CPU, 主要關注以下指標:
• Utilization. CPU 的利用率
• Saturation. 可以是 load average, runqueue length, sched latency 等
CPU 利用率用 top 看下:
top - 17:13:49 up 83 days, 23:10, 1 user, load average: 433.52, 422.54, 438.70 Tasks: 2765 total, 23 running, 1621 sleeping, 0 stopped, 34 zombie %Cpu(s): 23.4 us, 9.5 sy, 0.0 ni, 65.5 id, 0.7 wa, 0.0 hi, 1.0 si, 0.0 st
CPU 利用率拆分成了更細粒度的幾部分:
• us, sys, ni - 對應 un-niced user, kernel, niced user 的 CPU 利用率
• id, wa - 對應到 idle, io wait 的比例, io wait 本質上也是一種 idle, 區別在於對應 cpu 上有等待 io 的任務
• hi, si - 對應 hardirq, softirq 的比例
• st - 因為超賣等原因, hypervisor 從該 vm 偷走的時間 (todo: docker)
繼續看 load average, 3 個數值分別對應到系統 1/5/15 分鐘內的系統平均 load, load 是個比較模糊的概念, 可以簡單認為是對資源有需求的任務數, 包括 on cpu, runnable 的任務, 也包括等待 IO 及任意 D 狀態的任務. load 使用取樣的方式, 每隔 5 秒取樣一樣, 越近的取樣權重越大, 這樣從 1/5/15 的趨勢可以看出系統壓力的變化。
load average: 433.52, 422.54, 438.70
在這臺 128 個 CPU 的機器上, loadavg 看起來有些偏高, 但是具體影響目前不得而知, 效能低是相對具體目標而言的, load 高只是現象, 它可能相關也可能無關, 但至少是值得注意的。
再看下 dstat 關於任務狀態的統計:
• run - 對應到/proc/stat 裡面的 procs_running, 也就是 runnable 任務數
• blk - 對應到/proc/stat 裡面的 procs_blocked, 阻塞在 I/O 的任務數
實際上和 loadavg 沒有本質區別, 只是 load 模糊了 runnable 和 D 狀態, 同時 load 使用 1/5/15 分鐘的力度, 而 dstat 可以使用更細粒度, 如果只看某一時間點用 load, 如果要觀察長時間的變化使用 dstat (/proc/stat)。
#dstat -tp
----system---- ---procs---
time |run blk new
07-03 17:56:50|204 1.0 202
07-03 17:56:51|212 0 238
07-03 17:56:52|346 1.0 266
07-03 17:56:53|279 5.0 262
07-03 17:56:54|435 7.0 177
07-03 17:56:55|442 3.0 251
07-03 17:56:56|792 8.0 419
07-03 17:56:57|504 16 152
07-03 17:56:58|547 3.0 156
07-03 17:56:59|606 2.0 212
07-03 17:57:00|770 0 186
記憶體
這裡主要關注記憶體容量方面, 不關注訪存的效能。
• Utilization. 記憶體利用率
• Saturation. 這裡主要考察記憶體回收演算法的效率
簡單的記憶體利用率用 free 命令:
• total - MemTotal + SwapTotal, 一般來說 MemTotal 會略小於真實的實體記憶體
• free - 未使用的記憶體. Linux 傾向於快取更多頁面以提高效能, 所以不能簡單通過 free 來判斷記憶體是否不足
• buff/cache - 系統快取, 一般不需要嚴格區分 buffer 和 cache
• available - 估計的可用實體記憶體大小
• used - 等於 total - free - buffers - cache
• Swap - 該機器上未配置
#free -g
total used free shared buff/cache available
Mem: 503 193 7 2 301 301
Swap: 0 0 0
更詳細的資訊可以直接去讀/proc/meminfo:
#cat /proc/meminfo
MemTotal: 527624224 kB
MemFree: 8177852 kB
MemAvailable: 316023388 kB
Buffers: 23920716 kB
Cached: 275403332 kB
SwapCached: 0 kB
Active: 59079772 kB
Inactive: 431064908 kB
Active(anon): 1593580 kB
Inactive(anon): 191649352 kB
Active(file): 57486192 kB
Inactive(file): 239415556 kB
Unevictable: 249700 kB
Mlocked: 249700 kB
SwapTotal: 0 kB
SwapFree: 0 kB
[...]
再來看下記憶體回收相關的資訊, sar 的資料主要從/proc/vmstat 採集, 主要關注:
• pgscank/pgscand - 分別對應 kswapd/direct 記憶體回收時掃描的 page 數
• pgsteal - 回收的 page 數
• %vmeff - pgsteal/(pgscank+pgscand)
要理解這些資料的具體含義, 需要對記憶體管理演算法有一定了解, 比如這裡的 pgscan/pgsteal 只是針對inactive list而言的, 在記憶體回收的時候可能還需要先把頁面從 active list 搬到 inactive list 等. 如果這裡有異常, 我們可以先把這當成入口, 再慢慢深入, 具體到這裡的%vmeff, 最好情況就是每個掃描的 page 都能回收, 也就是 vmeff 越高越好。
#sar -B 1
11:00:16 AM pgscank/s pgscand/s pgsteal/s %vmeff
11:00:17 AM 0.00 0.00 3591.00 0.00
11:00:18 AM 0.00 0.00 10313.00 0.00
11:00:19 AM 0.00 0.00 8452.00 0.00
I/O
儲存 I/O 的 USE 模型:
• Utilization. 儲存裝置的利用率, 單位時間內裝置在處理 I/O 請求的時間
• Saturation. 佇列長度
我們一般關注這些部分:
• %util - 利用率. 注意即使達到 100%的 util, 也不代表裝置沒有效能餘量了, 特別地現在的 SSD 盤內部都支援併發. 打個比方, 一家旅館有 10 間房, 每天只要有 1 個房間入住, util 就是 100%。
• svctm - 新版 iostat 已經刪掉
• await/r_await/w_await - I/O 延遲, 包括排隊時間
• avgrq-sz - 平均 request size, 請求處理時間和大小有一定關係, 不一定線性
• argqu-sz - 評估 queue size, 可以用來判斷是否有積壓
• rMB/s, wMB/s, r/s, w/s - 基本語義
資源粒度
當我們判斷資源是否是瓶頸的時候, 只看系統級別的資源是不夠的, 比如可以用 htop 看下每個 CPU 的利用率, 目標任務執行在不同 CPU 上的效能可能相差很大。
記憶體也有類似情況, 執行 numastat -m
Node 0 Node 1 Node 2 Node 3
--------------- --------------- --------------- ---------------
MemTotal 31511.92 32255.18 32255.18 32255.18
MemFree 2738.79 131.89 806.50 10352.02
MemUsed 28773.12 32123.29 31448.69 21903.16
Active 7580.58 419.80 9597.45 5780.64
Inactive 17081.27 26844.28 19806.99 13504.79
Active(anon) 6.63 0.93 2.08 5.64
Inactive(anon) 12635.75 25560.53 12754.29 9053.80
Active(file) 7573.95 418.87 9595.37 5775.00
Inactive(file) 4445.52 1283.75 7052.70 4450.98
系統不一定就是物理機, 如果產品跑在 cgroup, 那麼這個 cgroup 是更需要關注的系統, 比如在空閒系統上執行如下命令:
#mkdir /sys/fs/cgroup/cpuset/overloaded
#echo 0-1 > /sys/fs/cgroup/cpuset/cpuset.cpus
#echo 0 > /sys/fs/cgroup/cpuset/cpuset.mems
#echo $$
#for i in {0..1023}; do /tmp/busy & done
此時從物理機級別看, 系統的 load 很高, 但是因為 cpuset 的限制, 競爭約束在 cpu 0 和 1 上, 對執行在其他 cpu 上的產品影響並不大。
#uptime
14:10:54 up 6 days, 18:52, 10 users, load average: 920.92, 411.61, 166.95
應用角度
系統資源和應用的效能可能會有某種關聯, 但是也可以更直接地從應用的角度出發定位問題:
• 應用能使用多少資源, 而不是系統提供了多少資源, 這裡面可能會有gap, 系統是個模糊的概念, 而應用本身卻相對具體. 以上面cpuset為例, 物理機是個系統, cpuset管理的資源也可以成為系統, 但是應用在cpuset裡面還是外面是確定的。
• 應用對資源的需求, 即使系統資源再多, 應用用不上效能也上不去, 也就是系統可能沒問題, 而是應用本身的原因。
以下面的myserv為例, 它的4個執行緒%cpu都達到了100, 這個時候再去分析整個系統的load什麼用處不大, 系統有再多的空閒cpu對myserv來說已經沒有意義。
#pidstat -p `pgrep myserv` -t 1
15:47:05 UID TGID TID %usr %system %guest %CPU CPU Command
15:47:06 0 71942 - 415.00 0.00 0.00 415.00 22 myserv
15:47:06 0 - 71942 0.00 0.00 0.00 0.00 22 |__myserv
...
15:47:06 0 - 72079 7.00 94.00 0.00 101.00 21 |__myserv
15:47:06 0 - 72080 10.00 90.00 0.00 100.00 19 |__myserv
15:47:06 0 - 72081 9.00 91.00 0.00 100.00 35 |__myserv
15:47:06 0 - 72082 5.00 95.00 0.00 100.00 29 |__myserv
常用命令
基本命令
基本命令一般用來讀取核心中記錄的各種統計資訊, 特別是/proc下面的各種檔案, 這裡簡單列舉部分:
• top - 提供了互動模式和batch模式, 不帶引數進入互動模式, 按下h鍵可以看到各種功能
• ps - 提供了各種引數檢視系統中任務的狀態, 比如ps aux或者ps -eLf, 很多引數可以在需要的時候檢視手冊
• free - 記憶體資訊
• iostat - I/O效能
• pidstat - 檢視程序相關的資訊, 上面已經介紹過
• mpstat - 可以檢視單獨cpu的利用率, softirq, hardirq個數等
• vmstat - 可以檢視虛擬記憶體及各種系統資訊
• netstat - 網路相關
• dstat - 可以檢視cpu/disk/mem/net等各種資訊, 這些stat命令哪個方便用哪個
• htop - 上面介紹過
• irqstat - 方便觀察中斷資訊
• sar/tsar/ssar - 收集和檢視系統執行的各種歷史資訊, 也提供實時模式
這裡舉個ps的例子, 我們監控mysqld服務, 當該程序使用的記憶體超過系統記憶體70%的時候, 通過gdb呼叫jemalloc的malloc_stats_print函式來分析可能的記憶體洩漏。
largest=70
while :; do
mem=$(ps -p `pidof mysqld` -o %mem | tail -1)
imem=$(printf %.0f $mem)
if [ $imem -gt $largest ]; then
echo 'p malloc_stats_print(0,0,0)' | gdb --quiet -nx -p `pidof mysqld`
fi
sleep 10
done
perf
perf是效能分析的必備工具, 它最核心的能力是能訪問硬體上的Performance Monitor Unit (PMU), 對分析CPU bound的問題很有幫助, 當然perf也支援各種軟體event. perf的主要能力包括:
• 通過取樣發現程式熱點
• 通過硬體PMU深入分析問題的根源, 特別是配合硬體上的優化
perf list可以列出支援的event, 我們可以通過perf來獲取cache misses, cycles等等。
#perf list | grep Hardware
branch-misses [Hardware event]
bus-cycles [Hardware event]
cache-misses [Hardware event]
cache-references [Hardware event]
cpu-cycles OR cycles [Hardware event]
instructions [Hardware event]
L1-dcache-load-misses [Hardware cache event]
L1-dcache-loads [Hardware cache event]
L1-dcache-store-misses [Hardware cache event]
L1-dcache-stores [Hardware cache event]
L1-icache-load-misses [Hardware cache event]
L1-icache-loads [Hardware cache event]
branch-load-misses [Hardware cache event]
branch-loads [Hardware cache event]
dTLB-load-misses [Hardware cache event]
iTLB-load-misses [Hardware cache event]
mem:<addr>[/len][:access] [Hardware breakpoint]
perf使用的時候一般會傳入以下引數:
• 通過-e指定感興趣的一個或多個event
• 指定取樣的範圍, 比如程序級別 (-p), 執行緒級別 (-t), cpu級別 (-C), 系統級別 (-a)
這裡使用預設的event看下程序31925的執行情況. 一個比較重要的資訊是insns per cycle (IPC), 也就是每個cycle能執行多少指令, 其他pmu event像cache misses, branch misses如果有問題最終都會反映到IPC上. 雖然沒有一個明確的標準, 但是下面0.09的IPC是比較低的, 有必要繼續深入。
#perf stat -p 31925 sleep 1
Performance counter stats for process id '31925':
2184.986720 task-clock (msec) # 2.180 CPUs utilized
3,210 context-switches # 0.001 M/sec
345 cpu-migrations # 0.158 K/sec
0 page-faults # 0.000 K/sec
4,311,798,055 cycles # 1.973 GHz
<not supported> stalled-cycles-frontend
<not supported> stalled-cycles-backend
409,465,681 instructions # 0.09 insns per cycle
<not supported> branches
8,680,257 branch-misses # 0.00% of all branches
1.002506001 seconds time elapsed
除了stat外, perf另一個可能更常用的方式是取樣來確定程式的熱點, 現在有如下程式:
void busy(long us) {
struct timeval tv1, tv2;
long delta = 0;
gettimeofday(&tv1, NULL);
do {
gettimeofday(&tv2, NULL);
delta = (tv2.tv_sec - tv1.tv_sec) * 1000000 + tv2.tv_usec - tv1.tv_usec;
} while (delta < us);
}
void A() { busy(2000); }
void B() { busy(8000); }
int main() {
while (1) {
A(); B();
}
return 0;
}
函式A和B執行時間的比例, perf的取樣結果和我們期望的2:8基本一致。
#perf record -g -e cycles ./a.out
#perf report
Samples: 27K of event 'cycles', Event count (approx.): 14381317911
Children Self Command Shared Object Symbol
+ 99.99% 0.00% a.out [unknown] [.] 0x0000fffffb925137
+ 99.99% 0.00% a.out a.out [.] _start
+ 99.99% 0.00% a.out libc-2.17.so [.] __libc_start_main
+ 99.99% 0.00% a.out a.out [.] main
+ 99.06% 25.95% a.out a.out [.] busy
+ 79.98% 0.00% a.out a.out [.] B
- 71.31% 71.31% a.out [vdso] [.] __kernel_gettimeofday
__kernel_gettimeofday
- busy
+ 79.84% B
+ 20.16% A
+ 20.01% 0.00% a.out a.out [.] A
strace
trace相對於取樣最大的優勢在於精度, trace能抓住每次操作, 這給除錯和理解帶來很大方便. strace專門用來trace系統呼叫。
strace通過捕獲所有的系統呼叫能快速幫助理解應用的某些行為, 這裡使用strace來看下上面提到的perf-record的實現, 很容易發現系統呼叫perf_event_open以及它的引數, 因為有128個cpu, 針對每個cpu都會呼叫一次該系統呼叫。
#strace -v perf record -g -e cycles ./a.out
perf_event_open({type=PERF_TYPE_HARDWARE, size=PERF_ATTR_SIZE_VER5, config=PERF_COUNT_HW_CPU_CYCLES, sample_freq=4000, sample_type=PERF_SAMPLE_IP|PERF_SAMPLE_TID|PERF_SAMPLE_TIME|PERF_SAMPLE_CALLCHAIN|PERF_SAMPLE_PERIOD, read_format=0, disabled=1, inherit=1, pinned=0, exclusive=0, exclusive_user=0, exclude_kernel=0, exclude_hv=0, exclude_idle=0, mmap=1, comm=1, freq=1, inherit_stat=0, enable_on_exec=1, task=1, watermark=0, precise_ip=0 /* arbitrary skid */, mmap_data=0, sample_id_all=1, exclude_host=0, exclude_guest=1, exclude_callchain_kernel=0, exclude_callchain_user=0, mmap2=1, comm_exec=1, use_clockid=0, context_switch=0, write_backward=0, namespaces=0, wakeup_events=0, config1=0, config2=0, sample_regs_user=0, sample_regs_intr=0, aux_watermark=0, sample_max_stack=0}, 51876, 25, -1, PERF_FLAG_FD_CLOEXEC) = 30
blktrace
iostat因為粒度太粗有的時候並不能很好地定位問題, blktrace通過跟蹤每個I/O, 並在I/O的關鍵路徑打樁, 可以獲得更精確的資訊, 從而幫忙分析問題. blktrace封裝了幾個命令:
• blktrace: 收集
• blkparse: 處理
• btt: 強大的分析工具
• btrace: blktrace/blkparse的一個簡單封裝, 相當於blktrace -d /dev/sda -o - | blkparse -i -
簡單看下blktrace的輸出, 裡面記錄了I/O路徑上的關鍵資訊, 特別地:
• 時間戳, 效能分析的關鍵資訊之一
• event, 第6列, 對應到I/O路徑上的關鍵點, 具體對應關係可以查詢相應手冊或原始碼, 理解這些關鍵點是除錯I/O效能的必要技能
• I/O sector. I/O請求對應的扇區和大小
$ sudo btrace /dev/sda
8,0 0 1 0.000000000 1024 A WS 302266328 + 8 <- (8,5) 79435736
8,0 0 2 0.000001654 1024 Q WS 302266328 + 8 [jbd2/sda5-8]
8,0 0 3 0.000010042 1024 G WS 302266328 + 8 [jbd2/sda5-8]
8,0 0 4 0.000011605 1024 P N [jbd2/sda5-8]
8,0 0 5 0.000014993 1024 I WS 302266328 + 8 [jbd2/sda5-8]
8,0 0 0 0.000018026 0 m N cfq1024SN / insert_request
8,0 0 0 0.000019598 0 m N cfq1024SN / add_to_rr
8,0 0 6 0.000022546 1024 U N [jbd2/sda5-8] 1
這是btt的一個輸出, 可以看到S2G的個數和延遲, 正常情況不應該出現這個問題, 這樣就找到了一條可以深入的線索。
$ sudo blktrace -d /dev/sdb -w 5
$ blkparse sdb -d sdb.bin
$ btt -i sdb.bin
==================== All Devices ====================
ALL MIN AVG MAX N
--------------- ------------- ------------- ------------- -----------
Q2Q 0.000000001 0.000014397 0.008275391 347303
Q2G 0.000000499 0.000071615 0.010518692 347298
S2G 0.000128160 0.002107990 0.010517875 11512
G2I 0.000000600 0.000001570 0.000040010 347298
I2D 0.000000395 0.000000929 0.000003743 347298
D2C 0.000116199 0.000144157 0.008443855 347288
Q2C 0.000118211 0.000218273 0.010678657 347288
==================== Device Overhead ====================
DEV | Q2G G2I Q2M I2D D2C
---------- | --------- --------- --------- --------- ---------
( 8, 16) | 32.8106% 0.7191% 0.0000% 0.4256% 66.0447%
---------- | --------- --------- --------- --------- ---------
Overall | 32.8106% 0.7191% 0.0000% 0.4256% 66.0447%
進階篇
大學教材
通過教程能夠系統地瞭解一門課的全貌, 網上搜到的大部分效能分析的教程都是基於Raj Jain的The Art of Computer Systems Performance Analysis, 這本書裡面主要包括幾個部分:
• Part I: AN OVERVIEW OF PERFORMANCE EVALUATION
• Part II: MEASUREMENT TECHNIQUES AND TOOLS
• Part III: PROBABILITY THEORY AND STATISTICS
• Part IV: EXPERIMENTAL DESIGN AND ANALYSIS
• Part V: SIMULATION
• Part VI: QUEUEING MODELS
書的重心放在performance analysis上面, 涉及較多概率和統計的計算, 另外rice大學的這個教程寫得挺不錯[1]。
技術部落格
• 參考文末[2]有時間可以都過一遍, 總的來說主要包括3個部分:
• 效能分析的方法集. 代表作 USE方法
• 效能資料的蒐集. 代表作 "工具大圖"
• 效能資料的視覺化. 代表作 火焰圖
• 文末連結[3]
• 文末連結[4]
• 文末連結[5]
知識結構
系統性能分析在深度和廣度上都有要求, 對底層包括OS和硬體, 以及一些通用能力要做到足夠深, 對上層產品的理解又需要有足夠的廣度, 近一年在混合雲親手摸過的產品估計不下二十款, 當然重點分析過的只有幾個。
作業系統
作業系統是系統分析的基礎, 不管是I/O, 記憶體, 網路, 排程, docker等等都離不開作業系統, 作業系統知識可以從Understanding the Linux Kernel開始, 這本書雖然老了但不妨礙理解OS的基本概念, 慢慢做到能閱讀核心文件和原始碼。
在適配某款arm平臺的時候發現, 在numa off的情況下:
• ecs綁在socket 0上效能好
• mysql綁在socket 1上效能好
能確定的是, 該平臺跨socket效能訪問不管是latency還是throughput和本地訪問都有較大差距, 所以一個合理的方向是跨socket的記憶體訪問, 如果有類似x86 pcm的話會比較直接, 但是該平臺上缺少該類pmu來檢視跨socket的資訊, 我們嘗試從OS的角度來回答這個問題。
首先通過將記憶體壓測工具跑在不同的socket/node上, 發現numa off表現出了和numa on相同的效能特徵, 和硬體產生確認該平臺numa off和on的實現在硬體上並沒有區別, 只是bios不傳遞numa資訊給作業系統, 這樣是可以知道實體地址在哪個socket/node上的。
接下來只要確定ecs/mysql的實體記憶體位置, 就可以用於判斷效能和跨socket的相關性. Linux在使用者態可以通過pagemap將虛擬地址對應到實體地址, 只需要稍加修改tools/vm/page-types.c就能拿到程序對應的所有實體地址. 經確認, 確實ecs/mysql的效能和它們使用的實體記憶體的位置強相關。最後要回答的是為什麼ecs和mysql表現恰好相反, 注意到ecs使用hugepage而mysql使用normal page, 有如下假設, 具體程式碼這裡不再列出。
• 系統啟動的時候, 實體記憶體加到夥伴系統是先socket 0後socket 1
• socket 1上的記憶體會被先分出來, 所以mysql分配的記憶體在socket 1. 特定叢集的機器不會隨意跑其他程序
• 在ecs的host上, 因為要分配的hugepage已經超過了socket 1上的所有記憶體, 所以後面分配的hugepage已經落在了socket 0
• hugepage的分配是後進先出, 意味著ecs一開始分配到的hugepage在socket 0, 而該機器資源並沒全部用完, 測試用的幾個ecs記憶體全落在了socket 0上, 所以將ecs程序綁到socket 0的效能更好
硬體知識
如果一直是x86架構, 事情會簡單很多, 一是x86的知識大家耳濡目染很久了, 多多少少都瞭解一些, 二是架構變化相對較小, 各種應用都適配較好, 需要調優的用例較少. 隨著各種新平臺的崛起, 它們效能各異, 對整個系統性能帶來的衝擊是巨大的, 這不是影響某個產品, 這影響的幾乎是所有產品. 最基本地, 我們要處理以下問題:
• 新的平臺上, 應用原有的很多假設被打破, 需要重新適配, 否則效能可能不及預期. 比如在Intel上面, 開關numa的效能差距不大, 在其他平臺上可能就不一樣
• 新的平臺要取代老的平臺, 就存在效能的比較. 由於平臺效能差異大並且差異點多, 雖然speccpu之類的benchmark能一定程度反應平臺整體的計算效能, 但很多時候還需要結合不同場景分別進行效能調優
• 不排除新平臺存在某種bug或者未知的feature, 都需要我們去摸索解決的辦法
資料分析
在收集了大量資料後, 經過資料分析可以放大資料的價值
• 資料提取. 利用各種工具比如awk/sed/perl等指令碼語言提取所需的資料
• 資料抽象. 從不同角度加工資料, 識別異常, 比如單機/叢集分別是什麼表現, 統計哪些值
• 視覺化. 視覺化是資料處理非常重要的能力, 一圖勝千言, 火焰圖就是最好的例子. 常用畫圖工具有gnuplot, excel等
比如分析MapReduce任務在10臺機器的叢集上的效能, 即使每臺機器都體現出一定的共性, 但是如果從叢集角度看的話則更加明顯, 也很容易驗證這種共性。
換種顯示方式則更加明顯, 很容易知道在不同階段的表現, 比如正常Map和Reduce階段cpu利用率也只有80%, 這個是否符合預期, 另外在Map和Reduce切換的時候, 系統idle很明顯, 會不會是潛在優化點。
如果有對照的話, 可以直觀地看不到不同表現, 特別是巨大的長尾時間有進一步優化的空間。
Benchmarking
Benchmarking是獲取效能指標最基本的手段, 也是測試常用的方法, 每個領域幾乎都有自己的一套測試用例. 對於benchmarking, 首先需要知道它測的是什麼. 以spec cpu2017為例, 它主要測試的是處理器, 記憶體子系統以及編譯器的效能, 那麼在測試的時候我們除了關注CPU型號, 還要考慮記憶體大小插法型號, 以及編譯器及其引數等等, 在做效能比對時也能清楚它的使用範圍。
Benchmark的一個特點是可重複性, spec.org做得很好的一點是上面有大量公佈的測試結果, 可以參考這些測試結果來驗證我們自己的測試方法引數是否合理. 如果想測試cpu2017, 第一件事就是先重做別人的測試, 直到能復現別人的資料, 這個過程可能會有很多收穫, 對benchmark也會有更多瞭解. 以intel 8160為例, 在硬體基本一致的情況下, 不經額外的配置自己環境cpu2017 integer rate只能跑到140, 而spec.org上面的測試用例能達到240, 效能逐步逼近240的過程, 也是深入理解cpu2017的過程。
關於效能資料, 首先想要強調的是有資料並不一定比沒資料強, 只有解釋過的資料才是有效資料, 沒解釋過的資料反而會引起不必要的誤判, 比如上面cpu2017的例子, 在做不同平臺效能對比的時候, 8160到底用140還是240呢, 得出的結論會十萬八千里. 再比如使用下面的命令測試某新平臺的記憶體延遲:
lat_mem_rd -P 1 -N 1 10240 512
測試出的延遲是7.4ns, 不加分析採用該結果就可能得出新平臺延遲太好的錯誤結論. 所以對待資料要足夠謹慎, 一般會有幾個階段:
- 在信任關係建立前, 對別人的資料保持謹慎. 一是有可能自己對這塊還沒有足夠理解, 二是需要測試報告提供足夠的資訊供他人做判斷。
- 相信自己的資料. 必須相信自己, 但是選擇相信自己的資料, 是因為有過詳細合理的分析。
- 相信別人的資料. 信任鏈建立之後, 以及自己有了足夠理解後, 選擇相信.
更多工具
ftrace
想要快速理解程式碼實現, 沒有什麼比列印呼叫路徑更直接了. ftrace可以用來解決2個問題:
• 誰呼叫了我. 這個只要在執行對應函式的時候拿到對應的棧就可以, 多種工具可以實現
• 我呼叫了誰. 這個是ftrace比較unique的功能
為了方便我們使用ftrace的wrapper trace-cmd, 假設我們已經知道I/O路徑會經過generic_make_request, 為了檢視完整的路徑我們可以這樣:
#trace-cmd record -p function --func-stack -l generic_make_request dd if=/dev/zero of=file bs=4k count=1 oflag=direct
通過report來檢視就一目瞭然了:
#trace-cmd report
cpus=128
dd-11344 [104] 4148325.319997: function: generic_make_request
dd-11344 [104] 4148325.320002: kernel_stack: <stack trace>
=> ftrace_graph_call (ffff00000809849c)
=> generic_make_request (ffff000008445b80)
=> submit_bio (ffff000008445f00)
=> __blockdev_direct_IO (ffff00000835a0a8)
=> ext4_direct_IO_write (ffff000001615ff8)
=> ext4_direct_IO (ffff0000016164c4)
=> generic_file_direct_write (ffff00000825c4e0)
=> __generic_file_write_iter (ffff00000825c684)
=> ext4_file_write_iter (ffff0000016013b8)
=> __vfs_write (ffff00000830c308)
=> vfs_write (ffff00000830c564)
=> ksys_write (ffff00000830c884)
=> __arm64_sys_write (ffff00000830c918)
=> el0_svc_common (ffff000008095f38)
=> el0_svc_handler (ffff0000080960b0)
=> el0_svc (ffff000008084088)
現在如果我們想繼續深入generic_make_request, 使用function_graph plugin:
$ sudo trace-cmd record -p function_graph -g generic_make_request dd if=/dev/zero of=file bs=4k count=1 oflag=direct
這樣就可以拿到整個呼叫過程 (report結果稍微整理過):
$ trace-cmd report
dd-22961 | generic_make_request() {
dd-22961 | generic_make_request_checks() {
dd-22961 0.080 us | _cond_resched();
dd-22961 | create_task_io_context() {
dd-22961 0.485 us | kmem_cache_alloc_node();
dd-22961 0.042 us | _raw_spin_lock();
dd-22961 0.039 us | _raw_spin_unlock();
dd-22961 1.820 us | }
dd-22961 | blk_throtl_bio() {
dd-22961 0.302 us | throtl_update_dispatch_stats();
dd-22961 1.748 us | }
dd-22961 6.110 us | }
dd-22961 | blk_queue_bio() {
dd-22961 0.491 us | blk_queue_split();
dd-22961 0.299 us | blk_queue_bounce();
dd-22961 0.200 us | bio_integrity_enabled();
dd-22961 0.183 us | blk_attempt_plug_merge();
dd-22961 0.042 us | _raw_spin_lock_irq();
dd-22961 | elv_merge() {
dd-22961 0.176 us | elv_rqhash_find.isra.9();
dd-22961 | deadline_merge() {
dd-22961 0.108 us | elv_rb_find();
dd-22961 0.852 us | }
dd-22961 2.229 us | }
dd-22961 | get_request() {
dd-22961 0.130 us | elv_may_queue();
dd-22961 | mempool_alloc() {
dd-22961 0.040 us | _cond_resched();
dd-22961 | mempool_alloc_slab() {
dd-22961 0.395 us | kmem_cache_alloc();
dd-22961 0.744 us | }
dd-22961 1.650 us | }
dd-22961 0.334 us | blk_rq_init();
dd-22961 0.055 us | elv_set_request();
dd-22961 4.565 us | }
dd-22961 | init_request_from_bio() {
dd-22961 | blk_rq_bio_prep() {
dd-22961 | blk_recount_segments() {
dd-22961 0.222 us | __blk_recalc_rq_segments();
dd-22961 0.653 us | }
dd-22961 1.141 us | }
dd-22961 1.620 us | }
dd-22961 | blk_account_io_start() {
dd-22961 0.137 us | disk_map_sector_rcu();
dd-22961 | part_round_stats() {
dd-22961 0.195 us | part_round_stats_single();
dd-22961 0.054 us | part_round_stats_single();
dd-22961 0.955 us | }
dd-22961 2.148 us | }
dd-22961 + 15.847 us | }
dd-22961 + 23.642 us | }
uftrace
uftrace在使用者態實現了一個類似ftrace的功能, 對需要快速理解使用者態的邏輯會有幫助, 但是需要加上-pg重新編譯原始碼, 詳情見[6]。
#gcc -pg a.c
#uftrace ./a.out
# DURATION TID FUNCTION
[ 69439] | main() {
[ 69439] | A() {
0.160 us [ 69439] | busy();
1.080 us [ 69439] | } /* A */
[ 69439] | B() {
0.050 us [ 69439] | busy();
0.240 us [ 69439] | } /* B */
1.720 us [ 69439] | } /* main */
BPF
BPF (eBPF) 是這幾年的熱點, 通過BPF幾乎可以看清系統的各個角落, 給診斷帶來了極大的方便. BPF不是一個工具, BPF是生產工具的工具, BPF工具編寫是效能分析必須掌握的技能之一。
這裡舉個使用BPF來分析QEMU I/O延遲的例子. 為了簡化問題, 先確保vm裡面的塊裝置只有fio在使用, fio控制裝置只有一個併發I/O, 這樣我們在host上選擇2個觀察點:
• tracepoint:kvm:kvm_mmio. host捕獲guest mmio操作, guest裡面最終通過寫該mmio傳送請求給host
• kprobe:kvm_set_msi. 因為guest裡面vdb使用msi中斷, 中斷最終通過該函式注入
因為host上有多個vm和虛擬盤需要區分, 使用以下資訊捕獲並且只捕獲我們關注的這個裝置:
• 只關注該qemu-kvm pid
• vbd mmio對應的gpa, 這個可以在guest裡面通過lspci獲得
對於kvm_set_msi, 使用如下資訊:
• struct kvm的userspace_pid, struct kvm對應的qemu-kvm程序
• struct kvm_kernel_irq_routing_entry的msi.devid, 對應到pci裝置id
#include <linux/kvm_host.h>
BEGIN {
@qemu_pid = $1;
@mmio_start = 0xa000a00000;
@mmio_end = 0xa000a00000 + 16384;
@devid = 1536;
}
tracepoint:kvm:kvm_mmio /pid == @qemu_pid/ {
if (args->gpa >= @mmio_start && args->gpa < @mmio_end) {
@start = nsecs;
}
}
kprobe:kvm_set_msi {
$e = (struct kvm_kernel_irq_routing_entry *)arg0;
$kvm = (struct kvm *)arg1;
if (@start > 0 && $kvm->userspace_pid == @qemu_pid && $e->msi.devid == @devid) {
@dur = stats(nsecs - @start);
@start = 0;
}
}
interval:s:1 {
print(@dur); clear(@dur);
}
執行結果如下:
@dur: count 598, average 1606320, total 960579533
@dur: count 543, average 1785906, total 969747196
@dur: count 644, average 1495419, total 963049914
@dur: count 624, average 1546575, total 965062935
@dur: count 645, average 1495250, total 964436299
更深理解
很多技術需要反覆去理解驗證, 每一次可能都有不同的收穫, 這裡舉個loadavg的例子. 引用kernel/sched/loadavg.c最開始的一段註釋:
5 * This file contains the magic bits required to compute the global loadavg
6 * figure. Its a silly number but people think its important. We go through
7 * great pains to make it work on big machines and tickless kernels.
這裡的silly我想說的是loadavg有一定的侷限性, 總的來說loadavg是有一定語義和價值的, 畢竟它只用了3個數字描述了過去一段時間的"load", 反過來說如果loadavg is silly, 那麼有沒有更好的選擇?
• 如果是實時觀察的話, vmstat/dstat輸出的runnable和I/O blocked的資訊是種更好的選擇, 因為相對於loadavg每5秒的取樣, vmstat可以做到粒度更細, 而且loadavg的演算法某種程度可以理解為有損的。
• 如果是sar/tsar的話, 假設收集間隔是10min的話, loadavg因為能覆蓋更大的範圍, 確實比10min一個的數字包含更多的資訊, 但我們需要思考它對除錯的真正價值.
另外, 5秒鐘的取樣間隔是比較大的, 我們可以構造個測試用例執行了大量時間但跳過取樣
• 獲取load取樣點的時間
• 測試用例剛好跳過該取樣點
檢視calc_load_fold_active在cpu 0上的呼叫時間:
kprobe:calc_load_fold_active /cpu == 0/ {
printf("%ld\n", nsecs / 1000000000);
}
執行沒有輸出, 監控上一層函式:
#include "kernel/sched/sched.h"
kprobe:calc_global_load_tick /cpu == 0/ {
$rq = (struct rq *)arg0;
@[$rq->calc_load_update] = count();
}
interval:s:5 {
print(@); clear(@);
}
執行結果符合預期:
#./calc_load.bt -I /kernel-source
@[4465886482]: 61
@[4465887733]: 1189
@[4465887733]: 62
@[4465888984]: 1188
檢視彙編發現這裡程式碼被優化, 但是剛好id_nr_invalid呼叫沒優化, 當然最方便的是能夠直接在函式偏移處直接打點:
kprobe:id_nr_invalid /cpu == 0/ {
printf("%ld\n", nsecs / 1000000000);
}
根據這個時間戳, 可以很容易跳過load的統計:
while :; do
sec=$(awk -F. '{print $1}' /proc/uptime)
rem=$((sec % 5))
if [ $rem -eq 2 ]; then # 1s after updating load
break;
fi
sleep 0.1
done
for i in {0..63}; do
./busy 3 & # run 3s
done
大量busy程序成功跳過load的統計, 可以設想像cron執行的任務也是有這個可能的. 雖然不能否認loadavg的價值, 但總的來說load有以下缺陷:
• 系統級別的統計, 和具體應用產生的聯絡不夠直接
• 使用取樣的方式並且取樣間隔 (5s) 較大, 有的場景不能真實反映系統
• 統計的間隔較大(1/5/15分鐘), 不利於及時反映當時的情況
• 語義稍微不夠清晰, 不只包括cpu的load, 還包括D狀態的任務, 這個本身不是大問題, 更多可以認為是feature
Linux增加了Pressure Stall Information (PSI), PSI從任務的角度分別統計了10/60/300s內因為cpu/io/memory等資源不足而不能執行的時長, 並按照影響範圍分成2類:
• some - 因為缺少資源導致部分任務不能執行
• full - 因為缺少資源導致所有任務不能執行, cpu不存在這種情況
我們在一臺96c的arm機器上掃描所有cgroup的cpu.pressure:
這裡會引出幾個問題, 篇幅原因這裡不再展開。
• 父cgroup的avg為什麼比子cgroup還小? 是實現問題還是有額外的配置引數?
• avg10等於33, 也就是1/3的時間有task因為沒有cpu而得不到執行, 考慮到系統cpu利用率在40%左右並不算高, 我們怎麼合理看待和使用這個值
top - 09:55:41 up 127 days, 1:44, 1 user, load average: 111.70, 87.08, 79.41
Tasks: 3685 total, 21 running, 2977 sleeping, 1 stopped, 8 zombie
%Cpu(s): 27.3 us, 8.9 sy, 0.0 ni, 59.8 id, 0.1 wa, 0.0 hi, 4.0 si, 0.0 st
RTFSC
有的時候RTFM已經不夠了, 手冊包括工具本身的更新沒對上核心的節奏, 我們回到上面頁面回收的例子, 估計有的同學之前就有疑問, 沒有scan哪裡來的steal。
#sar -B 1
11:00:16 AM pgscank/s pgscand/s pgsteal/s %vmeff
11:00:17 AM 0.00 0.00 3591.00 0.00
11:00:18 AM 0.00 0.00 10313.00 0.00
11:00:19 AM 0.00 0.00 8452.00 0.00
先看sysstat (sar) 裡面的實現, 主要是讀取分析/proc/vmstat:
• pgscand: 對應到pgscan_direct域
• pgscank: 對應到pgscan_kswapd域
• pgsteal: 對應到pgsteal_開頭的域
#gdb --args ./sar -B 1
(gdb) b read_vmstat_paging
(gdb) set follow-fork-mode child
(gdb) r
Breakpoint 1, read_vmstat_paging (st_paging=0x424f40) at rd_stats.c:751
751 if ((fp = fopen(VMSTAT, "r")) == NULL)
(gdb) n
754 st_paging->pgsteal = 0;
(gdb)
757 while (fgets(line, sizeof(line), fp) != NULL) {
(gdb)
759 if (!strncmp(line, "pgpgin ", 7)) {
(gdb)
763 else if (!strncmp(line, "pgpgout ", 8)) {
(gdb)
767 else if (!strncmp(line, "pgfault ", 8)) {
(gdb)
771 else if (!strncmp(line, "pgmajfault ", 11)) {
(gdb)
775 else if (!strncmp(line, "pgfree ", 7)) {
(gdb)
779 else if (!strncmp(line, "pgsteal_", 8)) {
(gdb)
784 else if (!strncmp(line, "pgscan_kswapd", 13)) {
(gdb)
789 else if (!strncmp(line, "pgscan_direct", 13)) {
(gdb)
757 while (fgets(line, sizeof(line), fp) != NULL) {
(gdb)
看下/proc/vmstat都有什麼:
#grep pgsteal_ /proc/vmstat
pgsteal_kswapd 168563
pgsteal_direct 0
pgsteal_anon 0
pgsteal_file 978205
#grep pgscan_ /proc/vmstat
pgscan_kswapd 204242
pgscan_direct 0
pgscan_direct_throttle 0
pgscan_anon 0
pgscan_file 50583828
最後看看核心的實現, pgsteal和pgscan的邏輯是一樣, 除了nr_scanned換成了nr_reclaimed:
現在問題很清晰了:
• 這裡sar取得是系統的/proc/vmstat, 而cgroup裡面pgscan_kswapd和pgscan_direct只會加到cgroup的統計, 不會加到系統級的統計
• cgroup裡面pgsteal_kswapd和pgsteal_direct同樣只會加到cgroup自己的統計
• 但是主要pgscan_anon, pgscan_file和pgsteal_anon, pgsteal_file都只加到系統級的統計
• sar讀取了pgscan_kswapd, pgscan_direct, 以及pgsteal_, 這裡還包括了pgsteal_anon和pgsteal_file
這整個邏輯都亂了, 我們有必要解決這個bug讓sar的輸出變得更加有意義. 那麼在cgroup內是不是沒問題?
#df -h .
Filesystem Size Used Avail Use% Mounted on
cgroup 0 0 0 - /sys/fs/cgroup/memory
#grep -c 'pgscan\|pgsteal' memory.stat
0
這些統計資訊在cgroup v1上完全沒有輸出, 而只在v2版本有輸出. 在以前核心沒有專門LRU_UNEVICTABLE的時候, 如果有很多比如mlock page的時候, 碰到過不停掃描卻不能回收記憶體的情況, 這個統計會非常有用, 即使是現在我相信這個統計還是有用的, 只是大部分時候還不用看到這麼細。
多上手
紙上得來終覺淺, 自己動手去做帶來很多好處:
• 回答預設問題. 除錯分析就是不斷提出問題和驗證的過程, 沒有上手的話就會一直停留在第一個問題上. 比如我想了解某平臺上實體記憶體是怎麼編址的, 沒有文件的話只能自己去實驗
• 提出新的問題. 除錯分析中不怕有問題, 怕的是提不出問題
• 會有意外收穫. 很多時候並不是有意為之, 比如準備的是分析cpu調頻能否降功耗, 上去卻發現系統一直執行在最低頻率
• 熟練. 熟練就是效率
• 改進產品. 可以試想下在整個雲環境所有機器上掃描 (類似全面體檢) 會發現多少潛在問題
參考資料
[1]https://www.cs.rice.edu/~johnmc/comp528/lecture-notes/
[2]https://brendangregg.com/
[3]http://dtrace.org/blogs/bmc/
[4]https://blog.stgolabs.net/
[5]https://lwn.net/
[6]https://github.com/namhyung/uftrace
[7]https://www.brendangregg.com/[8]The Art of Computer Systems Performance Analysis