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

第5回　Java VMの情報を取得する（前編）

Java, システム運用, Java VM

この記事を読むのに必要な時間：およそ 2 分

Java VMで監視すべき4つのポイント

前回は，システム運用者がJava VM（JVM）⁠，アプリケーションサーバ，Javaアプリケーションから，ログ，JMXとMBean，ダンプを使用して情報を取得する方法を紹介しました。今回と次回では，JVMからどのような情報を最低限取得するべきか，詳細を紹介します。

システム運用者は，JVMが滞りなくアプリケーションを支援できているか，アプリケーションが動いているかを確認する必要があります。JVMは内部で管理しているさまざまなリソースに関する情報を持っていますが，システム運用者がそれらをすべてを監視することは不可能です。そこで，たくさんある情報の中から，次の4つのポイントに絞ってJVMの動きを監視します。

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

1.では，JVMがアプリケーションを中断するおもな理由であるガベージコレクションを確認します。

2.では，ガベージコレクションの一部の処理がアプリケーションと並行して実行されてリソースを奪い合ってしまっていないかを確認します。

3.では，OS上で動くほかのアプリケーションがファイルI/OやネットワークI/Oを消費しており，JVMが十分な帯域を確保できないためI/Oに時間がかかることがあるので，それを確認します。

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

今回は，ガベージコレクションに関する1.と2.について解説します。

ヒープ領域で管理すべき3つのこと

JVMは，メモリ空間を用途ごとに分割して管理しています。それらの中で，アプリケーションがオブジェクトを作成する場所として使用されるのがヒープ領域です。

JVMは，ヒープ領域がいっぱいになると，不要な領域を開放するためにガベージコレクション（GC）をおこないます。GCがおこなわれている一部の期間，アプリケーションは停止します。停止した状態は，Stop The Worldと呼ばれます。

GCには，CPUリソースを消費します。そのため，アプリケーションを停止しない場合でも，アプリケーションに割り当てるCPUリソースが減ってしまいます。

ヒープ領域の管理で必要なのは，次の3つになります。これらの情報を取得することで，JVMがアプリケーションの処理を妨げていないかを確認します。

  • アプリケーションはどのくらいの時間で，どれくらいのヒープ領域を使うのか
  • GCは，どれぐらいの頻度で，どれぐらいの時間をかけて，なぜ実行されるのか
  • GCにより，ヒープ領域内の各領域はそれぞれどこまで減少したか

確認の結果，GCがアプリケーションの処理を妨げている場合には，情報をもとに，ヒープ領域やGCをチューニングします。

GCログを出力する際のポイント

これらの情報を得るためには，GCのログ（GCログ）を取得します。GCログは，デフォルトでは無効になっていますが，有効化することで，標準出力に出力されるようになります。

GCログの出力のレベルには，通常と詳細の2段階あります。出力される内容はGCの実装によって異なります。たとえば，HotSpot JVMのパラレルGCの場合，通常レベルでは次の情報が出力されます。

  • GCの種類と原因
  • GC前後のメモリ量
  • GCの時間

詳細レベルでは，通常レベルの出力内容に加え，次の情報も出力されます。

  • ヒープ領域ごとのメモリ量
  • ユーザー空間・システム空間・実空間ごとの処理時間

ただし，どちらのレベルでもGCの発生時間を出力しないため，追加で時間を出力する必要があります。

システムのログ要件としては，ログの出力先，ログの保存量，ログを保存する期間があります。GCログは，デフォルトでは標準出力へ出力されますが，標準出力にはほかのログも出力されるため，別のファイルに出力するようにしましょう。また，GCログをファイルに出力すると，GCログのファイルが肥大化するため，一定の時間ごとや一定のサイズごとでログローテーションするようにします。あわせて，ログローテーションしたファイルを何世代分保持するかを設定します。

システム運用者は，ログ要件に合うように，これらを設定・運用しましょう。それぞれの設定は，JVMの起動オプションで指定します。手動でGCログのローテーションを行うには，jcmdコマンドを使用します。

  • GCログを出力する → -verbose:gc
  • 詳細なGCログを出力する → -XX:+PrintGCDetails
  • 日時を出力する → -XX:+PrintGCDateStamps
  • ファイルに出力する → -Xloggc:<ファイルパス>
  • ログローテーションする → -XX:+UseGCLogFileRotation
  • ローテーションによって保持する数 → -XX:NumberOfGCLogFiles=<数>
  • ログファイルのサイズ → -XX:GCLogFileSize=<ファイルのサイズ>

たとえば，1日ごとにGCログをローテーションする場合には，ログファイルのサイズを0に設定し，jcmdコマンドでGC.rotate_logを毎日0時に実行します。

GCログのサンプル（-XX:+PrintGCDetails，-XX:+PrintGCDateStampsを指定）

2017-01-11T16:11:41.242+0900: [GC (Allocation Failure) [PSYoungGen: 1533K->501K(2048K)] 1533K->541K(7680K), 0.0027834 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-01-11T16:11:41.243+0900: [Full GC (Allocation Failure) [PSYoungGen: 0K->0K(2048K)] [ParOldGen: 4455K->549K(5632K)] 4455K->549K(7680K), [Metaspace: 3376K->3376K(1056768K)], 0.0031210 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

GCの実行時間が長いと，アプリケーションが動ける時間が短くなってしまいます。アプリケーションを止めない場合でもGCがCPUリソースを使用してしまうため，アプリケーションが使えるリソース量が減ってしまいます。GCの時間が長くなっている場合には，ヒープ領域が不足している可能性があります。システム運用者は，GCログを確認して，チューニングを行います。

次のような場合は，アプリケーションが動いていないと判断できます。

  • GCの開始時間にGCの処理時間を加えた時刻が，次のGC開始時間と同一の場合
  • 一定時間の中で，GC時間の合計が一定時間と等しい場合

このような場合には，GCログを使用してヒープやGCをチューニングする必要があります。

また，一定時間の中で，GC時間の合計が占める割合が大きい場合には，チューニングを推奨します。

次回は，続いて「OSのリソースが十分に割り当てられているか」と「アプリケーションが動いているか」を確認するためにどのような情報が必要となるかを紹介します。

Java, システム運用, Java VM

著者プロフィール

伊藤智博（いとうちひろ）

日本オラクル（株）コンサルタント。

テクノロジストとしてJavaに関わる製品の技術支援をおもに担当し，Java Day TokyoやJavaOne San Franciscoなどでの講演も行う。得意分野は，Java全般を対象としたトラブルシューティングとパフォーマンスチューニング。最近は，Javaコミュニティへの支援や，Oracle製品とOSSの間を埋めるツールの作成を趣味としている。

ブログ：http://chiroito.blogspot.jp/
Twitter：@chiroito

コメント

コメントの記入