連載
» 2008年02月04日 00時00分 公開

Linuxトラブルシューティング探偵団(1):高負荷なのに片方のサーバにだけ余裕が……なぜ? (2/4)

[福山義仁,NTT OSSセンタ]

アクセスログの確認

 このシステムでは、mod_jkによる振り分け方法として、リクエスト数に基づいて均等に振り分けるアルゴリズム(method=Request)を設定していました。この結果、2台のアプリケーションサーバには、均等にリクエストが振り分けられるはずです。

 しかし、現実にCPU使用率の偏りが発生しており、前述のとおりThreadBusyのスレッド数も異なることから、単純に「設定と異なり、実際に処理しているリクエスト数が違うのではないか?」と考えました。まずこの考えを確かめるため、本当にmod_jkが均等にリクエストを振り分けているのか、アクセスログを調査して確認することにしました。

■mod_jkログを取得し、調査

 mod_jkのアクセスログを取得するには、以下のような設定を行います。

* mod_jk.conf (httpd.conf)の設定
<IfModule mod_jk.c>
JkLogFile logs/mod_jk.log
JkLogLevel info
JkLogStampFormat "[%a %b %d %H:%M:%S %Y] "
JkRequestLogFormat "%w %V %T %R"
</IfMdule>

 ログの粒度を「info」レベルにすることで、失敗した場合のリトライ状況などが分かります。また、JkRequestLogFormatでは「使用したworker名」「クライアントIPアドレス」「処理時間」および「実際に振り分けたworker名」を出力するように設定しています。実際のログは、以下のように出力されます。

* logs/mod_jk.log
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.030167 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.051412 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.008556 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.057792 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.062163 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.041623 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.015135 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.050942 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.046896 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.051783 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.034083 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.071469 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.025259 worker1
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.075813 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.062054 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.016814 worker2
[Wed Jul 18 15:10:00 2007] workerlb
192.168.40.10 0.008090 worker2

  アクセス数
クライアント
5570787
AP1
2786488
AP2
2784299
表2 集計結果


 このログファイルを集計した結果が表2です。

 mod_jkが均等に振り分けており、AP1とAP2のアクセス数はほぼ均等になっているようです。残念ながら(?)、この面での問題はなさそうです。

 次に、各アプリケーションサーバに対するアクセス数を時間ごとに解析してみました(図2)

図2 各APへの時間ごとのアクセス数 図2 各APへの時間ごとのアクセス数

 これを見ても、mod_jkは均等にリクエストを振り分けています。しかし、各リクエストの処理時間を見ると、高負荷時にはAP1側のリクエスト処理時間が長くなっていることが分かりました。

ガベージコレクションも怪しい

 一方、Tomcatに限らずJavaでのCPU使用率トラブルは、ガベージコレクション絡みのことも多いので、その状況も確認してみます。

 Javaでは、動的に確保したメモリを、不要になった場合に自動的に削除します。この機能を「ガベージコレクション」(GC)といいます。

 ガベージコレクションには、「MinorGC」と「MajorGC」の2タイプがあります。MinorGCは比較的若い世代のオブジェクトのみを対象に消すので、対象となるメモリ量も少なく、処理が早く終わります。その代わり、古い世代のオブジェクトは消えません。一方MajorGCは、古い世代のオブジェクトが多くなってきた場合に処理を行います。全メモリを対象に行われ、使用されていないオブジェクトはすべて削除されます。その代わり時間がかかります。

 基本的に、GCの処理はすべての処理を止めて行われるため、Javaでは、2段階に分けた世代別ガベージコレクションによって、停止時間が短くなるように工夫されています。詳細はJava Solutionの記事「“Stop the World”を防ぐコンカレントGCとは?」を参照してください。

 今回の検証では、jstat(コラム参照)でGCのカウントなどを定期的に収集していました。これをまとめた結果が表3です。

  AP1 AP2
MinorGC COUNT
674
640
AVG MinorGC Time (sec)
0.112530
0.083180
FullGC COUNT
2
2
AVG MajorGC Time (sec)
0.140000
0.092000
表3 jstatによってまとめたGCの状況


 これを見ると、CPU使用率の高いAP1サーバで、MinorGCの回数が少し多い状態になっていることが分かります。ですが、そう頻繁に発生しているということもなく、差自体も少ないため、GCの動作的には問題はなさそうです。


 とはいえ、実際にAP1のCPU使用率を高くしているのは、GCの差によるものが1つの原因だと判断できます。

 一方、MajorGCはどちらも同じ回数発生しています。発生時間を見ても、負荷の高いAP1の方で早い時間にMajorGCが行われていますが、ほぼ同じタイミングでした。MajorGCの時間も短く、CPU使用率は常に偏っている状態ですので、一時的に発生するMajorGCとは関係なさそうです。

 この結果を基に、おそらくアプリケーションサーバに残っているアクティブなスレッド数が違うため、それだけ多くのオブジェクトがヒープメモリに存在し、結果としてGC回数も増えると予想されます。

 以上で、CPU使用率が高くなってしまう理由をだいたいつかむことができました。しかし、なぜスレッド数に違いが出るのかについて、まだ調査が必要です。

■DBのスロークエリログ

 片方のアプリケーションサーバだけクエリの処理が遅くなるというケースも考えにくいことですが、問題の切り分けのため、下記の設定を施して、念のためデータベースのクエリの処理時間を確認しました。

クエリの処理時間取得時のMySQLの設定(my.cnf)
log_slow_queries = /var/log/mysql/slow_queries.log
long_query_time = 1

 ですが結果は予想どおりで、処理に1秒以上かかっているクエリは存在しませんでした。どうやらこの線もハズレのようです。

コラム jstatの使い方

 jstat(http://java.sun.com/j2se/1.5.0/ja/docs/ja/tooldocs/share/jstat.html)はJDKに同梱されているツールで、下記のように動作中のJVMの状態を確認できます。

# jps
28230 Jps
10947 Bootstrap
# jstat -gc 10947 30000 5
S0C S1C S0U S1U EC EU OC OU PC PU
YGC YGCT FGC FGCT GCT
12288.0 12288.0 334.8 0.0 98304.0
21548.1 204800.0 11327.5 21248.0
20423.9 230 0.694 0 0.000 0.694

 GCの確認には、Javaの起動オプションで指定する方法もありますが、jstatの場合は基本的に、状態を確認する対象の起動オプションなどを変更する必要がありません。使い方は以下のとおりです。

jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

 引数の意味は下記の通りとなります。

引数 内容
option
表示する情報のオプション。gc以外にもあります。
lines
情報のヘッダーを表示する間隔(行数)。
-t
タイムスタンプの表示。JVMが起動してからの経過秒数が表示されます。
vmid
対象のJVMのID(jpsで調べられます)。
interval
秒(s)かミリ秒(ms)で表示の間隔を指定します。
count
表示する回数。

Copyright © ITmedia, Inc. All Rights Reserved.

RSSについて

アイティメディアIDについて

メールマガジン登録

@ITのメールマガジンは、 もちろん、すべて無料です。ぜひメールマガジンをご購読ください。