記錄一下自己加速程式的心得。重點是: 有個可靠且易於重覆執行的方式, 來計算執行時間。
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 明顯的好處有兩點:
大概會讀一些組語的話, 用 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 後, 再回來看這個吧。