2007年05月25日

オープンソースを楽しむエンジニアの二日目 - ftraceコマンドを書く

はてなブックマークに登録

 昨日のエントリ オープンソースを楽しむエンジニアの一日 では、特定のプログラムの関数呼び出しをトレースする方法を考えてみました。どうやら、gcc のプロファイリング関数と LD_PRELOAD を使えば比較的簡単に実装できそうだという事がわかりました。
今日はこれらの仕組みを利用して、ftraceコマンドを作ってみましたのでご紹介します。
さすがにシェアードライブラリだけ作って「あとは自分でLD_PRELOAD指定してね☆」というのも使い勝手が悪いので、strace や ltrace と同じような操作感覚で使えるようなコマンドにしてみました。プロファイル関数や LD_PRELOAD の使い方の参考にもなると思いますので、もし興味がありましたら以下のリンクからダウンロードしてご利用下さい。
  • ftrace-0.90.tar.gz (4215bytes)

  • ※ 5/26追記: naoyaさんからパッチを頂きましたので適用して差し替えました

    ftraceの内部では libbfd を使ってアドレスからシンボルを参照したり、fork() や pthread_create() などのライブラリ関数をフックしたりしています。
    この辺の内容に関しては、
  • 普通のやつらの下を行け: BFDでデバッグ情報の取得
  • Binary Hacks - ハッカー秘伝のテクニック100選
  • で詳しく解説されています。
    特に Binary Hacks には今回やりたかった事がすべて網羅されていて感動しました。

    あと、現在把握している問題点としては、
    ファイル出力の実装がいまいち(その1)
    -o オプションでファイルに出力する場合、-o tracelog みたいに相対パスで指定すると、対象プログラム内で chdir() したときに出力先が変わってしまいます。できるだけ -o /tmp/log/trace のように絶対パスで指定して下さい。

    ファイル出力の実装がいまいち(その2)
    -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)

    トラックバックURL

    この記事にコメントする

    名前:
    URL:
      情報を記憶: 評価: 顔   
     
     
     
    Blog内検索
    Archives
    このブログについて
    DSASとは、KLab が構築し運用しているコンテンツサービス用のLinuxベースのインフラです。現在5ヶ所のデータセンタにて構築し、運用していますが、我々はDSASをより使いやすく、より安全に、そしてより省力で運用できることを目指して、日々改良に勤しんでいます。
    このブログでは、そんな DSAS で使っている技術の紹介や、実験してみた結果の報告、トラブルに巻き込まれた時の経験談など、広く深く、色々な話題を織りまぜて紹介していきたいと思います。
    最新コメント
    「最新トラックバック」は提供を終了しました。