2013年03月08日

Log5j (Not Log4j) - Java High Performance Logging Library

アプリケーション開発においてハイ・パフォーマンス・ロギングへの注意は必要でしょうか?

media-seek-forward-3

大部分のアプリケーションでは必要無いかもしれません。しかし、もし貴方のアプリケーションがロギング要件は出来るだけ変更せずに秒オーダーで数千~数万トランザクション/セッションを管理し、なおかつタイムアウトの発生を極力避け無ければならない状況になったらどうでしょうか?

log5j を利用すれば log4j で実装したロギング処理をとても簡単にハイ・パフォーマンス化することが可能です。

Log5jのダウンロードと設定


Log5j のバイナリはGoogle Codeからダウンロードすることが出来ます。

Downloads - log5j - A modern facade on top of log4j - Google Project Hosting

ソースからビルドする場合は、Bitbucketにあるプロジェクト・ホームへ。

後もう一つ、Apache log4j をダウンロードしてクラス・パスに設定すれば準備はおしまい。

log5j_01


Log5j の基本的な使い方と特徴


log5j は log4j のメソッド・スタイルと互換性があり、log4j のコードをそのまま引き継ぐことも出来ますが、幾つか特徴もあります。

 private static final Logger log = Logger.getLogger();
 //private static final Logger log = Logger.getLogger(false); // Disable Thread Model
 //private static final Log log = LogFactory.getLog(); // 2.x or Later
 
 public void info() {
  String iMessage = "info";
  log.info("log5j %s", iMessage);
  //log.i("log5j %s", iMessage); // 2.x or Later
 }

まず、log4j であれば必要になる getLogger()メソッドでのクラス名設定は必要はありません。

// log4j style
private static Logger log = Logger.getLogger(MyLog4jApp.class.getName());

また、log5j では Logger オブジェクトの処理はスレッドであり、info(), debug()などのメソッドは基本的に非同期で実行されます。
※ Logger.getLogger(false) とすれば log4j と同じく同期モデルにすることも可能。

version 2.x 以降では LogFactory.getLog() を使ってLogオブジェクトを取得することも出来ますが、こちらは log4j とはインタフェースの互換性が無く、よく考えてから利用する必要があります。

ログ出力にも特徴があり、 printf スタイルを使ってログ・メッセージを記述することが出来ます。

  log.info("log5j %s", iMessage);
  //log.i("log5j %s", iMessage); // 2.x or Later

実はここにもハイ・パフォーマンスの秘密が隠されています。実際の priority 設定においてINFOレベルが無効であれば、ここで指定したメッセージ(Stringオブジェクト)の連結は行われません。これによってStringオブジェクトの連結を遅延評価させ、メモリ、CPUの利用を最小限化することが出来ます。
※但し、log4j の高階層ラッパー/ユーティリティである log5j は、単純に Logger インスタンスを生成した時点の基底値であれば log4j に比較してより多くのメモリを消費します。


Log5j によるパフォーマンスの改善


まず、次のコードを実行してみましょう。

public class MyLog5jApp {

 private static final Logger log = Logger.getLogger();
 
 public void info() {
  String iMessage = "info";
  log.info("log5j %s", iMessage);
  //log.i("log5j %s", iMessage); // 2.x or Later
 } 
 
 public static void main(String[] args) {
  MyLog5jApp l5j = new MyLog5jApp();    
  l5j.info();  
  System.out.println("************** END **************");    
  //LogManager.shutdown(); // Shutdown Logging Threads.
 }
}

次のような出力になるはずです。

************** END **************
2013-03-07 21:05:34  INFO MyLog5jApp log5j info  

この結果から分かる通り、log5j を使うと info() メソッドは非同期で実行され、ロギング処理によって他のコード(ビジネス・ロジック)の実行がロックされることはありません。これには良い面(アプリケーション本来の目的に優先的に時間を割くことが出来る)と悪い面(ログ出力の完全性が保証されない)がありますが、利用者側にハイ・パフォーマンスという選択肢(柔軟性)が生まれることは大変良いことでしょう。

続いて、メッセージ生成における遅延評価の効果をピュア log4j の場合と比較してみます。

次のコードでは100000000回(1億回) log.debug() を呼び出しています。これを log4j の priority 設定をINFO以上、つまり実際にはDEBUG出力しない状態で実行し、時間とメモリ使用量をピュア log4j の場合と比較します。
(log4j と同様の条件で測定するため、Thread は無効にしています)

 private static final Logger log = Logger.getLogger(false);
 
 public static void main(String[] args) {
  MyLog5jApp l5j = new MyLog5jApp();    
  l5j.perform();
 }
 
 public void debug(int i) {
  log.debug("log5j debug - %s", i);
 }
 
 public void perform() {
  int numLoop = 100000000;
  log.info("Starting debug loop... " + numLoop);
  long start = System.currentTimeMillis();
  for (int i=0; i<numLoop; i++) {
   debug(i);   
  }
  long end = System.currentTimeMillis();
  long total = Runtime.getRuntime().totalMemory();
  long free = Runtime.getRuntime().freeMemory();
  log.info("time: %s, mem: %s", end - start, total - free);
 }

ちなみに比較対象となるピュア log4j での debug() メソッド実装は次の通りです。

 public void debug(int i) {
  log.debug("log4j debug - " + i);
 }

この2つを実行すると次のような結果になりました。

-- pure log4j
2013-03-07 23:17:36  INFO MyLog4jApp Starting debug loop... 100000000
2013-03-07 23:17:49  INFO MyLog4jApp time: 13408, mem: 11585952

-- log5j
2013-03-07 23:18:26  INFO MyLog5jApp Starting debug loop... 100000000
2013-03-07 23:18:28  INFO MyLog5jApp time: 1842, mem: 5313056

log5j ではログ出力に伴う文字列連結が遅延評価されたことにより、実行速度・メモリ使用量共に改善しているのが分かります。

これさえ覚えておけば、いざという時に、貴方が望まないパフォーマンス戦争に巻き込まれたとしても勝利を手に入れることが出来るかもしれませんね!


[24時間365日] サーバ/インフラを支える技術 ‾スケーラビリティ、ハイパフォーマンス、省力運用 (WEB+DB PRESS plusシリーズ)
安井 真伸 横川 和哉 ひろせ まさあき 伊藤 直也 田中 慎司 勝見 祐己
技術評論社
売り上げランキング: 7,236

ハイパフォーマンスWebサイト ―高速サイトを実現する14のルール
Steve Souders スティーブ サウダーズ
オライリージャパン
売り上げランキング: 117,039

Posted by netbuffalo at 20:30│Comments(0)TrackBack(0)プログラミング | Java


この記事へのトラックバックURL

http://trackback.blogsys.jp/livedoor/netbuffalo/4396927

コメントする

名前
URL
 
  絵文字