【実録ドキュメント】そのログ本当に必要ですか？：現場から学ぶWebアプリ開発のトラブルハック（3）（2/2 ページ）

» 2007年05月24日 00時00分公開

続いて、ソースを洗う

　続いて、アプリケーションのソースを確認する。すべてのソースコードに目を通す時間はないので、適当に2、3のクラスをピックアップして確認したところ、ログを出力するコードがリスト2のようにif文で囲まれていなかった。

リスト2　ログ出力部分のソース（抜粋）

    // start generating log message

                    log = log + SessionUtil.getAllSessionString(session);

                

                 for(int i = 0; i < parameter.length; i++ ){

        log = log + “parameter [” + i ”] ”+ parameter[i];

    }



（中略）



    // end generating log message

    logger.debug(log);

■if文で不必要なログ出力を避ける

　これでは、ログレベルを変更したとき、出力する必要のないログメッセージ生成処理が行われてしまう。ログレベルを変更してもパフォーマンスの低下を招いてしまう。

　通常、パフォーマンスを考慮しリスト3のように、書き込み処理をif文で囲むことを推奨する。

リスト3　推奨されるログ出力方法

    if (logger.isDebugEnabled){

                        // start generating log message

                        log = log + SessionUtil.getAllSessionString(session);

                

                     for(int i = 0; i < parameter.length; i++ ){

            log = log + “parameter [” + i ”] ”+ parameter[i];

        }



（中略）



        // end generating log message

        logger.debug(log);

    }

■推理【3】ログレベルはdebugのみ？

　さらに気になった点が、“logger.debug(log)”の記述しかなく、どうもログレベルがdebugレベルしかないと考えられた。

再度、開発者に事情聴取

　パフォーマンスを劣化させている原因をいくつか発見したので、開発者へ再度ヒアリングを行う。問題を引き起こしている部分をまとめると、以下である。

ログ出力がパフォーマンスを大幅に低下させている
出力されるログ量が多過ぎる
ログが1つのファイルに出力される
ログ出力処理が無条件に行われる
ログレベルがdebugしかない（仮定）

　現段階で仮定である“ログレベルがdebugしかない”点を開発者に確認したところ、やはりdebugしかないとのこと。

そして、解決へ……

　これだけの原因があれば、付け焼き刃での対策ではパフォーマンスを改善できないと考え、以下の対策を施してもらうことにして、いったん引き揚げることにした。

ログの必要／不必要の再検討
ログレベルの再設計
ログ出力先ファイルの分割
ログ出力処理を「if(logger.isXXEnabled)」で囲む

　結局、そのプロジェクトは提示した対策をすべて実施しログ設計まで手戻りを発生させることでトラブルを解決した。

ログ出力でトラブルを起こさないためのTips

　今回はこのように、ログ出力にまつわるパフォーマンス・トラブルをハックした事例を紹介してきた。

　読者の皆さんは、「たかがログでパフォーマンスがそこまで劣化するのか？」と思われるかもしれないが、筆者の経験上ログ出力方法が原因でパフォーマンス・トラブルが発生するシステムは数多く存在する。

　そこで最後に、ログに関するパフォーマンスTipsを紹介する。

■Tips【1】ログ自体が必要かよく考慮する

　いま考えているログは何に取得するか、という目的を意識すると、ログ自体が必要かどうか判別しやすくなる。

　ログ設計指針が重要視され過ぎで、セキュリティ対策の一環や迅速なトラブル対応のために、ありとあらゆるログを取得するといったプロジェクトをまれに目にする。しかしそうなると、逆にログが膨大な量になり、解析に時間がかかるうえ、運用が開始されると結局、重要なログメッセージのみを監視するということになりがちである。

　ログ自体を出力しなければ、ログ出力がパフォーマンストラブルを引き起こすこともないだろう。

■Tips【2】ログレベル、ログ出力方式をキチンと設計する

　本当に必要なログが決まったら、出力するログの目的に応じたログレベルやログ出力方式を決定する。

　Java EE開発で多く用いられるCommon Logging＋Log4Jでは、軽微な情報出力から並べて、trace／debug／info／warn／error／fatalの6つのログレベルが存在する。ログレベルと出力内容は開発者が決定するものであるが、表1に各レベルに対応したログ出力例を示す。

**表1 Log4Jログレベルと使用例**
	ログレベル	使用例
	trace	ループ内部の変数などdebugの中でも大量に出力されるメッセージ。あまり使用しているプロジェクトはない
	debug	セッション内部の情報やユーザーHTTPリクエスト、レスポンス情報など、開発中やテスト用のデバッグメッセージ
	info	アプリケーションの起動情報やログインしたユーザーIDなど毎回出力させたいメッセージ
	warn	2重ログイン禁止のシステムで2重ログイン要求が発生したなど想定内の問題が発生したが、リクエストを処理し運用に問題ないメッセージ
	error	DBサーバが無応答など、ユーザーからの処理を処理できない場合
	fatal	アプリケーションがこれ以上動作できない場合など。あまり使用しているプロジェクトはない

　また、ログ出力方式も性能に大きな影響を与える。ログファイルをパッケージごとやログレベルごとに分散することで、ログファイルのロック開放待ちを抑制できる。

　ログの使用目的を熟慮したうえで、ログ出力が必要なときはネットワーク経由での非同期ログ出力を検討する。

注意！

Log4Jで非同期でのログ出力をサポートするAsyncAppenderクラスは使用方法が特殊なだけでなく、パフォーマンスを低下させる可能性もあるため、採用する前にはテストを行うことを推奨する。
org.apache.log4j.AsyncAppenderクラス

■Tips【3】ログ出力を実装するときは「if(Logger.isXXEnabled()){}」で囲む

　ログレベル、ログ出力方式が決定したら、最後は実装時に行うTipsを解説する。

　ログレベルをキチンと設計すると、ログ出力のための文字列連結などが不必要になるケースが多く出てくる。パフォーマンスを向上させるために、最大の効果が得られることは無駄な処理をしないことである。そのため、リスト3のようにログ出力の処理を削除するためにif文で囲む。

リスト3（再掲）　推奨されるログ出力方法

    if (logger.isDebugEnabled){

                        // start generating log message

                        log = log + SessionUtil.getAllSessionString(session);

                

                                     for(int i = 0; i < parameter.length; i++ ){

                            log = log + “parameter [” + i ”] ”+ parameter[i];

                        }

                

                （中略）

                

                        // end generating log message

                        logger.debug(log);

                    }