第2章 アーキテクチャ

Logbackのアーキテクチャ

logback の基本的なアーキテクチャは、さまざまな状況に対応できるよう、十分に汎用的になっています。今のところ、logbackは三つのモジュールに分割されています（logback-core、logback-classic、logback-access）。

coreモジュールは、他の二つのモジュールの足回りとして使用されています。classicモジュールは、 coreを拡張するものです。classic モジュールは、著しく改善されたバージョンのlog4jとも考えられます。logback-classic は SLF4J API を直接実装しているので、log4j や java.util.logging(JUL)などの他のロギング実装と切り替えることができます。三つ目のaccessと呼ばれるモジュールは、HTTPのアクセスログ機能を提供するため、サーブレットコンテナと統合しています。access モジュールについては別のドキュメントに記載されています。

このドキュメントの残りの部分では、logback-classicモジュールのことを "logback" と表記しています。

ロガー、アペンダー、レイアウト

logback は三つの主要なクラス（Logger 、 0}Appender、Layout ）で成り立っています。これらの三つのコンポーネントが協調することで、開発者はメッセージを適切な種類、レベルでロギングできるようになっています。また、書式化や出力先を実行中に変更できるようにもなっています。

Loggerクラスは、logback-classicモジュールに含まれています。一方、 AppenderとLayoutインタフェイスは、logback-coreモジュールに含まれています。logback-core モジュールは共通モジュールなので、logger の責務を含まないのです。

ロガーコンテキスト

どんなロギングAPIであっても単純なSystem.out.printlnに勝る第一の、そして最大の利点があります。それは、特定のロギング式を無効にしつつ、他のロギング式には一切影響を与えない機能です。この機能は、ロギング空間、すなわち、すべてのロギング式からなる空間が、開発者の選択した基準に基いて分類されていることを前提としています。logback-classic モジュールにおいて、この分類は logger に固有のものです。全てのロガーは LoggerContext に接続します。LoggerContext には、接続してきたロガーを階層的な木構造として配置する責務があります。

ロガーは名前を持ったエンティティです。名前は大文字と小文字が区別され、階層的な命名規則に従うようになっています。

たとえば、"com.foo"という名前のロガーは、"com.foo.Bar" というロガーの親になります。同様に、 "java"は"java.util"の親であると同時に、"java.util.Vector" の祖先になります。この命名スキームは、ほとんどの開発者がきちんと理解しなければならないものです。

ルートロガーは、ロガー階層の最上位に存在するものです。複数の階層構造すべてに含まれるという意味で、例外的な存在です。他のロガーと同じように、名前で取得することができます。こんな風に。

Logger rootLogger = LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME);

他のロガーも、org.slf4j.LoggerFactoryクラスの静的クラスメソッドであるgetLoggerによって取得することができます。このメソッドは、パラメータとして欲しいロガーの名前を受け付けます。Loggerインタフェイスの基本的なメソッドをいくつか以下に示します。

package org.slf4j; 
public interface Logger {

  // Printing methods: 
  public void trace(String message);
  public void debug(String message);
  public void info(String message); 
  public void warn(String message); 
  public void error(String message); 
}

有効レベル（別名レベルの継承）

ロガーにはレベルを割り当てることができます。利用できるレベル（TRACE、DEBUG、INFO、WARNおよびERROR）はch.qos.logback.classic.Levelクラスに定義されています。logback では Level クラスは final として宣言されており、サブクラス化出来ないことに注意してください。より柔軟性のあるアプローチはMarkerオブジェクトとして利用可能です。

レベルの割り当てられていないロガーは、直近の祖先に割り当てられたレベルを継承します。より正確に言うと次のようになります。

最終的に全てのロガーがレベルを継承できるように、ルートロガーには必ずレベルが割り当てられています。デフォルトではDEBUGになっています。

以下は、レベル継承ルールに従ってロガーに割り当てられた有効レベルの例です。

