本文內(nèi)容簡介之前介紹了 perf 最常見的一些用法，關(guān)注于 Linux 系統(tǒng)上應(yīng)用程序的調(diào)優(yōu)?，F(xiàn)在讓我們把目光轉(zhuǎn)移到內(nèi)核以及其他 perf 命令上面來。 在內(nèi)核方面，人們的興趣五花八門，有些內(nèi)核開發(fā)人員熱衷于尋找整個內(nèi)核中的熱點(diǎn)代碼；另一些則只關(guān)注某一個主題，比如 slab 分配器，對于其余部分則不感興趣。對這些人而言，perf 的一些奇怪用法更受歡迎。當(dāng)然，諸如 perf top，perf stat, perf record 等也是內(nèi)核調(diào)優(yōu)的基本手段，但用法和 part1 所描述的一樣，無需重述。 此外雖然內(nèi)核事件對應(yīng)用程序開發(fā)人員而言有些陌生，但一旦了解，對應(yīng)用程序的調(diào)優(yōu)也很有幫助。我曾經(jīng)參與開發(fā)過一個數(shù)據(jù)庫應(yīng)用程序，其效率很低。通過常規(guī)的熱點(diǎn)查詢，IO 統(tǒng)計等方法，我們找到了一些可以優(yōu)化的地方，以至于將程序的效率提高了幾倍?？上τ趽碛泻Ａ繑?shù)據(jù)的用戶，其運(yùn)行時間依然無法達(dá)到要求。進(jìn)一步調(diào)優(yōu)需要更加詳細(xì)的統(tǒng)計信息，可惜本人經(jīng)驗(yàn)有限，實(shí)在是無計可施。。。從客戶反饋來看，該應(yīng)用的使用頻率很低。作為一個程序員，為此我時常心情沮喪。。。 假如有 perf，那么我想我可以用它來驗(yàn)證自己的一些猜測，比如是否太多的系統(tǒng)調(diào)用，或者系統(tǒng)中的進(jìn)程切換太頻繁 ? 針對這些懷疑使用 perf 都可以拿出有用的報告，或許能找到問題吧。但過去的便無可彌補(bǔ)，時光不會倒流，無論我如何傷感，世界絕不會以我的意志為轉(zhuǎn)移。所以我們好好學(xué)習(xí) perf，或許可以預(yù)防某些遺憾吧。 這里我還要提醒讀者注意，講述 perf 的命令和語法容易，但說明什么時候使用這些命令，或者說明怎樣解決實(shí)際問題則很困難。就好象說明電子琴上 88 個琴鍵的唱名很容易，但想說明如何彈奏動聽的曲子則很難。 在簡述每個命令語法的同時，我試圖通過一些示例來說明這些命令的使用場景，但這只能是一種微薄的努力。因此總體說來，本文只能充當(dāng)那本隨同電子琴一起發(fā)售的使用說明書。。。 使用 tracepoint當(dāng) perf 根據(jù) tick 時間點(diǎn)進(jìn)行采樣后，人們便能夠得到內(nèi)核代碼中的 hot spot。那什么時候需要使用 tracepoint 來采樣呢？ 我想人們使用 tracepoint 的基本需求是對內(nèi)核的運(yùn)行時行為的關(guān)心，如前所述，有些內(nèi)核開發(fā)人員需要專注于特定的子系統(tǒng)，比如內(nèi)存管理模塊。這便需要統(tǒng)計相關(guān)內(nèi)核函數(shù)的運(yùn)行情況。另外，內(nèi)核行為對應(yīng)用程序性能的影響也是不容忽視的： 以之前的遺憾為例，假如時光倒流，我想我要做的是統(tǒng)計該應(yīng)用程序運(yùn)行期間究竟發(fā)生了多少次系統(tǒng)調(diào)用。在哪里發(fā)生的？ 下面我用 ls 命令來演示 sys_enter 這個 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) # 這個報告詳細(xì)說明了在 ls 運(yùn)行期間發(fā)生了多少次系統(tǒng)調(diào)用 ( 上例中有 101 次 )，多數(shù)系統(tǒng)調(diào)用都發(fā)生在哪些地方 (97% 都發(fā)生在 ld-2.12.so 中 )。 有了這個報告，或許我能夠發(fā)現(xiàn)更多可以調(diào)優(yōu)的地方。比如函數(shù) foo() 中發(fā)生了過多的系統(tǒng)調(diào)用，那么我就可以思考是否有辦法減少其中有些不必要的系統(tǒng)調(diào)用。 您可能會說 strace 也可以做同樣事情啊，的確，統(tǒng)計系統(tǒng)調(diào)用這件事完全可以用 strace 完成，但 perf 還可以干些別的，您所需要的就是修改 -e 選項(xiàng)后的字符串。 羅列 tracepoint 實(shí)在是不太地道，本文當(dāng)然不會這么做。但學(xué)習(xí)每一個 tracepoint 是有意義的，類似背單詞之于學(xué)習(xí)英語一樣，是一項(xiàng)緩慢痛苦卻不得不做的事情。 perf probetracepoint 是靜態(tài)檢查點(diǎn)，意思是一旦它在哪里，便一直在那里了，您想讓它移動一步也是不可能的。內(nèi)核代碼有多少行？我不知道，100 萬行是至少的吧，但目前 tracepoint 有多少呢？我最大膽的想象是不超過 1000 個。所以能夠動態(tài)地在想查看的地方插入動態(tài)監(jiān)測點(diǎn)的意義是不言而喻的。 Perf 并不是第一個提供這個功能的軟件，systemTap 早就實(shí)現(xiàn)了。但假若您不選擇 RedHat 的發(fā)行版的話，安裝 systemTap 并不是件輕松愉快的事情。perf 是內(nèi)核代碼包的一部分，所以使用和維護(hù)都非常方便。 我使用的 Linux 版本為 2.6.33。因此您自己做實(shí)驗(yàn)時命令參數(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 行處加入了一個動態(tài) probe 點(diǎn)，和 tracepoint 的功能一樣，內(nèi)核一旦運(yùn)行到該 probe 點(diǎn)時，便會通知 perf?？梢岳斫鉃閯討B(tài)增加了一個新的 tracepoint。 此后便可以用 record 命令的 -e 選項(xiàng)選擇該 probe 點(diǎn)，最后用 perf report 查看報表。如何解讀該報表便是見仁見智了，既然您在 shcedule() 的第 12 行加入了 probe 點(diǎn)，想必您知道自己為什么要統(tǒng)計它吧？ Perf sched調(diào)度器的好壞直接影響一個系統(tǒng)的整體運(yùn)行效率。在這個領(lǐng)域，內(nèi)核黑客們常會發(fā)生爭執(zhí)，一個重要原因是對于不同的調(diào)度器，每個人給出的評測報告都各不相同，甚至常常有相反的結(jié)論。因此一個權(quán)威的統(tǒng)一的評測工具將對結(jié)束這種爭論有益。Perf sched 便是這種嘗試。 Perf sched 有五個子命令： 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)計數(shù)據(jù)。 其他三個命令也同樣讀取 record 收集到的數(shù)據(jù)并從其他不同的角度來展示這些數(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 | --------------------------------------------------- 上面的例子展示了一個 Gnome 啟動時的統(tǒng)計信息。 各個 column 的含義如下： Task: 進(jìn)程的名字和 pid Runtime: 實(shí)際運(yùn)行時間 Switches: 進(jìn)程切換的次數(shù) Average delay: 平均的調(diào)度延遲 Maximum delay: 最大延遲 這里最值得人們關(guān)注的是 Maximum delay，一般從這里可以看到對交互性影響最大的特性：調(diào)度延遲，如果調(diào)度延遲比較大，那么用戶就會感受到視頻或者音頻斷斷續(xù)續(xù)的。 其他的三個子命令提供了不同的視圖，一般是由調(diào)度器的開發(fā)人員或者對調(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星號表示調(diào)度事件發(fā)生所在的 CPU。 點(diǎn)號表示該 CPU 正在 IDLE。 Map 的好處在于提供了一個的總的視圖，將成百上千的調(diào)度事件進(jìn)行總結(jié)，顯示了系統(tǒng)任務(wù)在 CPU 之間的分布，假如有不好的調(diào)度遷移，比如一個任務(wù)沒有被及時遷移到 idle 的 CPU 卻被遷移到其他忙碌的 CPU，類似這種調(diào)度器的問題可以從 map 的報告中一眼看出來。 如果說 map 提供了高度概括的總體的報告，那么 trace 就提供了最詳細(xì)，最底層的細(xì)節(jié)報告。 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]要理解以上的信息，必須對調(diào)度器的源代碼有一定了解，對一般用戶而言，理解他們十分不易。幸好這些信息一般也只有編寫調(diào)度器的人感興趣。。。 Perf replay 這個工具更是專門為調(diào)度器開發(fā)人員所設(shè)計，它試圖重放 perf.data 文件中所記錄的調(diào)度場景。很多情況下，一般用戶假如發(fā)現(xiàn)調(diào)度器的奇怪行為，他們也無法準(zhǔn)確說明發(fā)生該情形的場景，或者一些測試場景不容易再次重現(xiàn)，或者僅僅是出于“偷懶”的目的，使用 perf replay，perf 將模擬 perf.data 中的場景，無需開發(fā)人員花費(fèi)很多的時間去重現(xiàn)過去，這尤其利于調(diào)試過程，因?yàn)樾枰欢伲俣刂貜?fù)新的修改是否能改善原始的調(diào)度場景所發(fā)現(xià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)度器之外，很多時候人們都需要衡量自己的工作對系統(tǒng)性能的影響。benchmark 是衡量性能的標(biāo)準(zhǔn)方法，對于同一個目標(biāo)，如果能夠有一個大家都承認(rèn)的 benchmark，將非常有助于”提高內(nèi)核性能”這項(xiàng)工作。 目前，就我所知，perf bench 提供了 3 個 benchmark: 1. Sched message
2. Sched Pipe
3. Mem memcpy
這三個 benchmark 給我們展示了一個可能的未來：不同語言，不同膚色，來自不同背景的人們將來會采用同樣的 benchmark，只要有一份 Linux 內(nèi)核代碼即可。 perf lock鎖是內(nèi)核同步的方法，一旦加了鎖，其他準(zhǔn)備加鎖的內(nèi)核執(zhí)行路徑就必須等待，降低了并行。因此對于鎖進(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 對該報表的一些解釋如下： “Name”: 鎖的名字，比如 md->map_lock，即定義在 dm.c 結(jié)構(gòu) mapped_device 中的讀寫鎖。 “acquired”: 該鎖被直接獲得的次數(shù)，即沒有其他內(nèi)核路徑擁有該鎖的情況下得到該鎖的次數(shù)。 “contended”沖突的次數(shù)，即在準(zhǔn)備獲得該鎖的時候已經(jīng)被其他人所擁有的情況的出現(xiàn)次數(shù)。 “total wait”：為了獲得該鎖，總共的等待時間。 “max wait”：為了獲得該鎖，最大的等待時間。 “min wait”：為了獲得該鎖，最小的等待時間。 目前 perf lock 還處于比較初級的階段，我想在后續(xù)的內(nèi)核版本中，還應(yīng)該會有較大的變化，因此當(dāng)您開始使用 perf lock 時，恐怕已經(jīng)和本文這里描述的有所不同了。不過我又一次想說的是，命令語法和輸出并不是最重要的，重要的是了解什么時候我們需要用這個工具，以及它能幫我們解決怎樣的問題。 perf KmemPerf Kmem 專門收集內(nèi)核 slab 分配器的相關(guān)事件。比如內(nèi)存分配，釋放等?？梢杂脕硌芯砍绦蛟谀睦锓峙淞舜罅績?nèi)存，或者在什么地方產(chǎn)生碎片之類的和內(nèi)存管理相關(guān)的問題。 Perf kmem 和 perf lock 實(shí)際上都是 perf tracepoint 的特例，您也完全可以用 Perf record – e kmem:* 或者 perf record – e lock:* 來完成同樣的功能。但重要的是，這些工具在內(nèi)部對原始數(shù)據(jù)進(jìn)行了匯總和分析，因而能夠產(chǎn)生信息更加明確更加有用的統(tǒng)計報表。 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 該報告有三個部分：根據(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)存。 對于第一行 Total_alloc/Per 顯示為 1024/1024，第一個值 1024 表示函數(shù) perf_mmap 總共分配的內(nèi)存大小，Per 表示平均值。 比較有趣的兩個參數(shù)是 Ping-pong 和 Frag。Frag 比較容易理解，即內(nèi)部碎片。雖然相對于 Buddy System，Slab 正是要解決內(nèi)部碎片問題，但 slab 依然存在內(nèi)部碎片，比如一個 cache 的大小為 1024，但需要分配的數(shù)據(jù)結(jié)構(gòu)大小為 1022，那么有 2 個字節(jié)成為碎片。Frag 即碎片的比例。 Ping-pong 是一種現(xiàn)象，在多 CPU 系統(tǒng)中，多個 CPU 共享的內(nèi)存會出現(xiàn)”乒乓現(xiàn)象”。一個 CPU 分配內(nèi)存，其他 CPU 可能訪問該內(nèi)存對象，也可能最終由另外一個 CPU 釋放該內(nèi)存對象。而在多 CPU 系統(tǒng)中，L1 cache 是 per CPU 的，CPU2 修改了內(nèi)存，那么其他的 CPU 的 cache 都必須更新，這對于性能是一個損失。Perf kmem 在 kfree 事件中判斷 CPU 號，如果和 kmalloc 時的不同，則視為一次 ping-pong，理想的情況下 ping-pone 越小越好。Ibm developerworks 上有一篇講述 oprofile 的文章，其中關(guān)于 cache 的調(diào)優(yōu)可以作為很好的參考資料。 后面則有根據(jù)被調(diào)用地點(diǎn)的顯示方式的部分。 最后一個部分是匯總數(shù)據(jù)，顯示總的分配的內(nèi)存和碎片情況，Cross CPU allocation 即 ping-pong 的匯總。 Perf timechart很多 perf 命令都是為調(diào)試單個程序或者單個目的而設(shè)計。有些時候，性能問題并非由單個原因所引起，需要從各個角度一一查看。為此，人們常需要綜合利用各種工具，比如 top,vmstat,oprofile 或者 perf。這非常麻煩。 此外，前面介紹的所有工具都是基于命令行的，報告不夠直觀。更令人氣餒的是，一些報告中的參數(shù)令人費(fèi)解。所以人們更愿意擁有一個“傻瓜式”的工具。 以上種種就是 perf timechart 的夢想，其靈感來源于 bootchart。采用“簡單”的圖形“一目了然”地揭示問題所在。 加注了引號的原因是，perf timechart 雖然有了美觀的圖形輸出，但對于新手，這個圖形就好象高科技節(jié)目中播放的 DNA 圖像一樣，不明白那些坐在屏幕前的人是如何從密密麻麻的點(diǎn)和線中找到有用的信息的。但正如受過訓(xùn)練的科學(xué)家一樣，經(jīng)過一定的練習(xí)，相信您也一定能從下圖中找到您想要的。 圖 1. perf timechart 人們說，只有黑白兩色是一個人內(nèi)心壓抑的象征，Timechart 用不同的顏色代表不同的含義。上圖的最上面一行是圖例，告訴人們每種顏色所代表的含義。藍(lán)色表示忙碌，紅色表示 idle，灰色表示等待，等等。 接下來是 per-cpu 信息，上圖所示的系統(tǒng)中有兩個處理器，可以看到在采樣期間，兩個處理器忙碌程度的概括。藍(lán)色多的地方表示忙碌，因此上圖告訴我們，CPU1 很忙，而 CPU2 很閑。 再下面是 per-process 信息，每一個進(jìn)程有一個 bar。上圖中進(jìn)程 bash 非常忙碌，而其他進(jìn)程則大多數(shù)時間都在等待著什么。Perf 自己在開始的時候很忙，接下來便開始 wait 了。 總之這張圖告訴了我們一個系統(tǒng)的概況，但似乎不夠詳細(xì)？ Timechart 可以顯示更詳細(xì)的信息，上圖實(shí)際上是一個矢量圖形 SVG 格式，用 SVG viewer 的放大功能，我們可以將該圖的細(xì)節(jié)部分放大，timechart 的設(shè)計理念叫做”infinitely zoomable”。放大之后便可以看到一些更詳細(xì)的信息，類似網(wǎng)上的 google 地圖，找到國家之后，可以放大，看城市的分布，再放大，可以看到某個城市的街道分布，還可以放大以便得到更加詳細(xì)的信息。 完整的 timechart 圖形和顏色解讀超出了本文的范圍，感興趣的讀者可以到作者 Arjan 的博客上查看。這里僅舉一個例子，上圖中有一條 bar 對應(yīng)了 Xorg 進(jìn)程。多數(shù)時候該進(jìn)程都處于 waiting 狀態(tài)，只有需要顯示什么的時候它才會開始和內(nèi)核通信，以便進(jìn)行繪圖所需的 IO 操作。 將 Xorg 條目放大的例子圖形如下： 圖 2. perf timechart detail 上圖中需要注意的是幾條綠色的短線，表示進(jìn)程通信，即準(zhǔn)備繪圖。假如通信的兩個進(jìn)程在圖中上下相鄰，那么綠線可以連接他們。但如果不相鄰，則只會顯示如上圖所示的被截斷的綠色短線。 藍(lán)色部分表示進(jìn)程忙碌，黃色部分表示該進(jìn)程的時間片已經(jīng)用完，但仍處于就緒狀態(tài)，在等待調(diào)度器給予 CPU。 通過這張圖，便可以較直觀地看到進(jìn)程在一段時間內(nèi)的詳細(xì)行為。 使用 Script 增強(qiáng) perf 的功能通常，面對看似復(fù)雜，實(shí)則較有規(guī)律的計算機(jī)輸出，程序員們總是會用腳本來進(jìn)行處理：比如給定一個文本文件，想從中找出有多少個數(shù)字 0125，人們不會打開文件然后用肉眼去一個一個地數(shù)，而是用 grep 命令來進(jìn)行處理。 perf 的輸出雖然是文本格式，但還是不太容易分析和閱讀。往往也需要進(jìn)一步處理，perl 和 python 是目前最強(qiáng)大的兩種腳本語言。Tom Zanussi 將 perl 和 python 解析器嵌入到 perf 程序中，從而使得 perf 能夠自動執(zhí)行 perl 或者 python 腳本進(jìn)一步進(jìn)行處理，從而為 perf 提供了強(qiáng)大的擴(kuò)展能力。因?yàn)槿魏稳硕伎梢跃帉懶碌哪_本，對 perf 的原始輸出數(shù)據(jù)進(jìn)行所需要的進(jìn)一步處理。這個特性所帶來的好處很類似于 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
[...]該報表分別按進(jìn)程和按系統(tǒng)調(diào)用顯示失敗的次數(shù)。非常簡單明了，而如果通過普通的 perf record 加 perf report 命令，則需要自己手工或者編寫腳本來統(tǒng)計這些數(shù)字。 我想重要的不僅是學(xué)習(xí)目前已經(jīng)存在的這些腳本，而是理解如何利用 perf 的腳本功能開發(fā)新的功能。但如何寫 perf 腳本超出了本文的范圍，要想描述清楚估計需要一篇單獨(dú)的文章。因此不再贅述。 結(jié)束語從 2.6.31 開始，一晃居然也有幾個年頭了，期間每一個內(nèi)核版本都會有新的 perf 特性。因此于我而言，閱讀新的 changelog 并在其中發(fā)現(xiàn) perf 的新功能已經(jīng)成為一項(xiàng)樂趣，類似喜歡陳奕迅的人們期待他創(chuàng)作出新的專輯一般。 本文寫到這里可以暫時告一段落，還有一些命令沒有介紹，而且或許就在此時此刻，新的功能已經(jīng)加入 perf 家族了。所以當(dāng)您讀到這篇文章時，本文恐怕已經(jīng)開始泛黃，然而我依舊感到高興，因?yàn)槲艺诮?jīng)歷一個偉大時代，Linux 的黃金時代吧。 本人水平有限，必然有寫的不對的地方，還希望能和大家一起交流。 |
|
|
