perf 在內(nèi)核代碼開(kāi)發(fā)上的應(yīng)用
之前在《Perf Event ：Linux下的系統(tǒng)性能調(diào)優(yōu)工具》中介紹了 perf 最常見(jiàn)的一些用法，以及Linux 系統(tǒng)上應(yīng)用程序的調(diào)優(yōu)。本文將把目光轉(zhuǎn)移到內(nèi)核以及其他 perf 命令上面來(lái)。
在內(nèi)核方面，人們的興趣五花八門，有些內(nèi)核開(kāi)發(fā)人員熱衷于尋找整個(gè)內(nèi)核中的熱點(diǎn)代碼;另一些則只關(guān)注某一個(gè)主題，比如 slab 分配器，對(duì)于其余部分則不感興趣。對(duì)這些人而言，perf 的一些奇怪用法更受歡迎。當(dāng)然，諸如 perf top，perf stat, perf record 等也是內(nèi)核調(diào)優(yōu)的基本手段，但用法和 part1 所描述的一樣，無(wú)需重述。
此外雖然內(nèi)核事件對(duì)應(yīng)用程序開(kāi)發(fā)人員而言有些陌生，但一旦了解，對(duì)應(yīng)用程序的調(diào)優(yōu)也很有幫助。我曾經(jīng)參與開(kāi)發(fā)過(guò)一個(gè)數(shù)據(jù)庫(kù)應(yīng)用程序，其效率很低。通過(guò)常規(guī)的熱點(diǎn)查詢，IO 統(tǒng)計(jì)等方法，我們找到了一些可以優(yōu)化的地方，以至于將程序的效率提高了幾倍?？上?duì)于擁有海量數(shù)據(jù)的用戶，其運(yùn)行時(shí)間依然無(wú)法達(dá)到要求。進(jìn)一步調(diào)優(yōu)需要更加詳細(xì)的統(tǒng)計(jì)信息，可惜本人經(jīng)驗(yàn)有限，實(shí)在是無(wú)計(jì)可施。。。從客戶反饋來(lái)看，該應(yīng)用的使用頻率很低。作為一個(gè)程序員，為此我時(shí)常心情沮喪。。。
假如有 perf，那么我想我可以用它來(lái)驗(yàn)證自己的一些猜測(cè)，比如是否太多的系統(tǒng)調(diào)用，或者系統(tǒng)中的進(jìn)程切換太頻繁 ? 針對(duì)這些懷疑使用 perf 都可以拿出有用的報(bào)告，或許能找到問(wèn)題吧。但過(guò)去的便無(wú)可彌補(bǔ)，時(shí)光不會(huì)倒流，無(wú)論我如何傷感，世界絕不會(huì)以我的意志為轉(zhuǎn)移。所以我們好好學(xué)習(xí) perf，或許可以預(yù)防某些遺憾吧。
這里我還要提醒讀者注意，講述 perf 的命令和語(yǔ)法容易，但說(shuō)明什么時(shí)候使用這些命令，或者說(shuō)明怎樣解決實(shí)際問(wèn)題則很困難。就好象說(shuō)明電子琴上 88 個(gè)琴鍵的唱名很容易，但想說(shuō)明如何彈奏動(dòng)聽(tīng)的曲子則很難。
在簡(jiǎn)述每個(gè)命令語(yǔ)法的同時(shí)，我試圖通過(guò)一些示例來(lái)說(shuō)明這些命令的使用場(chǎng)景，但這只能是一種微薄的努力。因此總體說(shuō)來(lái)，本文只能充當(dāng)那本隨同電子琴一起發(fā)售的使用說(shuō)明書。。。
使用 tracepoint
當(dāng) perf 根據(jù) tick 時(shí)間點(diǎn)進(jìn)行采樣后，人們便能夠得到內(nèi)核代碼中的 hot spot。那什么時(shí)候需要使用 tracepoint 來(lái)采樣呢?
我想人們使用 tracepoint 的基本需求是對(duì)內(nèi)核的運(yùn)行時(shí)行為的關(guān)心，如前所述，有些內(nèi)核開(kāi)發(fā)人員需要專注于特定的子系統(tǒng)，比如內(nèi)存管理模塊。這便需要統(tǒng)計(jì)相關(guān)內(nèi)核函數(shù)的運(yùn)行情況。另外，內(nèi)核行為對(duì)應(yīng)用程序性能的影響也是不容忽視的：
以之前的遺憾為例，假如時(shí)光倒流，我想我要做的是統(tǒng)計(jì)該應(yīng)用程序運(yùn)行期間究竟發(fā)生了多少次系統(tǒng)調(diào)用。在哪里發(fā)生的?
下面我用 ls 命令來(lái)演示 sys_enter 這個(gè) tracepoint 的使用：
[root@ovispoly /]# perf stat -e raw_syscalls:sys_enter ls bin dbg etc lib media opt root selinux sys usr boot dev home lost+found mnt proc sbin srv tmp var Performance counter stats for 'ls': 101 raw_syscalls:sys_enter 0.003434730 seconds time elapsed [root@ovispoly /]# perf record -e raw_syscalls:sys_enter ls [root@ovispoly /]# perf report Failed to open .lib/ld-2.12.so, continuing without symbols # Samples: 70 # # Overhead Command Shared Object Symbol # ........ ............... ............... ...... # 97.14% ls ld-2.12.so [.] 0x0000000001629d 2.86% ls [vdso] [.] 0x00000000421424 # # (For a higher level overview, try: perf report --sort comm,dso) #
這個(gè)報(bào)告詳細(xì)說(shuō)明了在 ls 運(yùn)行期間發(fā)生了多少次系統(tǒng)調(diào)用 ( 上例中有 101 次 )，多數(shù)系統(tǒng)調(diào)用都發(fā)生在哪些地方 (97% 都發(fā)生在 ld-2.12.so 中 )。
有了這個(gè)報(bào)告，或許我能夠發(fā)現(xiàn)更多可以調(diào)優(yōu)的地方。比如函數(shù) foo() 中發(fā)生了過(guò)多的系統(tǒng)調(diào)用，那么我就可以思考是否有辦法減少其中有些不必要的系統(tǒng)調(diào)用。
您可能會(huì)說(shuō) strace 也可以做同樣事情啊，的確，統(tǒng)計(jì)系統(tǒng)調(diào)用這件事完全可以用 strace 完成，但 perf 還可以干些別的，您所需要的就是修改 -e 選項(xiàng)后的字符串。
羅列 tracepoint 實(shí)在是不太地道，本文當(dāng)然不會(huì)這么做。但學(xué)習(xí)每一個(gè) tracepoint 是有意義的，類似背單詞之于學(xué)習(xí)英語(yǔ)一樣，是一項(xiàng)緩慢痛苦卻不得不做的事情。
perf probe
tracepoint 是靜態(tài)檢查點(diǎn)，意思是一旦它在哪里，便一直在那里了，您想讓它移動(dòng)一步也是不可能的。內(nèi)核代碼有多少行?我不知道，100 萬(wàn)行是至少的吧，但目前 tracepoint 有多少呢?我最大膽的想象是不超過(guò) 1000 個(gè)。所以能夠動(dòng)態(tài)地在想查看的地方插入動(dòng)態(tài)監(jiān)測(cè)點(diǎn)的意義是不言而喻的。
Perf 并不是第一個(gè)提供這個(gè)功能的軟件，systemTap 早就實(shí)現(xiàn)了。但假若您不選擇 RedHat 的發(fā)行版的話，安裝 systemTap 并不是件輕松愉快的事情。perf 是內(nèi)核代碼包的一部分，所以使用和維護(hù)都非常方便。
我使用的 Linux 版本為 2.6.33。因此您自己做實(shí)驗(yàn)時(shí)命令參數(shù)有可能不同。
[root@ovispoly perftest]# perf probe schedule:12 cpu Added new event: probe:schedule (on schedule+52 with cpu) You can now use it on all perf tools, such as: perf record -e probe:schedule -a sleep 1 [root@ovispoly perftest]# perf record -e probe:schedule -a sleep 1 Error, output file perf.data exists, use -A to append or -f to overwrite. [root@ovispoly perftest]# perf record -f -e probe:schedule -a sleep 1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.270 MB perf.data (~11811 samples) ] [root@ovispoly perftest]# perf report # Samples: 40 # # Overhead Command Shared Object Symbol # ........ ............... ................. ...... # 57.50% init 0 [k] 0000000000000000 30.00% firefox [vdso] [.] 0x0000000029c424 5.00% sleep [vdso] [.] 0x00000000ca7424 5.00% perf.2.6.33.3-8 [vdso] [.] 0x00000000ca7424 2.50% ksoftirqd/0 [kernel] [k] 0000000000000000 # # (For a higher level overview, try: perf report --sort comm,dso) #
上例利用 probe 命令在內(nèi)核函數(shù) schedule() 的第 12 行處加入了一個(gè)動(dòng)態(tài) probe 點(diǎn)，和 tracepoint 的功能一樣，內(nèi)核一旦運(yùn)行到該 probe 點(diǎn)時(shí)，便會(huì)通知 perf。可以理解為動(dòng)態(tài)增加了一個(gè)新的 tracepoint。
此后便可以用 record 命令的 -e 選項(xiàng)選擇該 probe 點(diǎn)，最后用 perf report 查看報(bào)表。如何解讀該報(bào)表便是見(jiàn)仁見(jiàn)智了，既然您在 shcedule() 的第 12 行加入了 probe 點(diǎn)，想必您知道自己為什么要統(tǒng)計(jì)它吧?#p#
Perf sched
調(diào)度器的好壞直接影響一個(gè)系統(tǒng)的整體運(yùn)行效率。在這個(gè)領(lǐng)域，內(nèi)核黑客們常會(huì)發(fā)生爭(zhēng)執(zhí)，一個(gè)重要原因是對(duì)于不同的調(diào)度器，每個(gè)人給出的評(píng)測(cè)報(bào)告都各不相同，甚至常常有相反的結(jié)論。因此一個(gè)權(quán)威的統(tǒng)一的評(píng)測(cè)工具將對(duì)結(jié)束這種爭(zhēng)論有益。Perf sched 便是這種嘗試。
Perf sched 有五個(gè)子命令：
perf sched record # low-overhead recording of arbitrary workloads perf sched latency # output per task latency metrics perf sched map # show summary/map of context-switching perf sched trace # output finegrained trace perf sched replay # replay a captured workload using simlated threads
用戶一般使用’ perf sched record ’收集調(diào)度相關(guān)的數(shù)據(jù)，然后就可以用’ perf sched latency ’查看諸如調(diào)度延遲等和調(diào)度器相關(guān)的統(tǒng)計(jì)數(shù)據(jù)。
其他三個(gè)命令也同樣讀取 record 收集到的數(shù)據(jù)并從其他不同的角度來(lái)展示這些數(shù)據(jù)。下面一一進(jìn)行演示。
perf sched record sleep 10 # record full system activity for 10 seconds perf sched latency --sort max # report latencies sorted by max ------------------------------------------------------------------------------------- Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | ------------------------------------------------------------------------------------- :14086:14086 | 0.095 ms | 2 | avg: 3.445 ms | max: 6.891 ms | gnome-session:13792 | 31.713 ms | 102 | avg: 0.160 ms | max: 5.992 ms | metacity:14038 | 49.220 ms | 637 | avg: 0.066 ms | max: 5.942 ms | gconfd-2:13971 | 48.587 ms | 777 | avg: 0.047 ms | max: 5.793 ms | gnome-power-man:14050 | 140.601 ms | 434 | avg: 0.097 ms | max: 5.367 ms | python:14049 | 114.694 ms | 125 | avg: 0.120 ms | max: 5.343 ms | kblockd/1:236 | 3.458 ms | 498 | avg: 0.179 ms | max: 5.271 ms | Xorg:3122 | 1073.107 ms | 2920 | avg: 0.030 ms | max: 5.265 ms | dbus-daemon:2063 | 64.593 ms | 665 | avg: 0.103 ms | max: 4.730 ms | :14040:14040 | 30.786 ms | 255 | avg: 0.095 ms | max: 4.155 ms | events/1:8 | 0.105 ms | 13 | avg: 0.598 ms | max: 3.775 ms | console-kit-dae:2080 | 14.867 ms | 152 | avg: 0.142 ms | max: 3.760 ms | gnome-settings-:14023 | 572.653 ms | 979 | avg: 0.056 ms | max: 3.627 ms | ... ----------------------------------------------------------------------------------- TOTAL: | 3144.817 ms | 11654 | ---------------------------------------------------
上面的例子展示了一個(gè) Gnome 啟動(dòng)時(shí)的統(tǒng)計(jì)信息。
各個(gè) column 的含義如下：
Task: 進(jìn)程的名字和 pid
Runtime: 實(shí)際運(yùn)行時(shí)間
Switches: 進(jìn)程切換的次數(shù)
Average delay: 平均的調(diào)度延遲
Maximum delay: 最大延遲
這里最值得人們關(guān)注的是 Maximum delay，一般從這里可以看到對(duì)交互性影響最大的特性：調(diào)度延遲，如果調(diào)度延遲比較大，那么用戶就會(huì)感受到視頻或者音頻斷斷續(xù)續(xù)的。
其他的三個(gè)子命令提供了不同的視圖，一般是由調(diào)度器的開(kāi)發(fā)人員或者對(duì)調(diào)度器內(nèi)部實(shí)現(xiàn)感興趣的人們所使用。
首先是 map:
$ perf sched map ... N1 O1 . . . S1 . . . B0 . *I0 C1 . M1 . 23002.773423 secs N1 O1 . *Q0 . S1 . . . B0 . I0 C1 . M1 . 23002.773423 secs N1 O1 . Q0 . S1 . . . B0 . *R1 C1 . M1 . 23002.773485 secs N1 O1 . Q0 . S1 . *S0 . B0 . R1 C1 . M1 . 23002.773478 secs *L0 O1 . Q0 . S1 . S0 . B0 . R1 C1 . M1 . 23002.773523 secs L0 O1 . *. . S1 . S0 . B0 . R1 C1 . M1 . 23002.773531 secs L0 O1 . . . S1 . S0 . B0 . R1 C1 *T1 M1 . 23002.773547 secs T1 => irqbalance:2089 L0 O1 . . . S1 . S0 . *P0 . R1 C1 T1 M1 . 23002.773549 secs *N1 O1 . . . S1 . S0 . P0 . R1 C1 T1 M1 . 23002.773566 secs N1 O1 . . . *J0 . S0 . P0 . R1 C1 T1 M1 . 23002.773571 secs N1 O1 . . . J0 . S0 *B0 P0 . R1 C1 T1 M1 . 23002.773592 secs N1 O1 . . . J0 . *U0 B0 P0 . R1 C1 T1 M1 . 23002.773582 secs N1 O1 . . . *S1 . U0 B0 P0 . R1 C1 T1 M1 . 23002.773604 secs
星號(hào)表示調(diào)度事件發(fā)生所在的 CPU。
點(diǎn)號(hào)表示該 CPU 正在 IDLE。
Map 的好處在于提供了一個(gè)的總的視圖，將成百上千的調(diào)度事件進(jìn)行總結(jié)，顯示了系統(tǒng)任務(wù)在 CPU 之間的分布，假如有不好的調(diào)度遷移，比如一個(gè)任務(wù)沒(méi)有被及時(shí)遷移到 idle 的 CPU 卻被遷移到其他忙碌的 CPU，類似這種調(diào)度器的問(wèn)題可以從 map 的報(bào)告中一眼看出來(lái)。
如果說(shuō) map 提供了高度概括的總體的報(bào)告，那么 trace 就提供了最詳細(xì)，最底層的細(xì)節(jié)報(bào)告。
pipe-test-100k-13520 [001] 1254.354513808: sched_stat_wait: task: pipe-test-100k:13521 wait: 5362 [ns] pipe-test-100k-13520 [001] 1254.354514876: sched_switch: task pipe-test-100k:13520 [120] (S) ==> pipe-test-100k:13521 [120] :13521-13521 [001] 1254.354517927: sched_stat_runtime: task: pipe-test-100k:13521 runtime: 5092 [ns], vruntime: 133967391150 [ns] :13521-13521 [001] 1254.354518984: sched_stat_sleep: task: pipe-test-100k:13520 sleep: 5092 [ns] :13521-13521 [001] 1254.354520011: sched_wakeup: task pipe-test-100k:13520 [120] success=1 [001]
要理解以上的信息，必須對(duì)調(diào)度器的源代碼有一定了解，對(duì)一般用戶而言，理解他們十分不易。幸好這些信息一般也只有編寫調(diào)度器的人感興趣。。。
Perf replay 這個(gè)工具更是專門為調(diào)度器開(kāi)發(fā)人員所設(shè)計(jì)，它試圖重放 perf.data 文件中所記錄的調(diào)度場(chǎng)景。很多情況下，一般用戶假如發(fā)現(xiàn)調(diào)度器的奇怪行為，他們也無(wú)法準(zhǔn)確說(shuō)明發(fā)生該情形的場(chǎng)景，或者一些測(cè)試場(chǎng)景不容易再次重現(xiàn)，或者僅僅是出于“偷懶”的目的，使用 perf replay，perf 將模擬 perf.data 中的場(chǎng)景，無(wú)需開(kāi)發(fā)人員花費(fèi)很多的時(shí)間去重現(xiàn)過(guò)去，這尤其利于調(diào)試過(guò)程，因?yàn)樾枰欢伲俣刂貜?fù)新的修改是否能改善原始的調(diào)度場(chǎng)景所發(fā)現(xiàn)的問(wèn)題。
下面是 replay 執(zhí)行的示例：
$ perf sched replay run measurement overhead: 3771 nsecs sleep measurement overhead: 66617 nsecs the run test took 999708 nsecs the sleep test took 1097207 nsecs nr_run_events: 200221 nr_sleep_events: 200235 nr_wakeup_events: 100130 task 0 ( perf: 13519), nr_events: 148 task 1 ( perf: 13520), nr_events: 200037 task 2 ( pipe-test-100k: 13521), nr_events: 300090 task 3 ( ksoftirqd/0: 4), nr_events: 8 task 4 ( swapper: 0), nr_events: 170 task 5 ( gnome-power-man: 3192), nr_events: 3 task 6 ( gdm-simple-gree: 3234), nr_events: 3 task 7 ( Xorg: 3122), nr_events: 5 task 8 ( hald-addon-stor: 2234), nr_events: 27 task 9 ( ata/0: 321), nr_events: 29 task 10 ( scsi_eh_4: 704), nr_events: 37 task 11 ( events/1: 8), nr_events: 3 task 12 ( events/0: 7), nr_events: 6 task 13 ( flush-8:0: 6980), nr_events: 20 ------------------------------------------------------------ #1 : 2038.157, ravg: 2038.16, cpu: 0.09 / 0.09 #2 : 2042.153, ravg: 2038.56, cpu: 0.11 / 0.09 ^C
perf bench
除了調(diào)度器之外，很多時(shí)候人們都需要衡量自己的工作對(duì)系統(tǒng)性能的影響。benchmark 是衡量性能的標(biāo)準(zhǔn)方法，對(duì)于同一個(gè)目標(biāo)，如果能夠有一個(gè)大家都承認(rèn)的 benchmark，將非常有助于”提高內(nèi)核性能”這項(xiàng)工作。
目前，就我所知，perf bench 提供了 3 個(gè) benchmark:
1. Sched message
[lm@ovispoly ~]$ perf bench sched messaging
# Running sched/messaging benchmark...# 20 sender and receiver processes per group# 10 groups == 400 processes run Total time: 1.918 [sec]sched message 是從經(jīng)典的測(cè)試程序 hackbench 移植而來(lái)，用來(lái)衡量調(diào)度器的性能，overhead 以及可擴(kuò)展性。該 benchmark 啟動(dòng) N 個(gè) reader/sender 進(jìn)程或線程對(duì)，通過(guò) IPC(socket 或者 pipe) 進(jìn)行并發(fā)的讀寫。一般人們將 N 不斷加大來(lái)衡量調(diào)度器的可擴(kuò)展性。Sched message 的用法及用途和 hackbench 一樣。
2. Sched Pipe
[lm@ovispoly ~]$ perf bench sched pipe
# Running sched/pipe benchmark...# Extecuted 1000000 pipe operations between two tasks Total time: 20.888 [sec] 20.888017 usecs/op 47874 ops/secsched pipe 從 Ingo Molnar 的 pipe-test-1m.c 移植而來(lái)。當(dāng)初 Ingo 的原始程序是為了測(cè)試不同的調(diào)度器的性能和公平性的。其工作原理很簡(jiǎn)單，兩個(gè)進(jìn)程互相通過(guò) pipe 拼命地發(fā) 1000000 個(gè)整數(shù)，進(jìn)程 A 發(fā)給 B，同時(shí) B 發(fā)給 A。。。因?yàn)?A 和 B 互相依賴，因此假如調(diào)度器不公平，對(duì) A 比 B 好，那么 A 和 B 整體所需要的時(shí)間就會(huì)更長(zhǎng)。
3. Mem memcpy
[lm@ovispoly ~]$ perf bench mem memcpy
# Running mem/memcpy benchmark...# Copying 1MB Bytes from 0xb75bb008 to 0xb76bc008 ... 364.697301 MB/Sec這個(gè)是 perf bench 的作者 Hitoshi Mitake 自己寫的一個(gè)執(zhí)行 memcpy 的 benchmark。該測(cè)試衡量一個(gè)拷貝 1M 數(shù)據(jù)的 memcpy() 函數(shù)所花費(fèi)的時(shí)間。我尚不明白該 benchmark 的使用場(chǎng)景。。?；蛟S是一個(gè)例子，告訴人們?nèi)绾卫?perf bench 框架開(kāi)發(fā)更多的 benchmark 吧。
這三個(gè) benchmark 給我們展示了一個(gè)可能的未來(lái)：不同語(yǔ)言，不同膚色，來(lái)自不同背景的人們將來(lái)會(huì)采用同樣的 benchmark，只要有一份 Linux 內(nèi)核代碼即可。#p#
perf lock
鎖是內(nèi)核同步的方法，一旦加了鎖，其他準(zhǔn)備加鎖的內(nèi)核執(zhí)行路徑就必須等待，降低了并行。因此對(duì)于鎖進(jìn)行專門分析應(yīng)該是調(diào)優(yōu)的一項(xiàng)重要工作。
我運(yùn)行 perf lock 后得到如下輸出：
Name acquired contended total wait (ns) max wait (ns) min &md->map_lock 396 0 0 0 &(&mm->page_tabl... 309 0 0 0 &(&tty->buf.lock... 218 0 0 0 &ctx->lock 185 0 0 0 key 178 0 0 0 &ctx->lock 132 0 0 0 &tty->output_loc... 126 0 0 0 。。。 &(&object->lock)... 1 0 0 0 &(&object->lock)... 0 0 0 0 &(&object->lock)... 0 0 0 0 &p->cred_guard_m... 0 0 0 0 === output for debug=== bad: 28, total: 664 bad rate: 4.216867 % histogram of events caused bad sequence acquire: 8 acquired: 0 contended: 0 release: 20
對(duì)該報(bào)表的一些解釋如下：
“Name”: 鎖的名字，比如 md->map_lock，即定義在 dm.c 結(jié)構(gòu) mapped_device 中的讀寫鎖。
“acquired”: 該鎖被直接獲得的次數(shù)，即沒(méi)有其他內(nèi)核路徑擁有該鎖的情況下得到該鎖的次數(shù)。
“contended”沖突的次數(shù)，即在準(zhǔn)備獲得該鎖的時(shí)候已經(jīng)被其他人所擁有的情況的出現(xiàn)次數(shù)。
“total wait”：為了獲得該鎖，總共的等待時(shí)間。
“max wait”：為了獲得該鎖，最大的等待時(shí)間。
“min wait”：為了獲得該鎖，最小的等待時(shí)間。
目前 perf lock 還處于比較初級(jí)的階段，我想在后續(xù)的內(nèi)核版本中，還應(yīng)該會(huì)有較大的變化，因此當(dāng)您開(kāi)始使用 perf lock 時(shí)，恐怕已經(jīng)和本文這里描述的有所不同了。不過(guò)我又一次想說(shuō)的是，命令語(yǔ)法和輸出并不是最重要的，重要的是了解什么時(shí)候我們需要用這個(gè)工具，以及它能幫我們解決怎樣的問(wèn)題。
perf Kmem
Perf Kmem 專門收集內(nèi)核 slab 分配器的相關(guān)事件。比如內(nèi)存分配，釋放等?？梢杂脕?lái)研究程序在哪里分配了大量?jī)?nèi)存，或者在什么地方產(chǎn)生碎片之類的和內(nèi)存管理相關(guān)的問(wèn)題。
Perf kmem 和 perf lock 實(shí)際上都是 perf tracepoint 的特例，您也完全可以用 Perf record – e kmem:* 或者 perf record – e lock:* 來(lái)完成同樣的功能。但重要的是，這些工具在內(nèi)部對(duì)原始數(shù)據(jù)進(jìn)行了匯總和分析，因而能夠產(chǎn)生信息更加明確更加有用的統(tǒng)計(jì)報(bào)表。
perf kmem 的輸出結(jié)果如下：
[root@ovispoly perf]# ./perf kmem --alloc -l 10 --caller stat --------------------------------------------------------------------------- Callsite | Total_alloc/Per | Total_req/Per | Hit | Ping-pong| Frag --------------------------------------------------------------------------- perf_mmap+1a8 | 1024/1024 | 572/572|1 | 0 | 44.141% seq_open+15| 12384/96 | 8772/68 |129 | 0 | 29.167% do_maps_open+0| 1008/16 | 756/12 |63 | 0 | 25.000% ...| ... | ...| ... | ... | ... __split_vma+50| 88/88 | 88/88 | 1 | 0 | 0.000% --------------------------------------------------------------------------- Alloc Ptr | Total_alloc/Per | Total_req/Per | Hit |Ping-pong| Frag --------------------------------------------------------------------------- 0xd15d4600|64/64 | 33/33 1 | 0 | 48.438% 0xc461e000|1024/1024 | 572/572 |1 | 0 | 44.141% 0xd15d44c0| 64/64 | 38/38 |1 | 0 | 40.625% ... | ... | ... | ... | ... | ... --------------------------------------------------------------------------- SUMMARY ======= Total bytes requested: 10487021 Total bytes allocated: 10730448 Total bytes wasted on internal fragmentation: 243427 Internal fragmentation: 2.268563% Cross CPU allocations: 0/246458
該報(bào)告有三個(gè)部分：根據(jù) Callsite 顯示的部分，所謂 Callsite 即內(nèi)核代碼中調(diào)用 kmalloc 和 kfree 的地方。比如上圖中的函數(shù) perf_mmap，Hit 欄為 1，表示該函數(shù)在 record 期間一共調(diào)用了 kmalloc 一次，假如如第三行所示數(shù)字為 653，則表示函數(shù) sock_alloc_send_pskb 共有 653 次調(diào)用 kmalloc 分配內(nèi)存。
對(duì)于第一行 Total_alloc/Per 顯示為 1024/1024，第一個(gè)值 1024 表示函數(shù) perf_mmap 總共分配的內(nèi)存大小，Per 表示平均值。
比較有趣的兩個(gè)參數(shù)是 Ping-pong 和 Frag。Frag 比較容易理解，即內(nèi)部碎片。雖然相對(duì)于 Buddy System，Slab 正是要解決內(nèi)部碎片問(wèn)題，但 slab 依然存在內(nèi)部碎片，比如一個(gè) cache 的大小為 1024，但需要分配的數(shù)據(jù)結(jié)構(gòu)大小為 1022，那么有 2 個(gè)字節(jié)成為碎片。Frag 即碎片的比例。
Ping-pong 是一種現(xiàn)象，在多 CPU 系統(tǒng)中，多個(gè) CPU 共享的內(nèi)存會(huì)出現(xiàn)”乒乓現(xiàn)象”。一個(gè) CPU 分配內(nèi)存，其他 CPU 可能訪問(wèn)該內(nèi)存對(duì)象，也可能最終由另外一個(gè) CPU 釋放該內(nèi)存對(duì)象。而在多 CPU 系統(tǒng)中，L1 cache 是 per CPU 的，CPU2 修改了內(nèi)存，那么其他的 CPU 的 cache 都必須更新，這對(duì)于性能是一個(gè)損失。Perf kmem 在 kfree 事件中判斷 CPU 號(hào)，如果和 kmalloc 時(shí)的不同，則視為一次 ping-pong，理想的情況下 ping-pone 越小越好。Ibm developerworks 上有一篇講述 oprofile 的文章，其中關(guān)于 cache 的調(diào)優(yōu)可以作為很好的參考資料。
后面則有根據(jù)被調(diào)用地點(diǎn)的顯示方式的部分。
最后一個(gè)部分是匯總數(shù)據(jù)，顯示總的分配的內(nèi)存和碎片情況，Cross CPU allocation 即 ping-pong 的匯總。#p#
Perf timechart
很多 perf 命令都是為調(diào)試單個(gè)程序或者單個(gè)目的而設(shè)計(jì)。有些時(shí)候，性能問(wèn)題并非由單個(gè)原因所引起，需要從各個(gè)角度一一查看。為此，人們常需要綜合利用各種工具，比如 top,vmstat,oprofile 或者 perf。這非常麻煩。
此外，前面介紹的所有工具都是基于命令行的，報(bào)告不夠直觀。更令人氣餒的是，一些報(bào)告中的參數(shù)令人費(fèi)解。所以人們更愿意擁有一個(gè)“傻瓜式”的工具。
以上種種就是 perf timechart 的夢(mèng)想，其靈感來(lái)源于 bootchart。采用“簡(jiǎn)單”的圖形“一目了然”地揭示問(wèn)題所在。
加注了引號(hào)的原因是，perf timechart 雖然有了美觀的圖形輸出，但對(duì)于新手，這個(gè)圖形就好象高科技節(jié)目中播放的 DNA 圖像一樣，不明白那些坐在屏幕前的人是如何從密密麻麻的點(diǎn)和線中找到有用的信息的。但正如受過(guò)訓(xùn)練的科學(xué)家一樣，經(jīng)過(guò)一定的練習(xí)，相信您也一定能從下圖中找到您想要的。
圖 1. perf timechart
人們說(shuō)，只有黑白兩色是一個(gè)人內(nèi)心壓抑的象征，Timechart 用不同的顏色代表不同的含義。上圖的最上面一行是圖例，告訴人們每種顏色所代表的含義。藍(lán)色表示忙碌，紅色表示 idle，灰色表示等待，等等。
接下來(lái)是 per-cpu 信息，上圖所示的系統(tǒng)中有兩個(gè)處理器，可以看到在采樣期間，兩個(gè)處理器忙碌程度的概括。藍(lán)色多的地方表示忙碌，因此上圖告訴我們，CPU1 很忙，而 CPU2 很閑。
再下面是 per-process 信息，每一個(gè)進(jìn)程有一個(gè) bar。上圖中進(jìn)程 bash 非常忙碌，而其他進(jìn)程則大多數(shù)時(shí)間都在等待著什么。Perf 自己在開(kāi)始的時(shí)候很忙，接下來(lái)便開(kāi)始 wait 了。
總之這張圖告訴了我們一個(gè)系統(tǒng)的概況，但似乎不夠詳細(xì)?
Timechart 可以顯示更詳細(xì)的信息，上圖實(shí)際上是一個(gè)矢量圖形 SVG 格式，用 SVG viewer 的放大功能，我們可以將該圖的細(xì)節(jié)部分放大，timechart 的設(shè)計(jì)理念叫做”infinitely zoomable”。放大之后便可以看到一些更詳細(xì)的信息，類似網(wǎng)上的 google 地圖，找到國(guó)家之后，可以放大，看城市的分布，再放大，可以看到某個(gè)城市的街道分布，還可以放大以便得到更加詳細(xì)的信息。
完整的 timechart 圖形和顏色解讀超出了本文的范圍，感興趣的讀者可以到作者 Arjan 的博客上查看。這里僅舉一個(gè)例子，上圖中有一條 bar 對(duì)應(yīng)了 Xorg 進(jìn)程。多數(shù)時(shí)候該進(jìn)程都處于 waiting 狀態(tài)，只有需要顯示什么的時(shí)候它才會(huì)開(kāi)始和內(nèi)核通信，以便進(jìn)行繪圖所需的 IO 操作。
將 Xorg 條目放大的例子圖形如下：
圖 2. perf timechart detail
上圖中需要注意的是幾條綠色的短線，表示進(jìn)程通信，即準(zhǔn)備繪圖。假如通信的兩個(gè)進(jìn)程在圖中上下相鄰，那么綠線可以連接他們。但如果不相鄰，則只會(huì)顯示如上圖所示的被截?cái)嗟木G色短線。
藍(lán)色部分表示進(jìn)程忙碌，黃色部分表示該進(jìn)程的時(shí)間片已經(jīng)用完，但仍處于就緒狀態(tài)，在等待調(diào)度器給予 CPU。
通過(guò)這張圖，便可以較直觀地看到進(jìn)程在一段時(shí)間內(nèi)的詳細(xì)行為。#p#
使用 Script 增強(qiáng) perf 的功能
通常，面對(duì)看似復(fù)雜，實(shí)則較有規(guī)律的計(jì)算機(jī)輸出，程序員們總是會(huì)用腳本來(lái)進(jìn)行處理：比如給定一個(gè)文本文件，想從中找出有多少個(gè)數(shù)字 0125，人們不會(huì)打開(kāi)文件然后用肉眼去一個(gè)一個(gè)地?cái)?shù)，而是用 grep 命令來(lái)進(jìn)行處理。
perf 的輸出雖然是文本格式，但還是不太容易分析和閱讀。往往也需要進(jìn)一步處理，perl 和 python 是目前最強(qiáng)大的兩種腳本語(yǔ)言。Tom Zanussi 將 perl 和 python 解析器嵌入到 perf 程序中，從而使得 perf 能夠自動(dòng)執(zhí)行 perl 或者 python 腳本進(jìn)一步進(jìn)行處理，從而為 perf 提供了強(qiáng)大的擴(kuò)展能力。因?yàn)槿魏稳硕伎梢跃帉懶碌哪_本，對(duì) perf 的原始輸出數(shù)據(jù)進(jìn)行所需要的進(jìn)一步處理。這個(gè)特性所帶來(lái)的好處很類似于 plug-in 之于 eclipse。
下面的命令可以查看系統(tǒng)中已經(jīng)安裝的腳本：
# perf trace -l List of available trace scripts: syscall-counts [comm] system-wide syscall counts syscall-counts-by-pid [comm] system-wide syscall counts, by pid failed-syscalls-by-pid [comm] system-wide failed syscalls, by pid 。。。 比如 failed-syscalls 腳本，執(zhí)行的效果如下： # perf trace record failed-syscalls ^C[ perf record: Woken up 11 times to write data ] [ perf record: Captured and wrote 1.939 MB perf.data (~84709 samples) ] perf trace report failed-syscalls perf trace started with Perl script \ /root/libexec/perf-core/scripts/perl/failed-syscalls.pl failed syscalls, by comm: comm # errors -------------------- ---------- firefox 1721 claws-mail 149 konsole 99 X 77 emacs 56 [...] failed syscalls, by syscall: syscall # errors ------------------------------ ---------- sys_read 2042 sys_futex 130 sys_mmap_pgoff 71 sys_access 33 sys_stat64 5 sys_inotify_add_watch 4 [...]
該報(bào)表分別按進(jìn)程和按系統(tǒng)調(diào)用顯示失敗的次數(shù)。非常簡(jiǎn)單明了，而如果通過(guò)普通的 perf record 加 perf report 命令，則需要自己手工或者編寫腳本來(lái)統(tǒng)計(jì)這些數(shù)字。
我想重要的不僅是學(xué)習(xí)目前已經(jīng)存在的這些腳本，而是理解如何利用 perf 的腳本功能開(kāi)發(fā)新的功能。但如何寫 perf 腳本超出了本文的范圍，要想描述清楚估計(jì)需要一篇單獨(dú)的文章。因此不再贅述。
結(jié)束語(yǔ)
從 2.6.31 開(kāi)始，一晃居然也有幾個(gè)年頭了，期間每一個(gè)內(nèi)核版本都會(huì)有新的 perf 特性。因此于我而言，閱讀新的 changelog 并在其中發(fā)現(xiàn) perf 的新功能已經(jīng)成為一項(xiàng)樂(lè)趣，類似喜歡陳奕迅的人們期待他創(chuàng)作出新的專輯一般。
本文寫到這里可以暫時(shí)告一段落，還有一些命令沒(méi)有介紹，而且或許就在此時(shí)此刻，新的功能已經(jīng)加入 perf 家族了。所以當(dāng)您讀到這篇文章時(shí)，本文恐怕已經(jīng)開(kāi)始泛黃，然而我依舊感到高興，因?yàn)槲艺诮?jīng)歷一個(gè)偉大時(shí)代，Linux 的黃金時(shí)代吧。
【編輯推薦】