上記の例では、ルートロガーにだけレベルが割り当てられています。レベルはDEBUGで 、他の全てのロガーに継承されています。

上記の例では、​​すべてのロガーにレベルが割り当てられています。レベルの継承は何も仕事をしていません。

上記の例では、ルートロガーにDEBUG、XにINFO、X.Y.ZにERRORが割り当てられています。X.Yは親であるXからレベルを継承しています。

上記の例では、ルートロガーにDEBUG、XにINFOが割り当てられています。X.YおよびX.Y.Zは、最も近い親からレベルを継承しています。

印字メソッドと基本的な選択ルール

定義によると、印字メソッドはロギング要求のレベルを決定するものです。例えば、Lがロガーのインスタンスだとすると、式L.info("..")はINFOレベルのロギングであることになります。

ロギング要求は、そのロガーの有効レベル以上である場合に有効となります。そうでなければ、ロギング要求は無効になります。前述のように、レベルが割り当てられていないロガーは最も近い祖先​​から継承します。このルールは次のように要約できます。

このルールはlogbackの中核を為すものです。レベルは次のような順序であることを想定しています。TRACE < DEBUG < INFO < WARN < ERROR

以下は、選択ルールをより具体的に示したものです。垂直方向のラベルはロギング要求のレベルpです。そして水平方向のラベルはロガーの有効レベルqです。行（ロギング要求のレベル）と列（ロガーの有効レベル）の交点が、基本的な選択ルールの適用結果を表しています。

選択ルールのコード例を次に示します。

import ch.qos.logback.classic.Level;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
....

// "com.foo"という名前のロガーを取得します。
// ロガーのインスタンスはレベルを設定するために ch.qos.logback.classic.Logger とします。
ch.qos.logback.classic.Logger logger = 
        (ch.qos.logback.classic.Logger) LoggerFactory.getLogger("com.foo");
// レベルにINFOを設定します。setLevel() メソッドは logback のロガーにしかありません。
.setLevel(Level. INFO);

Logger barlogger = LoggerFactory.getLogger("com.foo.Bar");

// このロギング要求は有効です。WARN >= INFO
logger.warn("Low fuel level.");

// このロギング要求は無効です。DEBUG < INFO. 
logger.debug("Starting search for nearest gas station.");

// "com.foo.Bar" という名前のロガーは、"com.foo" ロガーからレベルを継承します。
// したがって、このロギング要求は有効です。INFO >= INFO. 
barlogger.info("Located nearest gas station.");

// このロギング要求は無効です。DEBUG < INFO.
barlogger.debug("Exiting gas station search");

ロガーの取得

LoggerFactory.getLoggerを呼び出しましょう。 同じ名前なら、常に同じロガーインスタンスへの参照を返します。

例えば次のような場合は常に同じインスタンスを返します。

Logger x = LoggerFactory.getLogger("wombat"); 
Logger y = LoggerFactory.getLogger("wombat");

xとyは、完全に同じオブジェクトを参照します。

このように、一度ロガーのインスタンスを設定すれば、わざわざ参照を渡さなくても、コード中のどこででも同じインスタンスを取得することができます。現実世界の生物の親子関係とは矛盾していますが、logback のロガーは親と子のどちらが先に生成されても問題ありません。ただし、「親」ロガーから子孫ロガーを見つけようとするときは、事前にインスタンス化しておく必要があります。

logback の実行環境の設定は、アプリケーションの初期化時に行われるのが一般的です。設定ファイルを読み込むようにするとよいでしょう。方法についてはすぐ後で説明します。

logback では、コンポーネントごとにロガーの名前を付けるのが簡単です。ロガーをクラスごとにインスタンス化すれば、それぞれのロガーの名前はクラスの完全名になります。これはロガーを定義する簡単かつ便利な方法です。クラスの完全名であるロガーの名前をログに出力するようになっていれば、メッセージを出力した箇所を特定するのは簡単です。ですが、これはロガーの命名戦略としてごく一般的な方法の一つでしかありません。logback 自体にロガーのインスタンス数の制限はありません。従って、開発者は自由に名前を付けることが出来ます。

