C/C++プログラマのためのDTrace入門

第1回関数フローの採取

はじめに

DTrace とは

皆さんは DTrace をご存知でしょうか?

DTrace は Sun Microsystems のブライアン・キャントリル(Bryan Cantrill)氏によって開発された、汎用情報採取のフレームワークです。

キャントリル氏へのインタビューでも語られているように、カーネルの動作状況を調査/確認することは、これまで非常に困難な作業でした。

しかし、DTrace の登場により、実際に稼動中のシステムのカーネルからも、安全に(かつ低コストで)情報を採取できるようになりました。

また、DTraceによって解析が容易になったことで、これまで解決することができなかったSolarisカーネルの(潜在的だったものも含めた)実装上の問題も、多数改善することができたのだそうです。

カーネル開発に関わったことがある方ならもちろん、通常のアプリケーション開発であっても、次のような点で苦しめられた経験をお持ちであれば、DTraceが如何に画期的であるかを実感できると思います。

  • リリース用のバイナリで発生するバグが、ログ出力するデバッグ用バイナリだと発生しない
  • デバッグ用バイナリは、実行が遅くて作業が進まない
  • 速度低下が怖くて、稼動中のシステムでは解析用のログ出力を有効にできない
  • 丁度良い量/内容のログを採取するのが難しい

利用可能OSの広がり

DTraceはもちろんSolaris10/OpenSolarisで使用することができます。

さらにこれらSolarisプラットフォーム以外でも、その有用性からDTraceを取り込むOSが増えつつあります。2010年2月時点では、以下のようなOSなどで、DTraceを利用することができます。

利用者の多い Linux では、ライセンス上の問題から残念ながら使用することができないのですが、近年シェア増加の著しいMacOS Xでも使用できますので、ぜひとも多くの方にDTraceの有用性を体感して欲しいところです。

本特集の対象読者

カーネルのパフォーマンスチューニングや、システムトラブルの解析といったカーネルに深く関わる領域で話題となることの多いDTraceですが、実のところユーザプログラムの開発においても非常に有用なツールなのです。

そこでこの連載では、C/C++プログラムの

  • 開発
  • テスト/障害解析
  • 性能チューニング

などに関わる方を対象に、DTrace の利用方法を説明したいと思います。

なお、最近は各種インタプリタやサーバ等にもDTrace対応が盛り込まれるようになりましたので、直接C/C++ での開発を行わない方にとっても、この記事は何がしかの参考になるのではないかと思います。

DTrace Day 2010.03 開催のお知らせ

DTrace Day 2010.03と題したDTraceに関する話題に集中的に取り組む勉強会が、2010年3月27日にOpenSolaris勉強会の主催で開催されます。

筆者も何コマか発表を担当しており、本特集で扱う話題のいくつかは、このイベントで先行的に取り上げる予定です。

「DTraceの事が気にはなっていたけど、始めるきっかけがなかった」方や、⁠もっとDTraceを使い倒したい」方はもちろん、⁠何やら面白そうだ」と興味をそそられた方は、ぜひともご参加ください。

事前準備

本特集での説明を読みながら、実際にDTraceを動かしてみる場合、いくつかの事前準備をしておく必要があります。

ルート権限

繰り返しになりますが、DTraceを使用すれば、現在実行中のカーネルからの情報採取すら可能となります。

その反面、これを悪用しようと思えば、他のユーザが実行しているプロセスから、さまざまな情報を不正に入手することも可能になってしまいます。

