【実録ドキュメント】そのログ本当に必要ですか？：現場から学ぶWebアプリ開発のトラブルハック（3）（1/2 ページ）
本連載は、現場でのエンジニアの経験から得られた、APサーバをベースとしたWebアプリ開発における注意点やノウハウについて解説するハック集である。現在起きているトラブルの解決や、今後の開発の参考として大いに活用していただきたい。（編集部）
今回の概要
数人で利用しているときは、レスポンスが軽快だったシステムで、ユーザー数が増えてくると急激にレスポンスタイムが悪化する現象が発生した。現場から学ぶWebアプリ開発のトラブルハック 第2回で扱ったFull GCなどいくつか原因が考えられるが、本稿ではログ出力にまつわるトラブルをドキュメンタリー形式で紹介し、まとめとしてログ出力のパフォーマンスに関するTipsを紹介する。
今日もまた、突然電話が鳴り響く
ある穏やかな朝、突然電話が鳴る。相手は結合テストの工程からパフォーマンステストで支援に入る予定のプロジェクトの担当者である。用件は「結合テストを20人のテスターで実施しようとしているが、レスポンスタイムが1分を超えていて、テストがままならない。早急になんとかしてほしい」
これだけの情報では、トラブルをハックすることはできないので、Webアプリの問題点を「見える化」する7つ道具をノートパソコンにインストールして、現場へ急行する。
まずは、現場で事情聴取
現場に到着したので、まずは担当者にヒアリングを行った。ヒアリングした結果をまとめると、以下の現象が発生しているようである。
- 単体テストの最終段階で画面遷移を行ったときは、3秒程度のレスポンスタイムだった
- 単体テストは、1人の開発者ごとに1台ずつ環境を使用していた
- 結合テストのレスポンスタイムは1分を超える
- 結合テストは20人のテスターが1つの環境を使用している
- 特定の画面遷移が遅いのではなく、全体的にレスポンスタイムが大きい
- 原因はまったくアタリを付けられていない
次に、7つ道具で原因を狭めていく
ヒアリングで現象が大まかに把握できたので、テスト環境を使い調査を開始する。まずは、トラブル切り分けフローに従い、基本データ分析を行う。
システムを20人が同時に使用することでトラブル現象は再現するが、再試験や再現性を考慮し負荷生成ツールを利用して、システムに負荷を掛けながら、ハードウェアリソースのモニタリングを行った。
ハードウェアリソースの使用状況を分析した結果、CPU、メモリ、ハードディスク、ネットワーク、いずれのハードウェアリソースもボトルネックと呼べるほど、使用されていなかった。並行して取得していたGC（Garbage Collection）発生状況を確認するも、問題となっていなかった。
■推理【1】アプリケーションの実行スレッドが待ち状態？
この段階で考えられるのは、アプリケーションの実行スレッドが待ち状態になっているケースである。どのスレッドが待ち状態になっているか確認するために、ThreadDump解析を行う。ThreadDumpを取得し、Samuraiで「見える化」を行った解析の結果、図1のように赤色で示されるブロック状態のスレッドが多数存在していた。
図1 ThreadDump解析結果（注意：事例を基に同様の現象を発生させたThreadDumpの解析結果である）ロックされているオブジェクトを特定するため、threadDump.logファイルの解析を行ったところ、org.apache.log4j.Category.callAppendersクラスが同じオブジェクトの開放待ち状態であることが判明した（リスト1）。
| リスト1 threadDump.logから抜粋 |
"http-8080-Processor4" daemon prio=1 tid=0x08453670 nid=0x4325 waiting for monitor entry [0x6bafd000..0x6baff0b0] |
Log4JのFileAppenderクラスでは、複数のスレッドから同じファイルにアクセスを行うときにファイルを破壊しないように、書き込みを行うときにはログファイルオブジェクトをロックする（図2）。
編集部注：Log4Jについて詳しく知りたい読者は、Java開発支援ツールの定番の「Log4J」をご参照ください。
図2 Log4Jファイル書き込みのロックそのため、ファイルオブジェクトをロックしているスレッドからの書き込み処理が完了するまで、ほかのスレッドは処理を完全に停止する。
■推理【2】ログが犯人？
ここまでの調査で、ログ出力がボトルネックとなり20人が同時に接続すると、レスポンスタイムが1分を超える現象が発生していることが判明した。ここまでの調査で判明した現象は以下である。
- 顕著なハードウェアリソースボトルネックは見られない
- GC発生状況は許容範囲内である
- アプリケーションスレッドはすべてLog4Jのappendクラスにて同じオブジェクトのロック開放待ちである
- ボトルネックはログ出力である
以降はトラブルをハックするために、より詳細な調査を行う。
ここで、ログサイズを確認
手始めに最も手軽に確認できるシステムが出力するログを確認する。担当者にログのパスを確認する際に、ログファイルが1つしかないことが判明した。
そのログファイルをlessコマンドで開こうとするが、なかなか表示されない。しばらく待つと、“[DEBUG]”で開始するログが大量に出力されている。
出力されている内容は「ユーザーからのHTTPリクエスト」「ユーザーへのHTTPレスポンス」「ユーザーセッション上の大量のオブジェクト」「コールされるクラス名やメソッド名」など大量の情報が出力されていた。
再現中に出力されたログの量を確認したところ、30分程度で2Gbytes以上のログを出力していた。
■DBサーバよりAPサーバの負担が大きい！
ここで先ほど取得したハードウェアリソースを再度確認したところ、DBサーバよりもAPサーバのディスクビジー率が高いことが判明した。当然であるが、通常はユーザからの処理やデータ加工を担うアプリケーションサーバよりも、データにアクセスする機能を担うデータベースサーバのディスクビジー率の方が高い。
Copyright © ITmedia, Inc. All Rights Reserved.
ITmediaはアイティメディア株式会社の登録商標です。