とはいえ、ロガーの名前にそれが置かれたクラスの完全名を付けることは、一般的に最も良い方法であるということが共通認識になっています。

アペンダーとレイアウト

ロガーのレベルに応じてロギング要求の有効無効を選択できる機能は、logbackの機能の一部でしかありません。logback は、ロギング要求を複数の宛先の送りつけることができます。logback では、宛先のことをアペンダーと呼びます。現在利用できるアペンダーには、コンソール、ファイル、MySQLやPostgreSQLやOracleなどのデータベースへのリモート接続、JMS、リモートSyslogデーモンなどがあります。

ロガーには一つ以上のアペンダーを割り当てることができます。

指定されたロガーにアペンダーを割り当てるには、addAppenderメソッドを使います。有効なロギング要求は、ロガーに割り当てられた全てのアペンダーについて、階層関係が上位のアペンダーから順に転送されます。別の言い方をすると、ロガー階層からアペンダーも引き継ぐということです。例えば、ルートロガーにコンソールアペンダーを割り当てたなら、有効なロギング要求は少なくともコンソールに出力されることになります。さらに、ロガーLにファイルアペンダーが割り当てられたなら、Lとその子孫全てにおいて、有効なロギング要求はコンソールとファイルの両方に出力されます。ロガーの additivity フラグを false に設定すれば、アペンダーを継承しないように振る舞いを変更することができます。

アペンダーの加算ルールをまとめると次のようになります。

利用者は、ほとんどの場合出力先だけでなく出力形式もカスタマイズしたがるでしょう。アペンダーとレイアウトを関連付けることで実現できます。レイアウトは、利用者の指定したとおりにロギング要求を整形するものです。一方、アペンダーは整形されたメッセージを指定された宛先に転送します。利用者は、logback の標準配布物に含まれるPatternLayoutを使って、C言語のprintf関数で使うような変換指示子によって出力形式を指定します。

PatternLayoutの変換パターンが "%-4relative [%thread] %-5level %logger{32} - %msg%n" のとき、出力は次のようになります。

176  [main] DEBUG manual.architecture.HelloWorld2 - Hello world.

最初のフィールドはプログラムが開始してからの経過時間をミリ秒にしたものです。二番目のフィールドはログ要求を行ったスレッドです。三番目のフィールドはログ要求のレベルです。四番目のフィールドはログ要求を行ったロガーの名前です。'-' より後のテキストはログ要求に指定されたメッセージになります。

パラメータ化ロギング

ogbakc-classicのロガーは、SLF4JのLoggerインターフェイスに含まれる一つ以上のパラメータを受け取る出力メソッドを実装しています。これらのメソッドは、コードの読みやすさへの影響を最小限に抑えながら、性能を改善するために用意されたものです。

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

こんな書き方をしているロギング式があった場合、メッセージを組み立てるために、整数iとentry[i]を文字列にするコスト、文字列を連結する中間的なコストがかかるでしょう。これは、ロギング要求が有効かどうかに関わらずかかってしまうコストです。

パラメータ構築のコストを回避するには、ロギング式全体をテスト条件で囲む方法があります。

if(logger.isDebugEnabled()) { 
  logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
}

こうすると、DEBUGレベルのロギング要求が無効になっていればパラメータ構築のコストはかからないでしょう。しかし、有効になっている場合、debugEnabledとdebugのそれぞれでロガーのレベルが有効かどうかを判定することになってしまいます。ロガーのレベルの評価はロギング要求に対して1%未満の時間しかかからないので、実際のオーバーヘッドは些細なものです。

より良い方法

メッセージフォーマットに基づいた便利な方法があります。entryが何らかのオブジェクトを指すものとして、次のように書くことが出来ます。

Object entry = new SomeObject(); 
logger.debug("The entry is {}.", entry);

