はじめに
本連載はJavaプログラムの実行を担うJava仮想マシン（Java Virtual Machine：以下、JVM）の仕組みやその情報を収集する方法を解説します。JVMの内部を文章で解説するものではなく、その情報を取得するさまざまなツールの利用を通じてJVMについての知識を深めることを目的としています。第1回ではJVMの概要およびヒープダンプの取得と解析について解説しました。JVMについてあらかじめ概要を知っておくほうが理解が深まるため、第1回を読んでから本記事を読んでいただくのがおすすめです。
今回は、JVMのログ出力と、ツールでのJVMの情報取得や設定変更について解説します。ログ出力とツールに関する知識はどちらも障害発生時など異常事態のときに役立ちます。本記事を読み終わったとき、JVMのログを設定することと、ツールを使ってJVMの情報を取得したり設定を変更したりすることの2つを習得できます。
対象読者
本連載は対象読者としてJavaプログラミングの「中級者」を想定しています。中級の明確な基準は作れませんが、企業などで実用のJavaアプリケーション開発や運用の経験があると十分です。JVM関連のツールの使用方法を理解したい方や、将来的にプログラミング言語Java自体の開発に携わってみたい方にはさらに興味深い内容になります。
Unified Loggingを使ってJVMのログを出力しよう
最初の題材はログです。2021年末に脆弱性で大きな話題となったApache Log4jやほかにもLogbackは皆さんが開発するアプリケーションのログを出力するためのライブラリです。これらが出力するログの内容を思い浮かべてみてください。JVMに関連するログはまったく出ていないことがわかります。JVMのログはこういったアプリケーションのログとは別の、JVM内部のログ基盤で扱われます。この基盤をUnified Logging（以下UL）と呼びます。
このログを有効にすれば、JVM内部のさまざまなコンポーネントが出力するログを見られます。ULを日本語に翻訳すると統合ログとなるのですが、これはJVM内部のすべてのコンポーネントに共通する統一的なログシステムであることを意味します。ULを使ってJVMのログを出力させることで、JVM関連のさまざまな情報を取得できるようになります！ どうでしょう。ワクワクしませんか！？
皆さんが深く関わっているアプリケーションのJavaはどのようなバージョンでしょうか。ULはJava 9で導入した機能ですので、Java 8ではULが使えません。また、Java 9以降のバージョンでもバージョンアップ時にULの機能が向上しているため各バージョンで動作が異なることもあります。
ただし核となる機能はJava 9から変わっていませんので、本記事を読んで実際にULの動作を試すときはJava 9以降のどんなバージョンを使っても問題ありません。本記事では執筆時の最新バージョンであるJava 17（Eclipse TemurinのJDK 17.0.2+8）を使用します。
ULは-Xlogオプションを付けて実行すると有効になります。この-Xlogオプションの値をコロンで区切りながら出力をカスタマイズできます。まずはヘルプを見てみましょう。コロンで区切ってhelpなので-Xlog:helpというオプションを付けて実行します。
$ java -Xlog:help
-Xlog Usage: -Xlog[:[selections][:[output][:[decorators][:output-options]]]]
where 'selections' are combinations of tags and levels of the form tag1[+tag2...][*][=level][,...]
NOTE: Unless wildcard (*) is specified, only log messages tagged with exactly the tags specified will be matched.
Available log levels:
off, trace, debug, info, warning, error
Available log decorators:
（以下略）
ヘルプの出力は70行近くあるので、記事では途中から省略しました。最初の行にUsage（利用方法）があります。Usageの内容から-Xlog[:[selections][:[output][:[decorators][:output-options]]]]という形式で指定すればよいことがわかります。この[]で囲んでいる意味は、囲まれている部分が省略可能だということです。つまり-Xlog以降のすべてを省略できますし、selections、output、decorators、output-optionsといったそれぞれの項目を個別に省略できます。項目について以下の表にまとめます。
| 項目 | 説明 | 例 |
|---|---|---|
| selections | 出力するログを絞り込む。各ログメッセージに付けられたタグとそのメッセージのログレベルを指定できる。 | -Xlog:gc=info |
| output | ログの出力先を指定する。標準出力、標準エラー出力、ファイルに出力できる。 | -Xlog:gc:file=gc.log |
| decorators | ログメッセージとともに出力する項目を指定します。例えば日時やプロセスIDなどがある。 | -Xlog:gc:file=gc.log:utctime,pid |
| output-options |
出力先への詳細なオプションを指定する。ファイル出力にしたとき、ログローテーションを使用するためにファイルサイズやファイルの世代数を指定できる。 |
-Xlog:gc:file=gc.log:utctime,pid:filecount=5,filesize=1m |
コラム：Java 15にあったULの細かな不備を修正してみた
前述のとおりULのオプションはコロンで区切るのですが、項目は全部で4つあるのでコロンの数も最大4つまでです。では-Xlog:::::のようにコロンを5つ付けるとどうなるでしょうか。
Java 9から15では特にコロンの数に関してエラーや警告が出るということはありません。何も出ていないのでよい、でしょうか？ 例えばユーザが項目output-optionを指定しようとしたけれどもコロンの数を1つ多い5つにしてしまった-Xlog:::::filecount=3のケースを考えてみましょう。
結果としてこの世代数指定は指定できておらず、それを知らせるメッセージも出力されていないことになります。5つ以上にしてしまったときはユーザが指定を失敗していると想定して警告が出る方がよりよいです。筆者はこう考え、Java（OpenJDK）のバグトラッキングシステムに登録し自分でコードの修正をしてOpenJDKのGitHubリポジトリにプルリクエストを出しました。
ここで伝えたかったことは、新機能の追加や大きな影響を及ぼすバグの修正だけがオープンソースソフトウェアへのコントリビュートではないということです。コントリビュートの第一歩としてはドキュメントの修正が挙げられますが、やはりコードを修正してみたい方も多いでしょう。バグはある種わかりやすい修正対象ですが、「この動作はこれでよいのか？」という引っかかりからもう一歩進んでみるとコード修正でのコントリビュートにつながることがあります。同時にこのような軽微な修正でも結果として決して少なくない量のコードを読むことになりましたので、ULログについての理解が深まりました。
それではULの設定を1つ試してみましょう。ぜひ皆さんのPCでも実際に実行してみてください。以下のコマンドを実行します。
$ java -Xlog:gc:file=gc.log -version $ cat gc.log [0.004s][info][gc] Using G1
デフォルトではULは起動時点からの経過時間、ログレベル、タグ、そしてログメッセージを出力します。実行例を確認します。
| 出力内容 | 内容 |
|---|---|
| 0.004s | JVM起動からの経過時間 |
| info | ログレベル |
| gc | タグ |
| Using G1 | ログメッセージ |
2番目の項目のログレベルはlog4jなど一般的なログライブラリにあるものと同じでそのログメッセージの重要度を表すものです。ULのログレベルには重要度が低いものから順にtrace、debug、info、warning、errorという5つと、ログ出力を抑制するoffの合わせて6つのレベルがあります。3番目の項目のタグは実行時のオプションで指定する項目にあるselectionsにこのタグの値を記述してログに出力する内容をそのタグがついたものだけに絞り込めます。
ただし、実際にはこのタグを指定する仕組みはもう少し厳密なものです。実行するとわかりやすいので、次の2つのコマンドを実行してみてください。
$ java -Xlog:gc=debug -version $ java -Xlog:gc*=debug -version
2つのコマンドともログレベルをdebugにして出力量を増やしました。両方の出力を抜粋します。
$ java -Xlog:gc=debug -version [0.005s][info][gc] Using G1 [0.005s][debug][gc] ConcGCThreads: 2 offset 16 [0.005s][debug][gc] ParallelGCThreads: 8 [0.005s][debug][gc] Initialize mark stack with 4096 chunks, maximum 524288 （以下省略） $ java -Xlog:gc*=debug -version [0.005s][debug][gc,heap] Minimum heap 8388608 Initial heap 268435456 Maximum heap 4294967296 [0.005s][info ][gc ] Using G1 [0.005s][debug][gc,heap,coops] Heap address: 0x0000000700000000, size: 4096 MB, Compressed Oops mode: Zero based, Oop shift amount: 3 [0.005s][debug][gc ] ConcGCThreads: 2 offset 16 [0.005s][debug][gc ] ParallelGCThreads: 8 [0.005s][debug][gc ] Initialize mark stack with 4096 chunks, maximum 524288 [0.005s][debug][gc,ergo,heap ] Expand the heap. requested expansion amount: 268435456B expansion amount: 268435456B [0.005s][debug][gc,heap,region] Activate regions (0, 128) [0.005s][debug][gc,ihop ] Target occupancy update: old: 0B, new: 268435456B [0.005s][debug][gc,ergo,refine] Initial Refinement Zones: green: 2048, yellow: 6144, red: 10240, min yellow size: 4096 [0.006s][debug][gc,task ] G1 Service Thread (Remembered Set Sampling Task) (register) （以下省略）
2つのコマンドで出力内容が変わりました。先ほど厳密と表現しました。タグでの絞り込みはその内容と完全に一致するログメッセージのみ出力します。そのため-Xlog:gcではgcタグのみを持つメッセージしか出力しません。タグの中にgcタグを含むメッセージを出力したいときは2番目の-Xlog:gc*のようにワイルドカード*を使います。他にタグaとタグbの両方を含むメッセージをa+bの形式で指定できます。記事の分量上省略しますが、他の例として-Xlog:gc+heapと-Xlog:gc+heap*を実際に実行して出力の違いを確認してみてください。
ここまでULの使い方を説明しました。ULでログを出力するとどんなときに役立つのでしょうか。端的に言えばアプリケーションに問題や障害が発生したときです。具体例として前回第1回の記事で紹介したOutOfMemoryErrorを発生させるプログラムをもう一度見てみましょう。プログラムは以下のような内容です。
import java.util.*;
class OomeSample {
public static void main(String... args) {
List cache = new ArrayList<>();
String sql = "INSERT INTO table_a VALUES (?, ?, ?, ?, ?)";
while (true) {
cache.add(sql);
sql = sql + ", (?, ?, ?, ?, ?)";
}
}
}
OomeSample.javaというファイル名で保存し、ULのオプションを付けて実行します。
$ java -Xlog:gc* -Xmx128m OomeSample.java （中略） [0.287s][info][gc,start ] GC(21) Pause Full (G1 Compaction Pause) (中略) [0.292s][info][gc,heap ] GC(21) Eden regions: 0->0(6) [0.292s][info][gc,heap ] GC(21) Survivor regions: 0->0(0) [0.292s][info][gc,heap ] GC(21) Old regions: 126->126 [0.292s][info][gc,heap ] GC(21) Archive regions: 2->2 [0.292s][info][gc,heap ] GC(21) Humongous regions: 0->0 [0.292s][info][gc,metaspace ] GC(21) Metaspace: 9282K(9536K)->9282K(9536K) NonClass: 8150K(8256K)->8150K(8256K) Class: 1131K(1280K)->1131K(1280K) [0.292s][info][gc ] GC(21) Pause Full (G1 Compaction Pause) 123M->123M(128M) 4.239ms (以下省略)
ガベージコレクション自体についてここでは説明しませんが、Pause Full (G1 Compaction Pause) 123M->123M(128M)とあるのでフルGCの前後でヒープの使用量が減っていないことがわかります。このようにULログを出力しておくことで問題が発生したときにJVMがどのような状態であったのかログからも情報を得られます。また通常ULはログローテートの設定をしてファイルに出力させましょう。ローテートせず1ファイルにすべてのログを出力してしまう設定だと、たとえば障害で大量のログを出力したときディスク容量を使い切ってしまうといったことが起こります。
コラム：Java 8までのGCログ出力オプションはもう使用できません
ULができたことでJava 8までで使用していたGCログ出力オプションは使用できなくなりました。例えばJava 8で運用しているアプリケーションでは-XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:<ファイル名>といったGCログ設定があるかと思います。これらのオプションがもう使用できないため、ULでのGCログ設定に変更しなければなりません。今まで使用していた項目をULでどのように指定すればよいか調べる必要があります。公式なリファレンスではありませんがEmbracing JVM unified logging (JEP-158 / JEP-271)にある情報が便利です。
