Struts2のUtilTimerStack

Struts2のソースを見てると、よく出てくるUtilTimerStack。
ただ処理時間を計測してログに出力するだけなんだけど、参考になりそうなのでメモ。

以下の2クラスだけで、ThreadLocalを利用したシンプルな作りでした。

• com.opensymphony.xwork2.util.profiling.UtilTimerStack
• com.opensymphony.xwork2.util.profiling.ProfilingTimerBean

使い方のポイント

• 計測したい処理の前後でUtilTimerStackのpushとpopを同じ名前(引数)で呼び出す。
• その処理の内部でも同じ要領で計測できる。
• システムプロパティを指定して実行する。

※log4j.xmlはlog4j.xml簡単テンプレートを見て準備。

サンプルクラスを書いてみました。

public class Sample {
  public static void main(String[] args) throws InterruptedException {
  
    UtilTimerStack.push("root"); // root start

    UtilTimerStack.push("a");    // a start
    Thread.sleep(1000);
    UtilTimerStack.pop("a");     // a end

    UtilTimerStack.push("b");    // b start
    Thread.sleep(500);
    UtilTimerStack.pop("b");     // b end
    
    UtilTimerStack.pop("root");  // root end
  }
}

上記のクラスをシステムプロパティを指定して呼び出します。

java -Dxwork.profile.activate=true Sample

するとこんな感じでログが出力されます。

  [1500ms] - root
  [1000ms] - a
  [500ms] - b

a処理(1000) + b処理(500) = root処理(1500)みたいなことですね。

また、UtilTimerStack.ProfilingBlockインターフェイスのdoProfilingメソッドをオーバーライドしながら呼び出す匿名インナークラス呼び出しなら、1行で記述できます。
上記のクラスのbの部分を書き換えてみました。

public class Sample {
  public static void main(String[] args) throws InterruptedException {
  
    UtilTimerStack.push("root"); // root start

    UtilTimerStack.push("a");    // a start
    Thread.sleep(1000);
    UtilTimerStack.pop("a");     // a end

    UtilTimerStack.profile("b", new UtilTimerStack.ProfilingBlock<String>() {
      public String doProfiling() throws InterruptedException {
        Thread.sleep(500);
        return null;
      }
    });                          // b start - end
    
    UtilTimerStack.pop("root");  // root end
  }
}

処理も結果も同じです。
UtilTimerStackのprofileメソッドは、doProfilingメソッドの実行前にpush、実行後にpopをやってくれるわけですね。