2007年05月25日
オープンソースを楽しむエンジニアの二日目 - ftraceコマンドを書く
昨日のエントリ オープンソースを楽しむエンジニアの一日 では、特定のプログラムの関数呼び出しをトレースする方法を考えてみました。どうやら、gcc のプロファイリング関数と LD_PRELOAD を使えば比較的簡単に実装できそうだという事がわかりました。
今日はこれらの仕組みを利用して、ftraceコマンドを作ってみましたのでご紹介します。
さすがにシェアードライブラリだけ作って「あとは自分でLD_PRELOAD指定してね☆」というのも使い勝手が悪いので、strace や ltrace と同じような操作感覚で使えるようなコマンドにしてみました。プロファイル関数や LD_PRELOAD の使い方の参考にもなると思いますので、もし興味がありましたら以下のリンクからダウンロードしてご利用下さい。
※ 5/26追記： naoyaさんからパッチを頂きましたので適用して差し替えました
今日はこれらの仕組みを利用して、ftraceコマンドを作ってみましたのでご紹介します。
さすがにシェアードライブラリだけ作って「あとは自分でLD_PRELOAD指定してね☆」というのも使い勝手が悪いので、strace や ltrace と同じような操作感覚で使えるようなコマンドにしてみました。プロファイル関数や LD_PRELOAD の使い方の参考にもなると思いますので、もし興味がありましたら以下のリンクからダウンロードしてご利用下さい。
※ 5/26追記： naoyaさんからパッチを頂きましたので適用して差し替えました
ftraceの内部では libbfd を使ってアドレスからシンボルを参照したり、fork() や pthread_create() などのライブラリ関数をフックしたりしています。
この辺の内容に関しては、
普通のやつらの下を行け： BFDでデバッグ情報の取得
Binary Hacks - ハッカー秘伝のテクニック100選
で詳しく解説されています。
特に Binary Hacks には今回やりたかった事がすべて網羅されていて感動しました。
あと、現在把握している問題点としては、
というのがありますのでご利用の際はご注意下さい。
おそらくこの手のツールは、このままで利用するよりも、トレースしたい対象にあわせて書き換えながら使うと解析効率が上がると思います。特定の関数が呼ばれたら引数や返値を詳細にログに出してみたりなど、いろいろな応用が考えられるのではないでしょうか。
最後に念のため、アーカイブにも入ってますが README を張り付けておきます。
この辺の内容に関しては、
特に Binary Hacks には今回やりたかった事がすべて網羅されていて感動しました。
あと、現在把握している問題点としては、
- ファイル出力の実装がいまいち（その１）
- -o オプションでファイルに出力する場合、-o tracelog みたいに相対パスで指定すると、対象プログラム内で chdir() したときに出力先が変わってしまいます。できるだけ -o /tmp/log/trace のように絶対パスで指定して下さい。
- ファイル出力の実装がいまいち（その２）
- -o オプションでファイルに出力する場合、対象プログラム内で chroot() されると、chroot 配下のパスにログを出力します。
というのがありますのでご利用の際はご注意下さい。
おそらくこの手のツールは、このままで利用するよりも、トレースしたい対象にあわせて書き換えながら使うと解析効率が上がると思います。特定の関数が呼ばれたら引数や返値を詳細にログに出してみたりなど、いろいろな応用が考えられるのではないでしょうか。
最後に念のため、アーカイブにも入ってますが README を張り付けておきます。
ftrace - 関数トレーサ
【ファイル構成】
Makefile
ftrace-test.c # 動作確認用のテストプログラム
ftrace.c # ftrace本体のソースコード
README # このファイル
【インストール】
$ make
# make install
【使用方法】
$ ftrace
usage: ftrace [-s] [-o file] [-t] [-T] command [arg ...]
commandにはトレースしたいコマンドを指定します。
このコマンドはあらかじめ -finstrument-functions と -g オプション
をつけてコンパイルしておく必要があります。
(例)
$ tar zxvf testtool-1.0.tar.zg
$ cd testtool-1.0
$ CFLAGS="-finstrument-functions" ./configure
$ make debug
※本アーカイブには、すぐに動作を確認できるよう ftrace-test という
テストコマンドが付属しています。
■ コマンドラインオプション
-s トレース結果をsyslogに出力します
-o トレース結果をファイルに出力します
プロセス毎に別ファイルになります(file.pid)
-t "-o"オプションと共に指定します
スレッド毎に別ファイルになります(file.pid.thread_id)
単体で指定されても意味は持ちません
-T 出力結果にスレッドIDを追加します
出力書式のプロセスIDの部分が [pid.thread_id] となります
※ -o も -s も指定されなかった場合は stderr に出力します
【出力書式】
ftraceはターゲットプログラムの関数コールの他に以下の関数呼び出し
もトレースします。
- fork()
- pthread_create()
- pthread_exit()
それぞれのログ出力は以下のような形式になります。
実行時刻 [プロセスID] ソースファイル名: 関数名(enter|exit)
実行時刻 [プロセスID] fork() : PID=xxxxx
実行時刻 [プロセスID] pthread_create(): result=xxx TID=xxx
実行時刻 [プロセスID] pthread_exit() : retval=xxx
【ftrace-testについて】
ftraceの動作をすぐに見ることができるテスト用のコマンドです
usage: ftrace-test [-f|-t]
option
-f forkを使います
-t pthread_createを使います
【実行例】
~$ ftrace ftrace-test
15:05:42.435920 [10412] ftrace-test.c : main(enter)
15:05:42.474754 [10412] ftrace-test.c : foo(enter)
15:05:42.475352 [10412] ftrace-test.c : foo(exit)
15:05:42.504625 [10412] ftrace-test.c : bar(enter)
15:05:42.505060 [10412] ftrace-test.c : foobar(enter)
15:05:42.505358 [10412] ftrace-test.c : foobar(exit)
15:05:42.505652 [10412] ftrace-test.c : foobar(enter)
15:05:42.505945 [10412] ftrace-test.c : foobar(exit)
15:05:42.563212 [10412] ftrace-test.c : bar(exit)
15:05:42.563650 [10412] ftrace-test.c : foo(enter)
15:05:42.563950 [10412] ftrace-test.c : foo(exit)
15:05:42.564299 [10412] ftrace-test.c : main(exit)
$ ftrace ftrace-test -f # fork()使用
16:01:54.646211 [19234] ftrace-test.c : main(enter)
16:01:54.648890 [19235] fork() : pid=00000
16:01:54.649860 [19235] ftrace-test.c : foobar(enter)
16:01:54.650495 [19235] ftrace-test.c : foobar(exit)
16:01:54.650555 [19235] ftrace-test.c : foo(enter)
16:01:54.650612 [19235] ftrace-test.c : foo(exit)
16:01:54.650668 [19235] ftrace-test.c : bar(enter)
16:01:54.650725 [19235] ftrace-test.c : foobar(enter)
16:01:54.650781 [19235] ftrace-test.c : foobar(exit)
16:01:54.650836 [19235] ftrace-test.c : foobar(enter)
16:01:54.650892 [19235] ftrace-test.c : foobar(exit)
16:01:54.650947 [19235] ftrace-test.c : bar(exit)
16:01:54.651002 [19235] ftrace-test.c : foo(enter)
16:01:54.651057 [19235] ftrace-test.c : foo(exit)
16:01:54.651112 [19235] ftrace-test.c : main(exit)
16:01:54.653672 [19234] fork() : pid=19235
16:01:54.654213 [19234] ftrace-test.c : foo(enter)
16:01:54.654320 [19234] ftrace-test.c : foo(exit)
16:01:54.654377 [19234] ftrace-test.c : bar(enter)
16:01:54.654434 [19234] ftrace-test.c : foobar(enter)
16:01:54.654489 [19234] ftrace-test.c : foobar(exit)
16:01:54.654544 [19234] ftrace-test.c : foobar(enter)
16:01:54.654598 [19234] ftrace-test.c : foobar(exit)
16:01:54.654653 [19234] ftrace-test.c : bar(exit)
16:01:54.654707 [19234] ftrace-test.c : foo(enter)
16:01:54.654762 [19234] ftrace-test.c : foo(exit)
16:01:54.654818 [19234] ftrace-test.c : main(exit)
$ ftrace -T ftrace-test -t # pthread_create() 使用
16:04:45.978241 [19237.3083928224] ftrace-test.c : main(enter)
16:04:45.978759 [19237.3083928224] pthread_create(): result=0 TID=3083926448
16:04:45.981685 [19237.3083926448] ftrace-test.c : workthread(enter)
16:04:45.982088 [19237.3083926448] ftrace-test.c : tf1(enter)
16:04:46.021797 [19237.3083926448] ftrace-test.c : tf1(exit)
16:04:46.022549 [19237.3083926448] ftrace-test.c : tf2(enter)
16:04:46.022857 [19237.3083926448] ftrace-test.c : tf2(exit)
16:04:46.023170 [19237.3083926448] pthread_exit() : retval=(nil)
16:04:46.025473 [19237.3083928224] ftrace-test.c : foo(enter)
16:04:46.105954 [19237.3083928224] ftrace-test.c : foo(exit)
16:04:46.106757 [19237.3083928224] ftrace-test.c : bar(enter)
16:04:46.107139 [19237.3083928224] ftrace-test.c : foobar(enter)
16:04:46.107442 [19237.3083928224] ftrace-test.c : foobar(exit)
16:04:46.145322 [19237.3083928224] ftrace-test.c : foobar(enter)
16:04:46.145690 [19237.3083928224] ftrace-test.c : foobar(exit)
16:04:46.145993 [19237.3083928224] ftrace-test.c : bar(exit)
16:04:46.146585 [19237.3083928224] ftrace-test.c : foo(enter)
16:04:46.179165 [19237.3083928224] ftrace-test.c : foo(exit)
16:04:46.179544 [19237.3083928224] ftrace-test.c : main(exit)
klab_gijutsu2 at 21:17│Comments(0)│TrackBack(0)
