記錄一下自己加速程式的心得。重點是: 有個可靠且易於重覆執行的方式, 來計算執行時間。
logging
我最常用的方法是手動 logging 計算函式的執行時間。通常我有兩種作法
- 在函式的開頭取得系統時間, 離開時再最得系統時間, 兩者相減得到執行的時間。 [*1]
- 使用一個會自動附上 timestamp 的 logging function, 會記錄這次到上次 log 的時間差, 或事後用外部 script 算出各筆 log 之間的時間差。這樣可以在懷疑的函式不同地方做 log, 了解各區塊的執行時間。
優點PS *1 實作細節
- 像 Python 有 decorator 的語法, 可以寫個 log_time(), 內容是「取得時間、執行目標函式、取得時間並記錄相減結果、傳回目標函式的傳回值」, 再用 decorator 的語法加到有興趣的函式上。
- C++ 的話, 可以寫個 class LogTime, 在 constructor 以及 destructor 計時, 達到同樣效果。然後在目標函式的第一行宣告 LogTime log。
- 可以明確抓出函式花的時間, 對於「加快程式」來說, 是最確實的反應。不論是真的 CPU bound 或 lock 或 I/O 導致緩慢, 都會反應在 log 裡。
- 可自行控制 log 函式的細膩度, 比方說先抓出 sort() 最花時間, 再來到 sort 裡放 log, 觀察在 sort 的那部份最花時間。
缺點
- 得自己手動在懷疑的部份加上 log 函式, 不方便大範圍無腦偵查。
使用 profiler
linux - Alternatives to gprof 列了不少工具, 大概掃過了這篇, 也試了一下, 這部份的經驗很淺, 下面可能會有些錯誤, 像是對工具的錯誤認知, 或少用了什麼功能而覺得不好用。
感覺上這類工具只能反應出真的 CPU bound, 若原因是 lock 或 I/O 拖慢效能, 需要用其它管道查明源頭。
我是在 VirtualBox 裡的 Ubuntu 11.04 試用。選用的前提是對實際執行的負擔要低, 愈接近原本情況愈好。
perf
perf 很容易使用, 基本指令:
- perf record CMD # 執行並記錄 CMD
- perf record -p PID # 記錄 process PID
- perf report # 看報告
- sudo perf top # 顯示即時全系統狀況
但不知為啥占最多時間的總是奇怪的東西, 我寫個 for-loop 一直做加法, 結果部份時間花在 snd_ac97_codec (聲音?)。移除 PulseAudio 後, 變成花在 binfmt_misc。對於其它不是像 busy loop 的程式, 有可能最花時間的部份變成 snd_ac97_codec 或 binfmt_misc。讓我不知是否能相信它的結果。
2013-04-17 更新
在實體機器 (非VM) 上執行 perf 後, 就沒有一堆怪東西了。試用的結果相當滿意, perf 明顯的好處有兩點:
- 幾乎不會拖慢執行速度
- 指令簡單易上手, 可參考 Tutorial - Perf Wiki 的教學。
大概會讀一些組語的話, 用 perf 的效果更好, 可以在 perf report 後再觀看各函式最花時間的位置, perf 會嘗試對回組語附近的原始碼。注意 perf 觀察到的是 sample 結果, sample 量愈多, 可以採信的程度愈深。比方說 sample 量「不夠多」的話, 可以參考那個函式最花時間, 但可能不適合參考函式內最花時間的程式是那幾行。
oprofile
oprofile 也不難用, 但在 VM 裡會有些問題, 且無法發揮完整功能。解決的方法是在啟動 oprofile daemon 前就執行 sudo modprobe oprofile timer=1。若有先執行過 oprofile, 即使照著上面說的執行 --deinit, 結果在執行 modprobe 時會卡住。用 strace 看的結果, 像在 busy-waiting oprofile 結束。重開機後, 在執行 oprofile 前先執行 modprobe 就 ok。
小結相關指令如下:
- sudo modprobe oprofile timer=1 # 可配合 dmesg | grep oprofile 看目前是否有用 timer interrupt
- sudo opcontrol --start --verbose --no-vmlinux # 見後面的說明
- sudo opcontrol --reset # 將記錄歸零
- sudo opcontrol --dump # 將記錄寫到硬碟
- opreport # 顯示整體摘要
- opreport -l PROGRAM # 顯示 PROGRAM 的取樣情況
- opreport -l PROGRAM -g # 加上原始碼位置和行號
- sudo opcontrol --shutdown # 結束 daemon
啟動 daemon 後, 之後就是一直
- ./PROG
- sudo opcontrol --dump
- opreport -l ./PROG
- sudo opcontrol --reset
但是在沒有 vmlinux 的情況, 會看到有大部份時間花在 no-vmlinux (kernel 裡)。所以除非自己寫的部份真的相當忙, 幫助也是有限。我在 Ubuntu 上找了一陣子, 有文章提到裝別人弄好的 vmlinux, 不過沒有成功, 就先忽略這件事了。
對照 perf 和 oprofile 反應的數據, 兩者各有一塊不明的部份占去最多時間, 其它項目的相對大小很接近, 多少算是提示。但我會懷疑數據反應出的實際影響。同一個函式, perf 可能說 20%, 但 oprofile 說 15%, 結果我也無法明白它們實際的執行時間有多長。
GooglePerformanceTools
gperftools 看起來也滿不錯的 --- 直到我抓下來看到 INSTALL 裡對於 x86-64 的注意事項後。於是我決定之後再來試用它, 至少先玩過 tcmalloc 後, 再回來看這個吧。
perf 你要跟他說你想要紀錄什麼event，
回覆刪除他預設是紀錄什麼我到現在還搞不清楚。
我看到的是用 stall-cycle
@wens, re: "perf 預設紀錄什麼 event"
回覆刪除perf 預設紀錄的 event 只有一個： "cycles" -- 即在 CPU 跑一定週期後取樣。
列出紀錄檔中 event 的種類可用：
perf evlist -i perf.data
"cycles" event 細節見: https://perf.wiki.kernel.org/index.php/Tutorial#Default_event:_cycle_counting
@fcamel,
1. 用詞上通常說:『profiler 分兩類：instrumenting based 和 sampling based』。instrumenting / instrumentation based profiler 中的 "instrument" 一詞指的是『加 code』。
2. Re: 『最花時間的部份變成 snd_ac97_codec 或 binfmt_misc。不知是否能相信它的結果』
若已知程式是 CPU bound 在 userspace 則可忽略花在 kernel space 的時間。我們知道 snd_ac97_codec 與 binfmt_misc 都是在 kernel 內的，因為工具列 report 時欄位有寫，且在你的測試程式內無此名稱的符號。基本上 sampling based profiler 對『program counter 落點』的紀錄可信，要出錯會是在 symbolic name 與驅動取樣的 event 上。
3. 你用 VirtualBox 會看到 snd_ac97_codec 這張模擬出來的音效卡的 driver 會出現在 profile 內，代表模擬硬體 / driver 跟 pulseaudio 互動不良，建議你 Linux VM 統一把音效卡移除掉。
高 CPU 可能原因： pulseaudio 的 timer based scheduling 會希望 audio codec driver 能盡量準確的回報 PCM data 播到第幾個 byte 由此導出資料消耗率與下次 wakeup 時間。這邊的的演算法會用到早期 driver 只用 interrupt driven mode 驅動時沒用到的 code path。
binfmt_misc 會出現比較奇怪。此機制通常是用來『透過模擬器執行不同 OS 或不同 CPU 的可執行檔的』（可看一下 /proc/sys/fs/binfmt_misc/)
4. event sampling profiler 在 Virtual Machine 跑會少功能而且取樣比較不準，因為 CPU 硬體原本提供的 cycle count, cache miss 等 event （這需要 driver）在 VM 內存不到。若 sampling profiler 無法使用 CPU performance counter 硬體 而改用『純軟體』的 timer interrupt來取樣的話，在 VM 內 timer interrupt 也比較不準，測量誤差也會高些(?)。
perf 不要跑在 VM 下的時候，其實真的很容易上手，且熟悉後可增加紀錄的事件 (cache miss, syscalls, kernel 內的 VM, block I/O, filesystem 等) 越鑽越深。
5. profiler 為何想要 "vmlinux"
perf 與 oprofile 想要的其實是編譯 kernel 時 gcc -g 產生的 debuginfo，
在 Fedora 下 "yum install kernel-debuginfo" 即可。Fedora 這邊有做好不是意外。
vmlinux 是 kernel 的 ELF image，格式同我們自己編譯出來的可執行檔。 除了讀 vmlinux 外，perf 與 oprofile 也懂得讀 /usr/lib/debug 下的 separate debug info 檔案取得同樣資訊。另外，Linux kernel 預設 CFLAGS 是沒加 -g 的，因為編譯會慢不少，且 debug info 頗大。
另外, "perf script" 類似 "perf report" 但輸出一行一個文字紀錄，滿有用的。
回覆刪除例: "perf record -e signal:signal_deliver" 用 "perf script" 可看到 signal number。