はじめに
Web/Applicationサーバーで、ミドルウェアのログからパフォーマンス調査する方法をまとめてみました。
前提
パフォーマンス調査を行う対象のシステムは、Webサーバー(Apache)、APサーバー(Tomcat)、DBサーバー(Oracle)で構成される、シンプルなWebシステムを想定しています。
Webサーバー(Apache)のパフォーマンス調査
Apacheのパフォーマンス調査をする際に確認するのは、以下の2つです。
- アクセスログ
- エラーログ
Apacheのアクセスログ
アクセスログを確認する前に、ログフォーマットについておさらい。
デフォルトのログフォーマットだと、以下のサイトにあるような情報しか出力されないため、パフォーマンス調査には少し情報量が足りません。
Apacheのログフォーマットには、上のサイトに記載されているような設定項目がありますが、パフォーマンスや障害調査用にアクセスログを利用するのであれば、最低でも以下の情報は出力しておいた方がよいと思います。
(特に、HTTPステータス(%>s)や処理にかかった時間(%T)はパフォーマンス調査には必須。)
| 設定値 | ログに出力される情報 |
|---|---|
| %h | アクセス元のホスト名 |
| %t | リクエストを受け付けた時刻 |
| %>s | 最後のレスポンスのステータス |
| %X | 接続ステータス |
| %T | 処理にかかった時間(秒単位)≒サーバー処理時間 |
| %B | 送信されたバイト数(ヘッダーは含まず) |
| %r | リクエストの最初の行の値 |
| %{Referer}i | アクセス元のURL |
| %{User-Agent}i | アクセス元のOSやブラウザの種類 |
なお、上記ログフォーマットにした場合、アクセスログには、Apacheがリクエストを受け付けた時刻順ではなく、リクエストを受け付けた後、処理が終わったタイミングでログに出力されるため、同時アクセスの状況などを見る際には、ログの出力順に注意が必要です。
アクセスログの解析方法
個人的に、皆さんがどのような方法でアクセスログの解析を行っているのか、興味がある所ですが、以下のような方法があると思います。
- Splunkなどの有償ログ解析基盤を利用
- Log Parser Studioでクエリ実行
- AWS Athenaでクエリ実行
- シェルでawk、grepなどを駆使して頑張る
Apacheのアクセスログで確認する事
今回前提としている構成では、Apacheでは静的コンテンツのやり取り、アプリケーションサーバー(Tomcat)へのリクエストの引き渡しがメインである想定であるため、Apacheのアクセスログでは、パフォーマンス状況がどのような状態なのかの把握と、問題がありそうな機能(リクエスト先のURL(%r)で判断)が何なのかについてアタリをつける事を目的にします。
まず大前提として、以下の記事に記載したように、パフォーマンス問題の発生状況をヒアリングしたうえでログを確認していきます。
パフォーマンス問題が発生し始めたのはいつ頃からか。
パフォーマンス問題が発生し始めた前後に、アプリ・システム運用におけるイベントや変更は無かったか(OS、ミドルウェア、アプリケーションのバージョンアップ・パッチ適用、アンチウィルスソフトの設定の変更、大規模な組織変更(Group会社追加、従業員増加・・)、バッチ処理など)。
何の機能(操作)が遅いのか、また、どの位レスポンスタイムなのか。
※合わせて、元々はどの位のレスポンスタイムだったかを確認。
動作が遅い日、時間帯はいつか。特定の日・時間帯なのか、常に又は不定期なのか(月末、月初が遅い、出社、退社時間付近が遅いなど)。
特定のユーザーが遅いのか、全てのユーザーが遅いのか、特定の拠点からのアクセスが遅いのか。
パフォーマンス問題の発生状況により、より細かく確認する項目は変動しますが、まず確認するのは、問題が発生している時間帯で、サーバー処理時間が閾値(3秒以上など)を超えているような、遅い処理(リクエスト)は何かです。
遅い処理は複数ある場合もありますが、その処理について、更に以下のような観点で状況を確認していきます。
- HTTPステータスが503など、サーバーエラーが発生していないか
- 遅い処理は連続して続いているか
- 遅い処理は常に遅いのか、特定の時間帯のみ遅いのか
- 遅い処理のリクエスト元のIPアドレスに偏りがあるか
- パフォーマンス問題発生前後で、同時リクエスト数に変動はないか
- データ転送量が大きくないか
単発で処理が遅いものがある場合は、その処理について何が問題なのか、詳細を調査していきますが、処理が遅い時間が連続して続いているような場合は、遅くなり始めた時間の前後を見て、きっかけとなった処理が何かを見ていきます。
単純に、アクセス集中により処理が捌けなくなっている場合もあり、遅い処理の特定は難しい面がありますが、OSのパフォーマンスログの確認(特に、CPU使用率とランキュー待ち)や、後述するアプリケーションサーバーのログの確認とを並行して行い、状況を確認していきます。
何の処理が遅いかが特定できた場合は、データベース(この例ではOracle)の処理が遅くないかをStatspackレポートなどから確認し、アプリケーションのロジックそのものに問題があるのか、SQLの記述やデータベースサーバー側に問題があるのかの切り分けを行います。
Apacheのエラーログ
エラーログでは、Apacheのエラー情報、ApacheとTomcatとの間での通信エラーが無いか、ざっと確認しつつ、以下のようなメッセージが出ていないかを確認します。
このメッセージはLinux環境の場合ですが、このメッセージが出ている場合、httpd.confで設定しているApacheの最大スレッド数以上のリクエストがあった事で、クライアントからのリクエストに待ちが発生している事を示しています。
※このメッセージは、Apache起動後、最初に最大スレッド数を超えたタイミングで1回のみ出力されるため、過去を遡って確認しないと気づけない場合があるため、注意が必要です。
[Tue Dec 16 16:53:09 20XX] [error] server reached MaxClients setting, consider raising the MaxClients setting
このメッセージが出ている場合は、必要に応じて、httpd.confの設定を見直し、Apacheの最大スレッド数を上げる必要があります(もしくは、Web/APサーバーの台数を増やす)。
Applicationサーバー(Tomcat)のパフォーマンス調査
アプリケーションサーバーでは、以下を確認していきます。
標準出力ログ(catalina.out、stdout)の確認
OutOfMemoryError、StackOverFlowErrorが発生していないかを、grepするなどして確認します。
OutOfMemoryErrorが発生している場合、以下のような問題の可能性があります。
- HeapサイズまたはMetaspaceのサイズが小さすぎて、純粋にメモリ割り当てが足りていない
- 特定の処理でメモリリークが発生している
- 特定の処理で大量のオブジェクトを生成している
- 大量のスレッドが生成され、ネイティブメモリが不足した
など
単純にHeapサイズやMetaspaceのサイズが小さすぎるのであれば、物理メモリに余裕があれば、不足した領域のサイズを増やす事で改善する可能性もありますが、基本的にはアプリケーションのメモリ使用状況の見直し(プログラムの改善)が必要になります。
この調査の為には、以下のような点を確認する必要があります。
- OutOfMemoryError発生時のヒープダンプを解析し、メモリを多く使っているオブジェクト、クラスが何かを確認
- スレッドダンプ(デッドロックしていないか)を確認
- GCログなどを確認し、HeapメモリやMetaspaceのメモリ使用量の推移を確認
※ヒープダンプは、JVMオプションに-XX:HeapDumpOnOutOfMemoryErrorをつけておくことで、OutOfMemoryError発生時のヒープダンプが出力される。
※ヒープダンプ、クラス・ヒストグラム、スレッドダンプなどを手動で出力する場合は、jcmdなどで出力。
StackOverFlowErrorは、アプリケーションでの再帰の回数が多すぎてスタックオーバーフローが起こる場合に発生するので、こちらについても、アプリケーションのプログラム修正が必要になります。
OutOfMemoryError発生時の調査方法については、少し古いですが、以下の記事に詳しく記載されています。
GCログの確認
GCログでは、Full GCなどにより、全てのアプリケーションスレッドが停止している(いわゆるStop the World状態。以下、STWと表記)時間の状況を確認します。
STW状態が連続して続いていたり、1回のSTW状態の時間が5秒以上かかっているような場合は、処理待ちが多発し、全体のパフォーマンスが低下している可能性があるため注意が必要です。
ただ、使用しているガベージコレクション(GC)の種類によって、STWしているタイミングが異なるため、GCの種類毎にログで確認(grep)するキーワードおよび確認点をまとめます。
※初期のJavaで実装されていたGCについては省略しています。
| GCの種類 | 世代別 | ログで確認するキーワード(STWになるタイミング) | 確認点 |
|---|---|---|---|
| Parallel GC | Yes | Full GC | Full GCが発生した領域(HeapかMetaspaceか)とFull GCにかかった時間。 |
| Concurrent Mark Sweep GC(CMS) | Yes | initial-mark remark Full concurrent mode failure |
各モードにかかった時間。Fullの場合は、発生した領域。 |
| G1GC | Yes | initial-mark remark cleanup Full concurrent mode failure |
各モードにかかった時間。Fullの場合は、発生した領域。 |
| Shenandoah GC | No | Init Mark Final Mark Init Update Refs Final Update Refs |
各モードにかかった時間。 |
| ZGC | No | Mark Start Mark End Relocate Start |
各モードにかかった時間。 |
GCの種類ごとの特徴や、利用可能なJDKのバージョンなどの情報については、以下のサイトが参考になると思います。
また、GCの種類毎のログの確認方法については、以下を参考にしました。
アプリケーションログ
アプリケーション側で、パフォーマンス情報を出力しているログがある場合は、そのログの内容を確認します。
おわりに
Web/Applicationサーバーで、ミドルウェアのログからパフォーマンス調査する方法をまとめてみました。
アプリケーション起因でパフォーマンスに問題がある場合、ヒープダンプやスレッドダンプなどをアプリケーション開発者に解析してもらったり、アプリケーションのロジックを確認してもらう必要がある場合が多いですが、インフラエンジニアとして、どのような観点で調査を進めていくのがよいか、参考になれば幸いです。