ロギング要求が有効かどうかを判断した後にだけ、そして、それが有効な場合にだけ、ロガーはメッセージを書式化して、'{}' を entry の文字列表現で置き換えます。つまり、ロギング要求が無効な場合、このやり方だとパラメータ構築のコストが発生しません。

以下の二行からはまったく同じ出力が得られます。しかし、 ロギング要求が無効な場合、二行目のやり方は一行目のやり方に比べて少なくとも30倍は遅くなるでしょう。

logger.debug("The new entry is "+entry+".");
logger.debug("The new entry is {}.", entry);

二つ置換場所を指定することもできます。たとえば、次のように書くことができます。

logger.debug("The new entry is {}. It replaces {}.", entry, oldEntry);

引数が三つ以上になる場合、Object[]でラップしなければなりません。たとえば、次のように書くことができます。

Object[] paramArray = {newVal, below, above};
logger.debug("Value {} was inserted between {} and {}.", paramArray);

内部実装を覗いてみよう

ここまでで、logback の中心的なコンポーネントについて紹介してきました。次のステップに進む準備は完璧です。利用者が logback の出力メソッドを呼び出した時に、logback フレームワークの内部でどんなことが起きているのか見ていきましょう。利用者がcom.wombatという名前のロガーについて、info()を呼び出した時の様子を分析してみましょう。

ステップ1. フィルタチェインの決定

TurboFilterが存在するならそれが呼び出されます。Turbo Filter コンテキストにまたがる閾値を設定できるし、いろんなイベントを捨てることができます。捨てるイベントは、Marker 、 Level 、 Logger 、メッセージ、Throwableといったロギング要求に関係する情報から判断します。フィルタチェインの結果が FilterReply.DENY だったら処理中のロギング要求はその時点で破棄します。FilterReply.NEUTRAL だったら次のステップ（ステップ2）に進みます。FilterReply.ACCEPT だったら、次のステップを無視してステップ3にジャンプします。

ステップ2. 基本的な選択ルールの適用

このステップでは、logback はロガーの有効レベルとロギング要求のレベルを比較します。比較した結果ロギング要求が無効の場合は残りの処理は行わず、ロギング要求を破棄します。ロギング要求が破棄されなければ、次のステップに進みます。

ステップ3. LoggingEventオブジェクトの作成

ロギング要求がここまでのフィルタを通過したら、logback はロギング要求に含まれる必要な情報を全て格納したch.qos.logback.classic.LoggingEvent オブジェクトを作成します。中には、ロギング要求を受け付けたロガーインスタンス、ロギング要求のレベル、ロギング要求に指定された例外オブジェクト、現在の時間、現在のスレッド、ロギング要求を起こしたクラスに関するさまざまな情報、MDCなどが含まれます。フィールドによってはレイジーな初期化となるものがあります。つまり、必要になった時点で初期化される、ということです。MDCは、ロギング要求の付加情報となります。MDCについては以降の章で詳しく説明します。

ステップ4. アペンダーの起動

LoggingEventオブジェクトを作ったら、logback は利用可能な全てのアペンダーについて doAppend()メソッドを呼び出します。ロガーコンテキストから受け継いだアペンダーが対象になります。

logback の配布物に含まれているアペンダーは、すべて AppenderBase 抽象クラスを継承しています。doAppend()メソッドは synchronized として宣言されており、スレッドセーフであることが保証されています。AppenderBaseクラスのdoAppend()メソッドでは、アペンダーに割り当てられたフィルターが存在する場合、それを呼び出します。カスタムフィルターは、実行時にアペンダーに割り当てることができるフィルターのことです。別の章で説明しています。

ステップ5. メッセージの書式化

ロギングイベントを書式化するのはアペンダーの責任です。しかし、全てでは無いにしてもいくつかのアペンダーは書式化のタスクをレイアウトに委譲します。レイアウトは、LoggingEventのインスタンスを書式化して、文字列として返します。アペンダーによっては（SocketAppenderなど）、ロギングイベントを文字列に変換するのではなく、シリアライズすることがあります。つまり、アペンダーはレイアウトを持っていることもあるし、持っていないこともあるのです。

