本文主要講了如何使用 time、perf、line_profiler
測試python文件
call.py
def call():
return True
for i in range(10000000):
call()
time使用
time python call.py
- real 總耗時 1.488秒
- user 用戶態耗時 1.255 秒
- sys 內核態耗時0.230秒
perf使用
perf --help 之后可以看到perf的二級命令。
| 序號 | 命令 | 作用 |
|---|---|---|
| 1 | annotate | 解析perf record生成的perf.data文件，顯示被注釋的代碼。 |
| 2 | archive | 根據數據文件記錄的build-id，將所有被采樣到的elf文件打包。利用此壓縮包，可以再任何機器上分析數據文件中記錄的采樣數據。 |
| 3 | bench | perf中內置的benchmark，目前包括兩套針對調度器和內存管理子系統的benchmark。 |
| 4 | buildid-cache | 管理perf的buildid緩存，每個elf文件都有一個獨一無二的buildid。buildid被perf用來關聯性能數據與elf文件。 |
| 5 | buildid-list | 列出數據文件中記錄的所有buildid。 |
| 6 | diff | 對比兩個數據文件的差異。能夠給出每個符號（函數）在熱點分析上的具體差異。 |
| 7 | evlist | 列出數據文件perf.data中所有性能事件。 |
| 8 | inject | 該工具讀取perf record工具記錄的事件流，並將其定向到標准輸出。在被分析代碼中的任何一點，都可以向事件流中注入其它事件。 |
| 9 | kmem | 針對內核內存（slab）子系統進行追蹤測量的工具 |
| 10 | kvm | 用來追蹤測試運行在KVM虛擬機上的Guest OS。 |
| 11 | list | 列出當前系統支持的所有性能事件。包括硬件性能事件、軟件性能事件以及檢查點。 |
| 12 | lock | 分析內核中的鎖信息，包括鎖的爭用情況，等待延遲等。 |
| 13 | mem | 內存存取情況 |
| 14 | record | 收集采樣信息，並將其記錄在數據文件中。隨后可通過其它工具對數據文件進行分析。 |
| 15 | report | 讀取perf record創建的數據文件，並給出熱點分析結果。 |
| 16 | sched | 針對調度器子系統的分析工具。 |
| 17 | script | 執行perl或python寫的功能擴展腳本、生成腳本框架、讀取數據文件中的數據信息等。 |
| 18 | stat | 執行某個命令，收集特定進程的性能概況，包括CPI、Cache丟失率等。 |
| 19 | test | perf對當前軟硬件平台進行健全性測試，可用此工具測試當前的軟硬件平台是否能支持perf的所有功能。 |
| 20 | timechart | 針對測試期間系統行為進行可視化的工具 |
| 21 | top | 類似於linux的top命令，對系統性能進行實時分析。 |
| 22 | trace | 關於syscall的工具。 |
| 23 | probe | 用於定義動態檢查點。 |
全局性概況：
perf list 查看當前系統支持的性能事件；
perf bench 對系統性能進行摸底；
perf test 對系統進行健全性測試；
perf stat 對全局性能進行統計；
全局細節：
perf top 可以實時查看當前系統進程函數占用率情況；
perf probe 可以自定義動態事件；
特定功能分析：
perf kmem 針對slab子系統性能分析；
perf kvm 針對kvm虛擬化分析；
perf lock 分析鎖性能；
perf mem 分析內存slab性能；
perf sched 分析內核調度器性能；
perf trace 記錄系統調用軌跡；
最常用功能perf record，可以系統全局，也可以具體到某個進程，更甚具體到某一進程某一事件；可宏觀，也可以很微觀。
perf record –e cpu-clock python call.py
pref record 記錄信息到perf.data；perf report 生成報告；
perf diff 對兩個記錄進行diff；
perf evlist 列出記錄的性能事件；
perf annotate 顯示perf.data函數代碼；
perf archive 將相關符號打包，方便在其它機器進行分析；
perf script 將perf.data輸出可讀性文本；
可視化工具perf timechart
perf timechart record記錄事件；
perf timechart生成output.svg文檔；
關於perf top界面常用命令如下：
h：顯示幫助，即可顯示詳細的幫助信息。
UP/DOWN/PGUP/PGDN/SPACE：上下和翻頁。
a：annotate current symbol，注解當前符號。能夠給出匯編語言的注解，給出各條指令的采樣率。
d：過濾掉所有不屬於此DSO的符號。非常方便查看同一類別的符號。
P：將當前信息保存到perf.hist.N中。
perf top常用選項有：
-e
：指明要分析的性能事件。 -p
：Profile events on existing Process ID (comma sperated list). 僅分析目標進程及其創建的線程。 -k
：Path to vmlinux. Required for annotation functionality. 帶符號表的內核映像所在的路徑。 -K：不顯示屬於內核或模塊的符號。
-U：不顯示屬於用戶態程序的符號。
-d
：界面的刷新周期，默認為2s，因為perf top默認每2s從mmap的內存區域讀取一次性能數據。 -g：得到函數的調用關系圖。
perf top --call-graph [fractal]，路徑概率為相對值，加起來為100%，調用順序為從下往上。
perf top --call-graph graph，路徑概率為絕對值，加起來為該函數的熱度。
perf stat
perf stat用於運行指令，並分析其統計結果。雖然perf top也可以指定pid，但是必須先啟動應用才能查看信息。
perf stat能完整統計應用整個生命周期的信息。
命令格式為：
perf stat [-e
| --event=EVENT] [-a]
perf stat [-e| --event=EVENT] [-a] — [ ]
下面簡單看一下perf stat 的輸出：
[root@master ~]# perf stat
Performance counter stats for 'system wide':40904.820871 cpu-clock (msec) # 5.000 CPUs utilized
18,132 context-switches # 0.443 K/sec
1,053 cpu-migrations # 0.026 K/sec
2,420 page-faults # 0.059 K/sec
3,958,376,712 cycles # 0.097 GHz (49.99%)
574,598,403 stalled-cycles-frontend # 14.52% frontend cycles idle (49.98%)
9,392,982,910 stalled-cycles-backend # 237.29% backend cycles idle (50.00%)
1,653,185,883 instructions # 0.42 insn per cycle
# 5.68 stalled cycles per insn (50.01%)
237,061,366 branches # 5.795 M/sec (50.02%)
18,333,168 branch-misses # 7.73% of all branches (50.00%) 8.181521203 seconds time elapsed
輸出解釋如下：
cpu-clock：任務真正占用的處理器時間，單位為ms。CPUs utilized = task-clock / time elapsed，CPU的占用率。
context-switches：程序在運行過程中上下文的切換次數。
CPU-migrations：程序在運行過程中發生的處理器遷移次數。Linux為了維持多個處理器的負載均衡，在特定條件下會將某個任務從一個CPU遷移到另一個CPU。
CPU遷移和上下文切換：發生上下文切換不一定會發生CPU遷移，而發生CPU遷移時肯定會發生上下文切換。發生上下文切換有可能只是把上下文從當前CPU中換出，下一次調度器還是將進程安排在這個CPU上執行。
page-faults：缺頁異常的次數。當應用程序請求的頁面尚未建立、請求的頁面不在內存中，或者請求的頁面雖然在內存中，但物理地址和虛擬地址的映射關系尚未建立時，都會觸發一次缺頁異常。另外TLB不命中，頁面訪問權限不匹配等情況也會觸發缺頁異常。
cycles：消耗的處理器周期數。如果把被ls使用的cpu cycles看成是一個處理器的，那么它的主頻為2.486GHz。可以用cycles / task-clock算出。
stalled-cycles-frontend：指令讀取或解碼的質量步驟，未能按理想狀態發揮並行左右，發生停滯的時鍾周期。
stalled-cycles-backend：指令執行步驟，發生停滯的時鍾周期。
instructions：執行了多少條指令。IPC為平均每個cpu cycle執行了多少條指令。
branches：遇到的分支指令數。branch-misses是預測錯誤的分支指令數。
其他常用參數
-a, --all-cpus 顯示所有CPU上的統計信息
-C, --cpu顯示指定CPU的統計信息
-c, --scale scale/normalize counters
-D, --delayms to wait before starting measurement after program start
-d, --detailed detailed run - start a lot of events
-e, --eventevent selector. use 'perf list' to list available events
-G, --cgroupmonitor event in cgroup name only
-g, --group put the counters into a counter group
-I, --interval-print
print counts at regular interval in ms (>= 10)
-i, --no-inherit child tasks do not inherit counters
-n, --null null run - dont start any counters
-o, --output輸出統計信息到文件
-p, --pidstat events on existing process id
-r, --repeatrepeat command and print average + stddev (max: 100, forever: 0)
-S, --sync call sync() before starting a run
-t, --tidstat events on existing thread id
...
示例
前面統計程序的示例，下面看一下統計CPU信息的示例：
perf stat python call.py
perf top -C 0
Flame Graph
1.抓取perf信息並轉換
perf record -F 99 -a -g -- sleep 60 perf script > out.perf
./stackcollapse-perf.pl out.perf > out.folded
./flamegraph.pl out.kern_folded > kernel.svg
line_profiler使用
逐行分析python代碼
# test.py
import line_profiler
@profile
def fib(n):
# 文件名aaa.py
a, b = 0, 1
for i in range(0, n):
a, b = b, a+b
return a
fib(5)
D:\PythonProject\interview> kernprof -l -v test.py
Wrote profile results to test.py.lprof
Timer unit: 1e-06 s
Total time: 3.61e-05 s
File: test.py
Function: fib at line 253
Line # Hits Time Per Hit % Time Line Contents
==============================================================
253 @profile
254 def fib(n):
255 # 文件名aaa.py
256 1 15.3 15.3 42.4 a, b = 0, 1
257 6 4.0 0.7 11.1 for i in range(0, n):
258 5 16.4 3.3 45.4 a, b = b, a+b
259 1 0.4 0.4 1.1 return a
- Total Time：測試代碼的總運行時間
- Line:代碼行號
- Hits：表示每行代碼運行的次數
- Time：每行代碼運行的總時間
- Per Hits：每行代碼運行一次的時間
- % Time：每行代碼運行時間的百分比
- 從分析結果可以看出：第258行代碼運行時間最長
參考資料
系統級性能分析工具 — Perf：http://blog.csdn.net/zhangskd/article/details/37902159/