Javaでなぜ問題が起きるのか 〜システムをきちんと運用するための基礎知識

第6回Java VMの情報を取得する(後編)

前回システム運用者は次の4つのポイントに絞ってJVMの動きを監視することを紹介し、そのうち1.と2.について解説しました。

  1. JVMがアプリケーションを中断することなく実行できているか
  2. JVMがアプリケーションのリソースを奪っていないか
  3. OSのリソースが十分に割り当てられているか
  4. アプリケーションが動いているか

今回は、3.と4.について解説します。

「OSのリソースが十分に割り当てられているか」「アプリケーションが動いているか」は、ともにスレッドを見ることで確認できます。

3.では、たとえばOS上で動くほかのプロセスによってストレージのリソースが大量に使われていると、JVMが十分なリソースを確保できなくなります。十分なリソースを確保できないと、JVMのI/Oの時間が長くなりますが、そのときファイルI/Oに関わるメソッドを処理するスレッドの実行時間が普段よりも長くなることが多いです。普段の実行時間と処理時間が長くなったときのI/O時間を比較することで、リソースが十分に割り当てられているかを確認することができます。

また、4.は、アプリケーションの実装が酷いためスレッドが常に動けない状態になっている可能性を確認することで把握できます。

スレッドの状態を4つに分ける

スレッドを見るにあたり、スレッドの状態を次の4つに分類します。

  • 処理の受付中
  • 処理中
  • 休み中
  • 待機中

「処理の受付中」は、スレッドが何も処理をしていない状況です。スレッドプールでプールされているスレッドがこの状態に該当します。

「処理中」は、スレッドが仕事を受け、CPUを使用して処理を実行している状態です。

「休み中」は、スレッドが明示的に休みを命じられて、何もしていない状態です。

「待機中」は、スレッドが何かしらの方法で処理を止められて、処理を再開するのを待たされている状態です。

OSのリソースが十分に割り当てられていないと、スレッドは待機中となります。

また、アプリケーションが動けていないと、スレッドは休み中もしくは待機中となります。

同じ理由で待機するスレッドが一定量を超えると、待機時間が急激に増加することがあります。しかし、少ないスレッド数で実行すると顕在化しないことがあるため、テストフェーズでは気付かないことが多いです。大量のリクエストが発生する本番環境でのみ発生することがよくあるため、注意が必要です。

スレッドが待機中になる3つの理由

スレッドは、おもに次の3つの理由から待機中になります。

  • I/O待ち
  • ロック待ち中
  • 委譲した処理の完了待ち

I/O待ち

ローカルやリモートのファイルを読み書きする時間や、ネットワーク先のマシンへアクセスを待っている状態です。ネットワーク先のマシンへのアクセスの一部は、後述する委譲した処理の完了待ちも含むことがあります。

これらは、OSのシステムコールを経由して処理されます。ほかのプロセスがリソースを使いすぎると、リソースがなかなか使えなくなってしまうため、待ち時間が長くなります。また、同一アプリケーション内でも別のスレッドがリソースを使いすぎると、同様にリソースがなかなか使えなくなります。

ロック待ち

排他的に実行しないといけない処理の入口でスレッドが待たされている状態です。

スレッドは、アプリケーションで指定したロックオブジェクトごとに待たされます。処理をおこなう際にロックオブジェクトを獲得できない場合、スレッドはロックオブジェクトが開放されるのを待ちます。ロックオブジェクトが開放されると、スレッドはロックオブジェクトを獲得して処理を続け、処理が終わるとロックオブジェクトを開放します。

委譲した処理の完了待ち

同一のJVM内で別スレッドへ処理を委譲したり、⁠RESTfullな)Webサービスやデータベースなど外部へ委譲した処理が返ってくるのを待っている状態です。待ち時間には、外部での実行時間に加え、データを転送する時間が含まれます。

スレッドダンプでスレッドの状態を確認する

スレッドがどの処理中にどのような状態になっているかを確認するためには、スレッドダンプを取得します。スレッドダンプは、ダンプした瞬間に各スレッドがどのメソッドを処理していて、どの状態にいるのかを取得します。

次のようなソースコードを例に、実際にスレッドダンプを取得してみましょう。スレッドプールへ処理を委譲して、処理の結果を出力するものです。処理は1分間休んだ後にHelloを返します。このソースコードは実働には耐えられませんが、スレッドダンプの結果をわかりやすくするために、このようにしています。

