はじめに

現在のWebシステム開発・運用で踏まえるべき新しい技術的な取り組みについて、日立Cosminexusの製品群を題材として取り上げながら解説する本連載の前回は、トラブルシューティングの後編として解説しました。

第5回の今回は、トラブルシューティング実践編①として、ユーザからの問い合わせが多かったり、調査が長期化しがちな事例をベースに、システムスローダウンとデータベース（DB）周りのトラブルシューティングの流れを説明します。

事例1：排他ロック多発によるシステムスローダウン

システムスローダウンとは、サービスのレスポンスが突然遅くなる状態です。原因はクライアント／ネットワーク／サーバのどこかがボトルネックになっているためですが、ボトルネックの個所の特定が難しいため調査が長期化しやすいトラブルです。

解決のためには、各種ログやPRFトレース[1]などのトレースで調査します。

トラブルが発生した システムの概要

ユーザ独自のフレームワークを搭載したWebアプリケーションにおいて、スローダウンが発生しました。

このフレームワークは、独自のDBコネクションプールを持っています。フレームワークはコネクションをプーリングで一元管理し、複数のリクエスト（スレッド）からコネクション取得の要求がくると、操作が重複（矛盾）しないように排他ロックを掛け、コネクションプールからコネクション（ID）をアプリケーションに返します。このとき、ロックを解除します。

アプリケーションはこのIDを使いSQLを発行します（図1⁠）⁠。

原因究明のための調査手順

このシステムにおいて複数ユーザがアクセスすると、急に応答が遅くなりました。アプリケーション開発チームが調査を実施しましたが、詳細な資料がないため行き詰まってしまいました。

そこでCosminexusのPRFトレース機能を使用して処理時間の事実を確認しました。これでリクエストの応答時間をプロットしたものが図2です。グラフを見ると、15:15から15:31の間で応答時間が延びており、最大では200秒ほど要していることがわかります。

さらに、PRFトレースを使ってリクエストの同時実行処理数をプロットしました（図3⁠）⁠。このグラフから、サーバ内に抱えているクライアントからのリクエスト数を把握できます。15:14以降の同時実行数が急増し、15:20に33まで増えています。これは処理速度の低下で、リクエストが滞留しているためです。

さらに調査を進め、性能処理時間の長い順に並べ替えるなどして、各処理ポイントで取得したPRFトレースの情報をシーケンスに表したのが、図4です。シーケンス図より、アプリケーション側での処理に時間がかかっていることがわかったので、今回はアプリケーション内部にボトルネックがあると推測し、スレッドダンプを取得しました。

トラブルの解決

スレッドダンプを見ると、スレッドごとのスタックトレースを把握できます。その結果、ボトルネックとなるロックを特定でき、プーリング機能が正常に動作していないことが判明しました。

この事例では、プール設定値の最小値と最大値が異なっているとDBコネクションの接続／切断を頻繁に繰り返し、これがスローダウンの原因と特定できたため、最小値と最大値を同一値に設定して解決しました。

事例2：DBアクセス回数の多さによる応答遅延

ある新規導入のシステムにおいて、リリース直後から特定のアクセスに限って応答が遅くなる現象が発生していました。DBサーバ側を調査してもSQL発行1回あたりの応答時間は正常で、問題個所は発見できません（図5⁠）⁠。

原因の特定から解決まで

そこで、CosminexusのPRFトレース機能を使用し、1つのHTTPリクエストが発行するSQLの回数を調査しました（図6⁠）⁠。すると、100回近く繰り返して発行しており、リクエスト全体では数秒に達しています。これが応答遅延の原因と判明しました。

この事例では個々のSQL処理時間は数十ミリ秒以内であり、DBサーバ側で調査しても異常は発見できません。PRFトレースの解析結果から原因を数時間で特定でき、ユーザにアプリケーションの実装を見直してもらうことで無事解決に至りました。

次回予告

次回はトラブルシューティングの実践編②として、メモリ周りのトラブルに関して実際の事例に基づき解決方法を解説します。