MacでCプログラムを書いていて、プロファイルを調べたくなった。Linuxであればgprofを使うので、とりあえず"which gprof"してみたらMac OSにも入っていた。
しかし、実際に使ってみると期待どおりに動かない。呼出回数は計測されるが時間が計測されないらしく、次の例のように 0.0 が並んでしまった。
$ gprof foo gmon.out
(中略)
% cumulative self self total
time seconds seconds calls ms/call ms/call name
0.0 0.00 0.00 200001 0.00 0.00 _main [79]
0.0 0.00 0.00 200000 0.00 0.00 _f1 [80]
0.0 0.00 0.00 200000 0.00 0.00 _f2 [81]
0.0 0.00 0.00 100000 0.00 0.00 _f3 [82]
0.0 0.00 0.00 1 0.00 0.00 __start [83]
環境は以下のとおり。
$ uname -mrs
Darwin 10.8.0 x86_64
Shark
調べたところ Mac OS で gprof の動作が不完全なのはFAQというか一般常識。代わりに"Shark"を使うのが定石らしい。
そのShark、「MacOSXではgprofが使えない→Sharkを使う - 西尾泰和のはてなダイアリー」で紹介されているように、確かにこれで間に合うのだが、GUIなのが面倒でツラい。1つのプロセスのプロファイルが欲しいのに、たくさんのプロセスを一度にプロファイリングしてその中から選ぶのも冗長な気がしてしまう。
Sharkをコマンドラインで
man shark してみたら実はコマンドラインからも使えて、テキスト形式のレポートも簡単に生成できることがわかった。
以下はfooというプログラムのプロファイルをとってレポートする例。
$ shark -1 -G -i ./foo
shark 4.7.3 (383)
* Option+Esc to start/stop a trace session
* Ctrl+c to stop sampling and quit (any pending samples are processed and saved)
* Batch mode
* Watching task exits
* Profiling limited to foo (PID #33472)
Sampling Config: Time Profile
Timed Samples & Counters
-Sampling begins immediately.
-A sample is taken every 1ms.
-Sampling ends automatically after 30s.
Ready.
Sampling...
0 #これはプログラムfooが出力した数字
Processing samples...( Ctrl-c will cancel processing; No session will be created. )
CHUDData - Analyzing samples...
(略。WARNINGが出力される…)
sharkコマンドが終わると、カレントディレクトリにファイルが2個生成される。
一つは "session_001.mshark" で、shark的には session file と呼ばれるバイナリ。プロファイルの1セッション分の情報が記録されていると思われる。
もう一つは"session_001-report.txt" で、これがテキストのレポート。次のような内容になっている。長い。
$ cat session_001-report.txt
================================================================================
Session
================================================================================
Authored by: dminor11th on 2011-07-17 19:13:45 +0900 (started 2011-07-17 19:13:32 +0900)
Version: Shark 4.7.3-383 (Session v0.3.0)
Host: dminor11th-MacBookPro.local
Operating System: Mac OS X 10.6.8 (10K540)
Machine Class: MacBookPro5,5
Memory: 4096 MB
Processor: 2 x 2530/1064 MHz Intel Core 2 (Penryn) v7.0
Memory Controller: Unknown
IO Controller: UnknownCHUD.framework: v4.7.3
CHUDProf.kext: v366
CHUDUtils.kext: Unknown
================================================================================
Sampling Configuration
================================================================================
Timed Samples & Counters
-Sampling begins immediately.
-A sample is taken every 1ms.
-Sampling ends automatically after 30s.
================================================================================
Module: SharkProfileAnalysis
================================================================================
REPORT:
================================================================================
Active Process Summary
================================================================================
Process [PID] % Total
-----------------------------------------
foo [33472] 100.0%
-----------------------------------------
Total 100.0%
Process [PID] # Total
-----------------------------------------
foo [33472] 12107
-----------------------------------------
Total 12107
===============================================================================================
foo [33472]
% Total Symbol Library Address Length
-----------------------------------------------------------------------------------------------
58.4% strncmp /usr/lib/libSystem.B.dylib 0x7fff8833c280 0xe5
20.0% f2 /Users/dminor11th/temp/foo 0x100000863 0x14c
18.1% f3 /Users/dminor11th/temp/foo 0x100000a8d 0x81
2.4% dyld_stub_strncmp /Users/dminor11th/temp/foo 0x100000dae 0x6
0.1% __vfprintf /usr/lib/libSystem.B.dylib 0x7fff8834662c 0x5304
0.1% __bzero /usr/lib/libSystem.B.dylib 0x7fffffe00600 0x180
0.1% vsnprintf /usr/lib/libSystem.B.dylib 0x7fff8837b454 0x194
(略)
「あーあ、strncmp
が58.4%か…」みたいな感じ。
以上、sharkについて。これでとりあえずは Mac OS でのプロファイラには困らないかなと。