public class ThreadStatusSample {

    public static void main(String[] args) throws Exception {

        ExecutorService executor = Executors.newFixedThreadPool(1);
        Future<String> future = executor.submit(() -> {
                TimeUnit.MINUTES.sleep(1);
                return "Hello";
        });

        System.out.println(future.get());
        executor.shutdown();
    }
}

mainメソッドは、mainスレッドが実行します。newFixedThreadPoolメソッドは、スレッド数が1のスレッドプールを作成します。

mainスレッドは、submitメソッドでスレッドプールへ処理を委譲し、getメソッドで委譲した処理が終わるのを待機します。

次の図は、各スレッドの状態の変化を時間ごとに表したものです。

図1 各スレッドの状態の変化とスレッドダンプ
図1 各スレッドの状態の変化とスレッドダンプ

スレッドダンプを取得する方法はさまざまありますが、今回はjcmdを使用して取得します。jcmdに対象となるJavaプロセスのプロセスIDを指定し、Thread.printコマンドを指定することで、スレッドダンプを取得します。

スレッドダンプの例
> jcmd <プロセスID> Thread.print
"main" #1 prio=5 os_prio=0 tid=0x000000000271d800 nid=0x2ce4 waiting on condition [0x0000000002b5e000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x000000076b2f19b8> (a java.util.concurrent.FutureTask)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
        at java.util.concurrent.FutureTask.get(FutureTask.java:191)
        at thread.ThreadStatusSample.main(ThreadStatusSample.java:28)

"pool-1-thread-1" #11 prio=5 os_prio=0 tid=0x000000001db47800 nid=0xa18 waiting on condition [0x000000001e37f000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at java.lang.Thread.sleep(Thread.java:340)
        at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
        at thread.ThreadStatusSample.lambda$main$0(ThreadStatusSample.java:14)
        at thread.ThreadStatusSample$$Lambda$1/990368553.call(Unknown Source)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)
(略)

このスレッドダンプからは、mainとpool-1-thread-1の2つのスレッドがあり、それぞれ次の状態であることがわかります。

  • mainスレッドは、WAITING (parking)、すなわち待機中である。具体的には、Futureインターフェースの実体であるFutureTaskクラスのgetメソッド内でスレッドプールに委譲している処理が終わるのを、sun.misc.Unsafeクラスのparkメソッドで待機中である
  • pool-1-thread-1スレッドは、TIMED_WAITING (sleeping)、すなわち休み中である。具体的には、TimeUnitクラスのsleepメソッド内でThreadクラスのsleepメソッドを呼び出して、休み中である

スレッドダンプでは、処理の受付中、処理中、休み中、待機中の一部の情報を取得できます。スレッドダンプで得られる情報は取得した瞬間の情報なので、分析をするためには一定期間のうちに何度か取得して、推移を確認するのが一般的です。

ただし、情報の推移だけでは判断を誤ることがあるため注意が必要です。次の図は、先ほどスレッドプールへ委譲した処理を2回連続で実行した例です。スレッドダンプを4回取得しています。

図2 スレッドダンプからスレッドの状態変化を予測する
図2 スレッドダンプからスレッドの状態変化を予測する

最初の3回は、pool-1-thread-1は休み中で、4回目は処理中の状態です。この場合は、予測を誤ると、1回目のスレッドダンプから3回目のスレッドダンプまでを休み中と判断してしまいます。

予測を誤らないためには、次のようにして、スレッドの状態変化をより細かく記録します。

  • スレッドダンプをより細かい周期で取得する
  • (負荷がかかりますが)JVMへ接続してスレッドの変化をすべて記録する

しかし、すべてのスレッドの状態を記録するのは非常に高負荷になるほか、情報を取得することが負荷の中心となってしまい、本来のボトルネックが隠れてしまうことがあるため注意しましょう。すべての状態を記録するのではなく、まずは一定時間を超えた状態のみ記録することでボトルネックとなる状態を絞り込み、絞り込んだ状態のみをすべて記録するなどの対応が必要です。

次回は、アプリケーションが取得すべき情報について解説します。

おすすめ記事

記事・ニュース一覧