JVMのスタックトレース

グラフ１と同じ条件のシステムに負荷をかけてパフォーマンスを測定し、レスポンスタイムが遅くなり、CPU使用率が100％になる辺りでスレッドダンプを取得してみた。

[Control]+[Break]を押下して取得したスレッドダンプからアプリケーションの実行状態を表す典型的なスタックトレースを図16に示す。

図16

(1)"ExecuteThread: '3' for queue: 'default'" daemon prio=5 tid=0x8b3cc28 nid=0x6f4 
runnable [0x972f000..0x972fdbc]

at c8e.k.n.next(Unknown Source)
at weblogic.jdbc.pool.ResultSet.next(ResultSet.java:180)
at jw.sample.entity.EntityMgr.getMaxRecordNo(EntityMgr.java:123)
at jw.sample.entity.EntityMgr.getRecordList(EntityMgr.java:61)
at jw.sample.AllViewCommand.doAction(AllViewCommand.java:23)
at jw.sample.AbstractCommand.execute(AbstractCommand.java:63)
at jw.sample.HttpHandlerServlet.doGet(HttpHandlerServlet.java:27)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)
at weblogic.servlet.internal.ServletStubImpl.invokeServlet(ServletStubImpl.java:263)
at weblogic.servlet.internal.WebAppServletContext.invokeServlet(WebAppServletContext.java:2390)
at weblogic.servlet.internal.ServletRequestImpl.execute(ServletRequestImpl.java:1959)
at weblogic.kernel.ExecuteThread.execute(ExecuteThread.java:137)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:120)
(2)"ExecuteThread: '0' for queue: 'default'" daemon prio=5 tid=0x8ad37f0 nid=0x700 
waiting on monitor [0x966f000..0x966fdbc]
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:420)
at weblogic.kernel.ExecuteThread.waitForRequest(ExecuteThread.java:94)
at weblogic.kernel.ExecuteThread.run(ExecuteThread.java:118)

図中(1)が実行されているスレッドのある瞬間のスタックトレースである。このスレッドは実際に稼動しているスレッドである。スタックトレースを追ってみると、HttpHandlerServletを呼び出し、実際にロジックが実装されているCommadを経由して、EntityMgrを介して、データベースに問い合わせを行い、検索結果をjava.sql.ResultSetで受けているところであることがわかる。実際には、その先のJDBCドライバーの内部クラスで処理が止まっているようだ。

参考に挙げるが、図中(2)に示されるスレッドは何もタスクがなく、実行待ちの状態になっていることを示している。こういったスレッドが多い場合には並行に実行されるようにチューニングしてやる必要がある。

アプリケーションのチューニング

前項までで、アプリケーションサーバアプリケーションサーバのパラメータチューニングがひとまず終わった。このシステムでは実行スレッド数、コネクションプール数がそれぞれ10の状態で同時アクセスクライアント数が10を超えると、アプリケーションサーバのCPUネックになるということがわかった。更なるチューニングを行うために、アプリケーション自体のロジック的なネックの究明と解析に入ろう。

JProveによるプロファイルの取得方法

ここでは、WebLogic Server上のアプリケーションのJProveによる簡単なプロファイリング方法を紹介する。JProveにはここに紹介する以外のたくさんの機能があるが、それらについては、マニュアルなどを参照いただきたい。

1. JProve上でWebLogic Serverを動かすためのパラメータ設定

プロファイルを行う対象アプリケーションの設定は、JProve Launch Padで行う。サーバサイドデバッグ用の設定画面がある（図17）ので、ここでWebLogic Server6.1を選択する。JProveの基本的な機能を使ってプロファイルを行うための設定としては、この設定画面で、WebLogic Serverを起動するときのJVMの引数と、アプリケーションが使うサーバ側クラスパスを設定するだけである。

JProveでは大きく分けて2つのプロファイル情報が得られる。パフォーマンス情報とヒープ情報だ。システム過負荷時に、ボトルネックになっているロジックを探し出すには、パフォーマンス情報を取得するとよい。

図17

2. スナップショットの取得

Launch Padで各種設定を行ったら、実行ボタンをクリックしてみる。JProve上でWebLogic Serverが立ち上がり、サーバ起動時のメモリヒープのサマリーグラフが現れれば正常に起動している。