ステップ6. LoggingEventの送信

完全に書式化されたロギングイベントは、それぞれのアペンダーの宛先に送信されます。

このUMLのシーケンス図は、ここまでで紹介してきたステップ全体を概観するものです。図をクリックすればより大きなサイズの図を見ることができます。

性能

ロギングについてよく議論の的になる課題の一つとして、必要な計算コストがあります。そこそこの規模のアプリケーションであっても、数千に及ぶログ要求を生成することになるので、性能に関心があるのは当然です。開発中に私たちが一番多くの力と時間を費やしたのは、logback の性能を測定することと、性能を調整することでした。私たちがどれだけの労力を費やしてきたとしてもそれとは関係無く、利用者は次のような性能問題に注意しなければなりません。

問題1. ロギングが完全にオフになっているときの性能

ルートロガーのレベルに最高レベルのLevel.OFFを設定すると、完全にロギングをオフにすることができます。完全にロギングをオフにすると、ロギング要求のコストはメソッド呼び出しと整数比較だけになります。3.2GHz の Pentium D のマシンの場合、通常ならそのコストは 20 マイクロ秒程度になります。

しかし、メソッド呼び出しによっては隠れたパラメータ構築のコストが含まれます。例えば、ロガーxについて次のように実装されていると

x.debug("Entry number: " + i + "is " + entry[i]);

パラメータ構築のコストが含まれることになります。つまり、整数iとentry[i]を文字列に変換するコストと、中間文字列を連結するコストです。これらのコストは、メッセージがログに出力されるかどうかは関係無くかかります。

パラメータ構築のコストは、パラメータの数にもよりますが非常に高くなることがあります。パラメータ構築のコストを回避するため、SLF4Jのパラメータ化されたロギングを利用することができます。

x.debug("Entry number: {} is {}", i, entry[i]);

このやり方の場合パラメータ構築のコストは発生しません。前のdebug()メソッドの呼び出し方に比べると、圧倒的に速くなります。メッセージが書式化されるのは、割り当てられたアペンダーにロギング要求が送信されるときだけだからです。また、メッセージを書式化するコンポーネントには、高度な最適化が行われています。

そうはいっても、非常に範囲の狭いループ中にロギング式があると、呼び出し回数が非常におおくなります。性能が劣化する可能性があるため、何のメリットもありません。たとえロギングがオフになっていても、狭い範囲のループにロギング式が含まれていると、アプリケーションの動作が緩慢になってしまいます。それに、ロギングをオンにすると非常に大量の（そして役に立たない）出力が生じます。

問題2. ロギングをオンにした状態で、ロギングするかどうかを判定する場合の性能

logbackでは、ロガー階層を渡り歩く必要がありません。ロガーは、インスタンスが作成された時点で自分の有効レベル（ロガー自体のレベルと受け継いたレベルを考慮した結果）を知っています。親ロガーのレベルを変更すると、全ての子ロガーは変更通知を受け取ります。したがって、ロガーは祖先ロガーに問い合わせること無く、有効レベルに基いてロギング要求を受け付けるか拒否するかを瞬時に判断することができます。

問題3. 実際にロギングする（書式化と出力デバイスへの書き込み）

これは、ログ出力を書式化し、宛先へ送信するコストです。レイアウト（フォーマッター）の処理を出来る限り高速化するために、同じように過大な労力を費やしました。同じことがアペンダーにも当てはまります。ローカルマシン上のファイルにロギングするとき、実際のロギングのコストは9マイクロ秒から12マイクロ秒程度になりました。リモートサーバ上のデータベースにロギングするとき、これが数ミリ秒に跳ね上がります。

logback は豊富な機能を備えていますが、設計上の第一目標は高速な実行速度であり、第二目標として挙げられていたのは信頼性だけでした。logback のコンポーネントは、性能改善のため何度も書き直されています。