WebSphere+commons-logging+log4jは使い物にならない

Written on Jan 3, 2007. Posted in Java

IBM WebSphere6.1(WAS)とBEA Weblogic9.2(WL)のどちらを採用するかを検証する機会が昨年あった。政治的な理由でWASに大きく傾きかけていたのだが，致命的な問題がWASに存在することが発見された。

それは，commons-loggingとlog4jの組み合わせをWebアプリケーションで使っていた場合に，WLやTomcatの場合と比べて，出力ログパターンによって処理性能が著しく低下するというもの。具体的には，「%C」「%M」といった，保守や不具合の原因の発見に非常に有効な情報となるパターンを使った場合に，性能劣化が激しく生じる。

例えば，Strutsやcommonsシリーズなどのjakarta系のライブラリに対してDEBUGレベルのログ出力を「%C」や「%M」を含めて行おうとした場合，Webアプリケーションの起動だけでも数十分以上かかってしまう。TRACEレベルなど指定してしまったら，きっと時間単位になってしまうだろう。

これは，以下のサーブレットコードとlog4j.xmlファイルの組み合わせを実行することで，簡単に再現可能だ。

// package，import文は省略 @SuppressWarnings(“serial”) public class LoggingServlet extends HttpServlet { private static Log logger1 = LogFactory.getLog(“test1”); private static Log logger2 = LogFactory.getLog(“test2”); @Override protected void doGet(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException { logger1.debug(“* logger1.debug() call. (1)”); logger1.debug(“* logger1.debug() call. (2)”); logger1.debug(“* logger1.debug() call. (3)”); logger1.debug(“* logger1.debug() call. (4)”); logger1.debug(“* logger1.debug() call. (5)”); logger1.debug(“* logger1.debug() call. (6)”); logger1.debug(“* logger1.debug() call. (7)”); logger1.debug(“* logger1.debug() call. (8)”); logger1.debug(“* logger1.debug() call. (9)”); logger1.debug(“* logger1.debug() call. (10)”); logger1.debug(“* logger1.debug() call. (11)”); logger1.debug(“* logger1.debug() call. (12)”); logger1.debug(“* logger1.debug() call. (13)”); logger1.debug(“* logger1.debug() call. (14)”); logger1.debug(“* logger1.debug() call. (15)”); logger1.debug(“* logger1.debug() call. (16)”); logger1.debug(“* logger1.debug() call. (17)”); logger1.debug(“* logger1.debug() call. (18)”); logger1.debug(“* logger1.debug() call. (19)”); logger1.debug(“* logger1.debug() call. (20)”); logger2.debug(“* logger2.debug() call. (1)”); logger2.debug(“* logger2.debug() call. (2)”); logger2.debug(“* logger2.debug() call. (3)”); logger2.debug(“* logger2.debug() call. (4)”); logger2.debug(“* logger2.debug() call. (5)”); logger2.debug(“* logger2.debug() call. (6)”); logger2.debug(“* logger2.debug() call. (7)”); logger2.debug(“* logger2.debug() call. (8)”); logger2.debug(“* logger2.debug() call. (9)”); logger2.debug(“* logger2.debug() call. (10)”); logger2.debug(“* logger2.debug() call. (11)”); logger2.debug(“* logger2.debug() call. (12)”); logger2.debug(“* logger2.debug() call. (13)”); logger2.debug(“* logger2.debug() call. (14)”); logger2.debug(“* logger2.debug() call. (15)”); logger2.debug(“* logger2.debug() call. (16)”); logger2.debug(“* logger2.debug() call. (17)”); logger2.debug(“* logger2.debug() call. (18)”); logger2.debug(“* logger2.debug() call. (19)”); logger2.debug(“* logger2.debug() call. (20)”); response.setContentType(“text/html; charset=Windows-31J”); PrintWriter writer = response.getWriter(); writer.println(“OK”); writer.close(); } }

version=”1.0” encoding=”UTF-8” ?

コンソール出力

「%C」「%M」を含まないパターン（test1カテゴリ）と，それらを含むパターン（test2カテゴリ）で，それぞれ２０回連続でログ出力を行うコードである。まず，これをWLで実行した場合の結果は，以下のようになる。

全体でも121msしか処理時間はかかっていない。特に「%C」などが含まれたとしても，問題はない。この結果は，Tomcat5.5で行った場合もほぼ同じである。

次に，WASでの結果を以下に示す。

全体では501msと，WLの結果と比べて５倍近い性能劣化が見てとれる。特に，後半のtest2カテゴリでのログ出力に性能劣化が認められるのがわかるだろう。

これだけを見ると，単に５倍程度の劣化だが，ログ出力の箇所は通常ものすごい多くなるだろうし，ただでさえレスポンスタイムの顧客からの要求はシビアなのに，５倍という数字はとても話にならないものである。また，マシン自体の負荷が高まってくると，５倍では済まず，３０倍から５０倍程度の性能劣化が生じたこともある。ひどい結果であると言わざるを得ない。

IBMのこれに関するサポートについても，良いとは言えなかった。

• 「%C」「%M」を使わなければ遅くならないのであれば，使わないでください。（ファーストコンタクト）

• そのような報告は今までにありませんし，検証しても再現させることができませんでした。（ログ内容を送った結果その１）

• それはアプリケーションの問題であり，WASには何ら問題はありません。（ログ内容を送った結果その２）

• サポート範囲外です。購入後に受け付けます。（検証アプリにより性能劣化がIBMで認められた結果）

びっくりである（担当者は，消費者であるこちらに歩み寄る姿勢を最後まで見せなかった）。

もしWASでこのような問題が発生した経験を持っている方や，根本的な解決策をお持ちの方は，ぜひコメントを寄せて欲しい。

Tweet

関連記事

2023年のRemap

Remapにファームウェアビルド機能を追加しました

Google I/O 2023でのウェブ関連のトピック

2022年を振り返って

現在のRemapと今後のRemapについて