そのため、DTrace(実際にはdtraceコマンドによるトレース採取)の実行には、ルート権限が要求されます(※1⁠⁠。

しかし幸いなことに、OpenSolarisやFreeBSD等のOSは無償で入手可能ですし、ハードウェアの低価格化/仮想化の普及も手伝って、自前のDTrace利用環境を構築するのは容易と言っても良いでしょう。

もちろん、大規模なソフトウェアの本格的な開発を行うのであれば、相応の環境が必要となりますが、⁠DTrace がどんなものか試してみたい」程度であれば、環境の調達も難しくないと思われます。

プログラム開発環境

連載後半では、自前のプログラムに対する独自のログ採取機構の埋め込みを扱いますので、C/C++ コンパイラが必要になります。

また、同じコンパイル手順の繰り返しを行う可能性を考えて、makeコマンド等も準備しておきたいところです。

C++プログラマの方へ

本特集は「C/C++ プログラマのための~」と題していますし、DTraceはC++開発にとっても十分有用なツールであるのは確かです。

しかし、DTraceで情報を採取する際に得られる関数名は、C++のソースファイルに記述される形式ではなく、リンカ等のために符号化されたものとなります。

符号化された関数名は、⁠わかる人にはわかる」形式ではあるのですが、決して読みやすい形式ではありませんので、出力された符号化済み関数名を復号化するツールが必要です。

このような用途には、c++filtdemコマンドなどが使用可能(※2)です。

コマンド実行時の関数フロー採取

まずはコマンド実行時の関数フローを採取してみましょう。

エディタ等を使用して、リスト1の内容を持つファイルを作成してください。

リスト1 関数フロー採取スクリプトwatch_flow_whole.d
pid$target:$1::entry,
pid$target:$1::return
{
}

これはDTraceによるトレース採取手順を書いたもので、以後このようなDTrace向けのスクリプトを「Dスクリプト」と呼びます。

上記Dスクリプトをwatch_flow_whole.dという名前で保存したなら、以下の要領でdtraceコマンドを実行してみましょう("\" による折り返しは単に可読性向上のためです⁠⁠。

図1 関数フローの採取
$ dtrace -s ./watch_flow_whole.d \
         -F \
         -o /tmp/trace.log \
         -c '/bin/ls -l' \
         ls
dtrace: script './watch_flow_whole.d' matched 63 probes
....
dtrace: pid 11077 has exited

実行結果の前後に見慣れないメッセージが表示されはします(色文字の部分は環境等に応じて変化しますので、違う値でも気にしないでください)が、それ以外は普通に'/bin/ls -l'が実行されたことと思います。

それでは/tmp/trace.logファイル(リスト2)を見てください。

リスト2 採取された関数フロー/tmp/trace.log
CPU FUNCTION
  0  -> _start
  0    -> __fsr
  0    <- __fsr
  0    -> main
  0      -> gstat
  0      <- gstat
  0      -> pem
  0      <- pem
  0      -> new_line
  0      <- new_line
  0      -> pdirectory
  0        -> rddir
  0          -> makename
  0          <- makename
........(以下略)

ファイルに記録されているのは、'/bin/ls -l' を実行した際の'/bin/ls' コマンド内部での関数呼び出しフローです。

呼び出されてすぐに復帰している関数(例: new_lineもあれば、他の関数を順次呼び出している関数(例: pdirectoryもありますね。

ここで重要なのは、関数フローの採取対象となっている'/bin/ls' が、プロファイル採取用の -p オプション付きでビルドされたわけでも、デバッグ用の -g オプション付きでビルドされたわけでもない、ごく普通のバイナリファイル(※3)である点にあります。

D スクリプト/コマンド行指定の詳細

それではここで先ほどの実行例にいったん戻って、使用したDスクリプトや、コマンド行での各引数指定等について説明しようと思います。

まずはコマンド行から見て行きましょう。

リスト3 関数フロー採取のコマンド行
dtrace -s ./watch_flow_whole.d \
       -F \
       -o /tmp/trace.log \
       -c '/bin/ls -l' \
       ls

コマンド行の各要素は、以下の意味を持っています。

表1 コマンド行の構成要素
-s 実行するDスクリプトが格納されているファイル指定します。
本実行例ではファイル watch_flow_whole.dからDスクリプトを読み込みます。
-F 採取されたトレースを表示する際に、関数呼び出しの深さに応じて表示の字下げを行います。
-o 採取したトレースの書き出し先を指定します。すでにファイルが存在する場合、追記的に書き出されますので注意してください。
本実行例では、ファイル/tmp/trace.logに採取したトレースが書き出されます。
-c dtrace 実行に先立って指定されたコマンドを新規に実行します。コマンド実行が完了した段階で dtrace 実行も終了します。
コマンドに対して引数を指定する場合は、本実行例のように引用符で囲むなどして、あくまで -c オプションに対する単一値として指定してください。

上記のオプション記述以降は、dtraceコマンドへの引数とみなされ、Dスクリプト側からは $1, $2, $3, …という記述により参照することが可能です。

この実行例では、"ls"という引数が1つ指定され、Dスクリプト側からは$1という記述で参照することができます。

では次に、Dスクリプトを見てみましょう。

リスト 4 関数フロー採取のDスクリプトwatch_flow_whole.d
pid$target:$1::entry,
pid$target:$1::return
{
}

Dスクリプトの各要素は、以下の意味を持っています。

表2 スクリプトの構成要素
pid プロセスIDで指定されたユーザプロセスにおける、関数の出入りを監視することを意味します。
pid の後ろに続く部分(この例では $targetがプロセスIDとみなされます。
$target dtraceコマンドの-cオプションで指定されたコマンドを実行する際のプロセスIDで置換されます。
本実行例では、'/bin/ls -l' を実行するプロセスのプロセス ID で置換されます。
$1 この位置には、トレース採取対象とするバイナリファイル名を指定します。
$1 は、先述のようにdtraceに指定された第1引数で置換されます。
本実行例では、lsで置換されます。
entry 関数の呼び出しを監視することを意味します。
return 関数からの復帰を監視することを意味します。
{} 波括弧の中には、トレース採取の詳細な処理手順を記述します。
本実行例では特に何もしませんので、空になっています。

つまり今回のdtraceコマンド実行は、次のような意図によるものです(※4⁠⁠。

  • '/bin/ls -l'実行時の関数トレースを採取
  • トレース採取対象は ls バイナリファイルに含まれる情報
  • 関数の出入りを共に監視
  • 関数呼び出しの深さに応じて字下げを実施

実行中プロセスの関数フロー採取

先のDスクリプトの説明を見て

$targetの代わりに直接プロセスIDを指定すれば、実行中プロセスの関数フローも採取できるのでは?

と思われた方もいることでしょう。

ご想像の通り、明示的にプロセスIDを指定することで、実行中プロセスの関数フローも採取することができます。以下のDスクリプトを見てください。

リスト5 関数フロー採取スクリプトwatch_flow_attach.d
pid$1:$2::entry,
pid$1:$2::return
{
}

先のDスクリプトとは以下のような違いこそありますが、基本的には同等のものです(※5⁠⁠。

  • プロセスIDの指定に$targetではなく、第1引数と置換される$1を使用
  • トレース採取対象とするバイナリファイル名に、第1引数と置換される$1ではなく、第2引数と置換される$2を使用

それでは、dtraceコマンドを起動してみましょう。

採取対象としては、HTTPD といった既に稼働中のサーバ(※6)でも良いですし、エディタやbashのような対話的なプログラムなどでも(実行時間調整の都合上)良いでしょう。

dtraceコマンド実行における重要な情報は、①採取対象プロセスのプロセスIDと、②そのプロセスのバイナリファイル名の2点です。以下の実行例中のPIDおよびFILENAME部分は、採取対象に応じて適宜置き換えてください。

図2 実行中プロセスからの関数フローの採取
$ dtrace -s ./watch_flow_attach.d \
          -F \
          PID \
          FILENAME

dtraceコマンド経由でlsコマンドを起動した先の例と異なり、採取対象の出力と採取結果が紛れてしまうことが無いですので、今回は-oオプションを省略してみました。

採取対象で何らかの処理が行われるつど、関数フローが出力されているでしょうか?

なお、実行中プロセスのトレースを行うケースでは、例示したDスクリプトを使用する場合、対象プロセスが終了しても dtrace コマンドそのものは終了しません。適宜Ctrl-C等で中断してください。

追記

dtrace コマンド起動の際に、-c オプションによるコマンド指定の代わりに、-p オプションによるプロセスID指定を行えば、リスト1のwatch_flow_whole.dスクリプトをそのまま使用することができますし、対象プロセス終了時にdtraceコマンドも終了します。

ただし、dbx等のデバッガでattach中のプロセスに対しては、この方法は使用できませんので注意してください。

関数フローの不整合

大変手軽に採取できる関数フローですが、常に完全な関数フローが採取できるわけではありません。

たとえば、以下のようなCプログラムを採取対象にしたとします。

リスト6 最適化確認用プログラム
static void f1(){ /* nop */ }

static void f2(){ f1(); }

static void f3(){ f1(); f2(); }

int
main(int argc,
     const char* argv[])
{
    f3();
    return 0;
}

特にオプション指定をしないコンパイル結果のバイナリファイルからは、以下のような関数フローが採取できます。

リスト7 最適化無しの場合の関数フロー
  0    -> main
  0      -> f3
  0        -> f1
  0        <- f1
  0        -> f2
  0          -> f1
  0          <- f1
  0        <- f2
  0      <- f3
  0    <- main

見ての通り、この関数フローはソースコードと対応が取れています。

しかし、最適化オプション-O3を指定して生成したバイナリファイルや、さらに最適化度の高い-O4を指定して生成したバイナリファイルからは、リスト8やリスト9のようにソースファイルから想定するものとは異なる関数フローが採取されます(※7⁠⁠。

リスト8 -O3最適化時の関数フロー
  0    -> main
  0      -> f3
  0        -> f1
  0        <- f1
  0      <- f3
  0      -> f2
  0      <- f2
  0      -> f1
  0      <- f1
  0    <- main
リスト9 -O4最適化時の関数フロー
  0    -> main
  0    <- main

関数フロー出力において、字下げが綺麗に表示されなかったり、呼び出しと復帰の対応が取れていないといった不整合は、概ねこのような最適化による影響です。

コンパイラの最適化技法の話に踏み込むことになりますので、この場での詳細説明は割愛しますが、最適化が施されたバイナリファイルから採取された関数フローは、必ずしもソースファイルにおける記述とは対応しない場合がある、ということは覚えておいてください。

次回予告

まずは手始めに実行時関数フローを採取してみましたが、いかがでしたでしょうか?

次回は、単に関数の呼び出しフローを追いかけるだけではなく、さらに詳細な情報の採取方法について説明をする予定です。

おすすめ記事

記事・ニュース一覧