JProve側ではパフォーマンス記録を開始し、ブラウザなどからプロファイル対象のアプリケーションを稼動する。任意のポイントでシステムのスナップショットを取ることが出来る。このスナップショットから、アプリケーション実行時のシステムの状態を解析するのである。

取得したスナップショットを選択したら、[メニュー]→[ツール]から「コールグラフ」を選択してみよう。システムの各スレッドが実行したメソッド、更にそのメソッドから呼び出されたメソッド･･･といった様に、メソッド同志の呼び出し関係が表されたグラフが表示される（図18）。グラフ中で色赤くなっているメソッドが測定中に負荷の高かったメソッドである。「負荷の高い」という基準は、設定により、呼び出し回数やオブジェクト数や実行時間などさまざまに変化させることが出来る。

グラフ中で赤くなっているメソッドの一つをさらにダブルクリックしてみると、図19のような画面が現れる。この画面は選択されたメソッドの先で呼ばれた処理についての統計だ。選択されたメソッドからさらに呼ばれたメソッドにおけるCPU使用時間や呼び出し回数の情報が得られるのである。実際にソースを追いかけて、メソッドのコールツリーをたどっていく必要はないのだ。必要であれば、統計情報の画面から、実際のソースコードへとクリック一つで飛べる機能も持っている。

図18

図19

3. データの解析

では、スナップショットの簡単な取得方法がわかったところで、掲示板アプリケーションの過負荷時のスナップショットを実際に取得して解析してみることにしよう。

負荷をかけてしばらくパフォーマンス記録を取得し、2～3分たったところでスナップショットを取得する。取得したスナップショットのコールグラフを開くと、最も処理に時間のかかったメソッドが赤で表示されるので、アプリケーション中のボトルネックが一目瞭然である（あるいは、画面下のメソッドリストで、実行時間ソートし、そちらで重い処理を見つける）。

さらに、チェックしたいクラスをダブルクリックすると、そのクラスから呼ばれたメソッドの実行時間や呼び出された回数の統計が取得できる。実際にやってみると非常に簡単で、かつ目的の情報に最短でたどり着ける事がわかるだろう。

スナップショットの解析

EachGetViewCommand実行時のスナップショットからパフォーマンスデータのコールグラフを表示してみる。このコマンドは、30件のデータを取得するために30回のSQL問い合わせを行い、その都度コネクションプールからコネクションを取得する処理を行うという処理が実装されている。

コールグラフでEachGetViewCommandのタブをダブルクリックして表れた統計を見てみると、コネクションを実際にコネクションプールから取得するjava.sql.Driver..connect()にほとんどの実行時間(72％)がとられていることがわかった。コネクションプール機能を使用していたとしても、相対的に見れば重たいコネクションの取得処理を、データベースを参照するたびに行っているためである。

さらに、データの取得も1件ずつ複数回行われるため、EntityMgrからのgetメソッドが冗長に呼ばれている（26％）。それらが重なって、大きなパフォーマンスロスを生じ、結果として、トータルの実行時間が極端に大きくなっている。

同様にOnceGetViewCommand実行時のパフォーマンス情報を取得してみた。このコマンドは、データの取得方法はEachGetViewCommandと同様に、合計30回のSQL問い合わせを行うのであるが、コネクションの取得が最適化されていて、一度取得したコネクションを一連の処理の間持ち回り使いまわすのである。そのため、java.sql.Driver.connect() メソッドにかかる処理時間は軽減されている。しかし、冗長なデータベースへの問い合わせ処理により、そのメソッドの実行回数が非常に多くなり、全体の処理時間が増加し、パフォーマンスに悪影響を与えていることがわかった。

OnceGetViewCommandでのCPU時間の9割以上が、実際のメインの処理であるデータベースレコードを取得するメソッドに使われていた。しかしデータベースからデータを取得するロジックがよくないために、スループットはそれほどあがらないのである。

そこで、データの取得方法を最適化したものが、AllViewCommandである。このコマンドでは、1回のSQL問い合わせで全てのデータを一度に取得する。コネクションプールからのコネクションの取得方法はOnceGetViewCommandと同様である。

