misc.log

日常茶飯事とお仕事と

自メソッドを呼んだメソッドを知る

ちょっとログ処理の工夫方法を調べてみました。以下のようなシチュエーションで、ログ出力内容を多少マシにするためのネタ。

  • ログは専用クラス(仮称「Logger」と呼ぶ)が出す。
  • 専用クラスにはWriteLogメソッドがある。
  • WriteLogにはメッセージ文字列を渡す。そうすると適当な出力先に文字列が書き出される。

ログを出させたメソッド名を知る

ログの文章にメソッド名を入れて……なんてのはVisual Basic 6.0の頃とかよくやりましたが、呼び元でメソッド名などを文字列として指定してやる、なんて手間が出て、しまいには文字列間違えたり忘れたりして変なログが出たりなんてのはよくありましたよね?なかった??

ですが、.NETになってからリフレクションという自分自身をメタな視点から見る機能がついているので、これを使えば「自分が誰に呼ばれたか?」なんてこともわかったりします。

こんな感じで。

public void WriteLog2(string message)
{
    // 1つ前のスタックフレームを指定して、メソッド名を取り出す
    System.Diagnostics.StackFrame caller = new System.Diagnostics.StackFrame(1);
    string methodName = caller.GetMethod().Name;

    Console.WriteLine("[{0}] {1}", methodName, message);
}

たいていの言語では、メソッド呼び出しのようにある処理から別の処理群へジャンプする際に、「元の場所」をスタックと呼ばれるデータ構造に保管してからジャンプします。スタックはデータを「上へ、上へ」と積み重ねるようなタイプのデータ構造で、メソッド呼び出しでジャンプするたびに「元の場所」が積み重ねて保存され、ジャンプ先処理が終わるたびに「積み重なった一番上の戻り場所」へ順に戻りながら元の処理に帰って行きます。

スタックフレームはこの「積み重ねられた元の場所」1つを表す情報です。また、この積み重ねを連ねたものが「スタックトレース」。なので、スタックトレースを見れば、「どういう順番で呼び出されてその処理に至ったか」がわかります。

上記のコードで、StackFrame()の引数をゼロにすれば「自分自身」、この場合「WriteLog2メソッド」の名前が取れます。

スタックフレームの数

スタックフレームが一体いくつあるのかについては、このようなコードで取得できるスタックトレースオブジェクトを見ればわかります。

System.Diagnostics.StackTrace trace = new System.Diagnostics.StackTrace();

実際、これで生成したtraceオブジェクトをウォッチ機能で見てみると…

f:id:frontline:20131112002034j:plain

こんな感じ。今、スタックトレースの様子がわかりやすいように、前述の「WriteLog2」メソッドが呼ばれるまでには「Main→MainProcess→MainProcess2→MainProcess3→MainProcess4→WriteLog2」という順を追って処理が実行されるようなサンプルを書いています。そして、上記のStackTraceオブジェクト生成は最後の「WriteLog2」で実行しました。

このとき、スタックトレースには0~16の合計17スタックフレームがありますが、実際に自作して記述したコードに該当するのは下図の赤い網掛け部分だけです。

f:id:frontline:20131112002251j:plain

スタックフレーム0~2は、上記のStackTraceオブジェクト生成コード自体の実行でスタックに積まれたコンストラクタや内部処理。そしてスタックフレーム9~16は、.NETアプリケーション開始から自作のMainメソッド実行までの準備処理にあたります。

StackTrace.framesを使えばこうして自作以外の自動生成処理のフレームも取得できますが、前述のStackFrameクラスでコンストラクタに引数として数値を渡す場合、引数ゼロは、上図の赤い網掛け部の先頭、[3]のところに相当します。

というわけで、StackFrame(1)は「1つまえ」のメソッドになった、ということなのですね。

1つ前のメソッドが含まれるクラス名を知る

では、1つ前のメソッドが含まれる「クラス名」は?というと、こんなコードで取れます。以下のサンプルは、前述のメソッド名取得に1行加えて、WriteLineの出力にクラス名も付け加えたものです。

public void WriteLog2(string message)
{
    // 1つ前のスタックフレームを指定して、メソッド名を取り出す
    System.Diagnostics.StackFrame caller = new System.Diagnostics.StackFrame(1);
    string methodName = caller.GetMethod().Name;
    // クラス名も取る
    string className = caller.GetMethod().ReflectedType.FullName;

    Console.WriteLine("[{0}.{1}] {2}", className, methodName, message);
}

このあたりを上手く使えば、ログ出力処理に「ログ出力処理を呼んだクラスとメソッド名」を書き出す機能を持たせることができるのではないでしょうか?

Effective C# 4.0

Effective C# 4.0