このコマンドに負荷をかけた際の、スナップショットからコールグラフを見てみると、AllViewCommand使用時の大半のCPU使用時間は、新規に実装されたデータベースから複数のレコードを取得するメソッドに費やされているのであるが、呼び出し回数は当然他の２つのコマンドと比較して少なくなっている。それに伴い、全体の処理スピードがあがり、スループットが上がっているのである。

ここで例に挙げた、アプリケーションのロジックのチューニング内容自体に、大きな意味はない。なぜなら、これらのアプリケーションのロジックによる性能の劣化は、顕著な例を示すために故意に組み込んだものであり、実際にこのような単純なパターンはなかなかないものだ。

JProveのようなプロファイルツールを使うことによる大きなメリットは、アプリケーションのソースを追うことなく、時間のかかる処理、メモリリークなどを比較的簡単に発見できるという点である。さらには、全く仕様を知らないようなシステム、あるいは自分が全く開発に携わっていないようなシステムであっても、チューニングが容易だということだ。システムリリース直前に、アプリケーションのどこかにロジック的なミスがありそうな兆候を見つけたときに、巨大化したアプリケーションの中から、1点のロジックミスを見つける作業がいかに大変な作業であるかを、身をもって知っている読者も多いことだろう。

システムのパフォーマンスはボトルネックとなっている部分に大きく左右される。パフォーマンスを低下させるアプリケーションロジックは、その原因をつきとめられれば8割は解決したようなものである。Javaのプロファイリングツールは、その原因究明の大きな手助けになりうる場合が多いのだ。

パフォーマンスとのトレードオフ

パフォーマンスを挙げるために、システムの、あるファクタの性能や機能との間にトレードオフが起こるというのはよくあることだ。トレードオフの起こる対象はさまざまである。あるときは、汎用性であったり、あるときは移植性であったり、コードの美しさであったりする。

今回のサンプルアプリケーションでも、作成中にパフォーマンスと移植性とのトレードオフが生じた。サンプルアプリケーションは当初、データベースからコネクションを取得する際にDataSourceを使い、JNDIツリーから、使用するデータベースプールをルックアップして探し出す作りにしていた。しかし、実際に負荷をかけてみると、性能が全く出なかった。そこでJProveでスナップショットを取ってみると、多くのCPU時間が、JNDIツリーのルックアップ処理にかかっている事がわかった。

データベースコネクションプールをJNDIツリーに登録し、アプリケーション側では、それをLookupするという作りにするメリットは、JNDIを介することによって、アプリケーションを環境に依存しない作りに出来ることにある。つまり、コネクションプールのURIや使用するJDBC Driverをカプセル化し、それを使うアプリケーション側では意識することなく、コーディングが出来るようになるというメリットが得られるのである。

しかし、今回の様にデータベースを一度参照更新するだけのアプリケーションでは、そのコストが全体の処理の中に占める割合が大きかったため、DataSourceを使うことによる移植性等のメリットを捨て、パフォーマンスを上げるということを選択した。

このように、移植性や汎用性など、何らかのファクタとトレードオフにシステムのボトルネックとなっている部分をチューニングすることにより、パフォーマンスを優先するというのも一つの選択肢なのである。このような場面は意外と多い。筆者の経験では、あるEJBの処理が余りに重いため、その処理のみコEJBのもつコンポーネント性を犠牲にして、ストアドプロシジャーを使ったというシステムがあった。

問題が起きたときや、システムの要件が変わったときに適切に対応が出来るように、常に現在システムが出せるパフォーマンスの値や、アプリケーションのどこにネックがあるかをきちんと把握していることが大事なのである。そうすることによって、必要なときに適切な対策が取れるのだ。

最後に

実践編で、非常に小規模ではあるが実際にシステムのチューニングをしてみて、「チューニングはどのように行われていくの？」というところの全体像がなんとなくつかめただろうか？どれも一つ一つを取ってみると、それほど敷居の高いことではなく、どれも実践できそうなものであったことだろう。

チューニングで大切なことは

・測定→究明→対策のスパイラルな繰り返し

・正しい測定をすること

・システム全体の性能特性を把握する

であると筆者は考える。
正しいチューニングを行えば、システムは確実に早くなるはずだ。