Javaのエコシステムは、JVMがJava言語そのものよりも価値があるかもしれないところまで進化しています。
GCのメカニズムはまた、JVMのコアの一つであり、プログラムを実行する過程で、GCのプロセスは、ログの形で記録され、GCのログを理解することは、GCのメカニズムの研究の基礎であり、GCのログはまた、Javaプログラムが正常に実行されているかどうかを判断するための重要な基礎です。
この記事では、OpenJDK1.8とHotSpot仮想マシンに基づいて、GCロギングのいくつかの側面について詳しく説明します。
GC メカニズムの説明を始める前に、GC メカニズムについていくつか理解しておくこ とが重要です。
$ java -version
openjdk version "1.8.0_40"
OpenJDK Runtime Environment (build 1.8.0_40-b25)
OpenJDK 64-Bit Server VM (build 25.40-b25, mixed mode)
例えば、JDKはopenjdk1.8で、現在のJVMはServer VMで、混合実行モードを使用していることがわかります。
JVMはClient VMとServer VMに分けられ、Client VMはメモリが少なく、デスクトップアプリケーションのようなインタラクティブなシーンに適しており、Server VMはメモリが多いサーバーサイドの環境に適しています。
以下のコマンドでJVMを切り替えることができます。
$ java -client -version
$ java -server -version
ただし、Javaはデスクトップ・アプリケーションをあきらめたので、今後はServer VMに集中することができます。
Javaは複雑な言語で、解釈、コンパイル、またはその両方の方法を共存させることができ、デフォルトでは両方の方法が共存し、JVMがどちらのコードをコンパイルして実行するかを決定します。
この3つの実行は切り替えることもできます：
$ java -Xint -version # 完全に説明された実行
$ java -Xcomp -version # フルコンパイル実行
$ java -Xmixed -version # ハイブリッド実行
Client VMとServer VMのGCメカニズムは異なるため、この記事ではServer VMのGCにのみ焦点を当てます。
JVM メモリモデル
以下の2つの図は重要で、JVMについて言及するときは必ず使用します。
JVMのメモリーモデルは以下の通り：
Java 8以降では、メソッド領域はメタ空間を使用して実装され、ヒープ内の領域を占有する代わりに、この目的のためにローカルメモリが使用されます。
ヒープ内の領域は以下のように分布：
Eden、from、toの領域は新世代領域と呼ばれ、これら3つの領域の大きさの比率はデフォルトで8:1:1、新世代領域全体と旧世代領域の比率は1:2です。
GC 基本的な分類
一般的にGCは、領域の一部のGCとヒープ全体のGCに分けられます。 一般的に、領域の一部だけがGCされることが多く、ヒープ全体がGCされることが多いと、メモリリークなどの事態が発生する可能性があります。
いくつかの地域のGCは、新生代または古い時代に発生した可能性があります。
また、新世代と旧世代の両方をGCするG1コレクターが使用される特殊なケースもあります。
JVMのGCについて話すとき、それは一般的にJVMヒープの再利用を指し、ほとんどの場合、ヒープ内のメモリのみが再利用されます。
GC
デフォルトでは、Javaプログラムは実行時にGCログを表示せず、以下のJVMパラメータを必要とします：
-verbose:gc # コンソールでgcログを印刷する
-XX:+PrintGCDetails # gcプロセスの詳細を印刷する
-XX:+PrintGCDateStamps # gc発生のタイムスタンプを印刷する
ファイルとして保存したい場合は、以下のパラメータを追加する必要があります。 ファイルとして保存すると、コンソールにgcログが表示されなくなることに注意してください：
-Xloggc:gc.log # gcログをファイルとして保存する。デフォルトではプロジェクトのルート・ディレクトリに保存される。
他にもいくつかのサポートパラメータがあります。
-XX:+PrintGCApplicationStoppedTime # 世界の停止時間を表示する
-XX:+PrintGCApplicationConcurrentTime # プログラムが中断することなく実行されている時間を印刷する
-XX:+PrintHeapAtGC # GC前後のスタック情報を印刷する
-XX:+PrintTenuringDistribution # 各マイナーGCの後に新しい生存サイクルのしきい値を表示する
GCログの理解
最初に出てきたのは、パラメータが設定された基本的なログでした：
-Xms8m
-Xmx8m
-verbose:gc
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
次に以下のコードを実行します：
public class NoGC {
public static void main(String[] args) {
System.out.println("No gc");
}
}
生成されるログは以下の通り：
Heap
PSYoungGen total 2048K, used 1400K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
eden space 1536K, 91% used [0x00000000ffd80000,0x00000000ffede3d0,0x00000000fff00000)
from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
to space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
ParOldGen total 5632K, used 0K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
object space 5632K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffd80000)
Metaspace used 3018K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 323K, capacity 388K, committed 512K, reserved 1048576K
上記のコードを実行すると、上記のようなログが生成され、このコードを実行した時点ではGCが実行されておらず、ヒープのメモリ状態だけが出力されていることがわかります。
ヒープ内部からメモリを確保する代わりに、メタスペースはオフヒープ・メモリを使用します。しかし、構造的にはヒープと一緒に、メタ空間も非ヒープという名前を持っています。
PSYoungGenは新しい世代を表し、GCにコレクターを使用します。ParOldGenは古い世代を表し、GCにコレクターを使用します。
新世代は、eden、from、toの3つのリージョンに分かれています。 fromとtoのリージョンはSurvivorリージョンとも呼ばれ、上のログではそれぞれのリージョンのサイズと使用率を見ることができます。
老年期は他の地域に細分化されず、新しい世代で排除されなかったものは老年期に入ります。
パーシャルGCの発生
次のコードを実行してください：
public class NormalGC {
public static void main(String[] args) throws InterruptedException {
Object o = new Object();
for (int i = 0; ;i++) {
Thread.sleep(1000);
byte[] b = new byte[1024 * 1024];
b = null;
}
}
}
その結果、GCログは以下のようになりました：
{Heap before GC invocations=1 (full 0):
PSYoungGen total 2048K, used 1536K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
eden space 1536K, 100% used [0x00000000ffd80000,0x00000000fff00000,0x00000000fff00000)
from space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
to space 512K, 0% used [0x00000000fff00000,0x00000000fff00000,0x00000000fff80000)
ParOldGen total 5632K, used 0K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
object space 5632K, 0% used [0x00000000ff800000,0x00000000ff800000,0x00000000ffd80000)
Metaspace used 3136K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 333K, capacity 388K, committed 512K, reserved 1048576K
[GC (Allocation Failure)
Desired survivor size 524288 bytes, new threshold 7 (max 15)
[PSYoungGen: 1536K->496K(2048K)] 1536K->560K(7680K), 0.0024873 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
Heap after GC invocations=1 (full 0):
PSYoungGen total 2048K, used 496K [0x00000000ffd80000, 0x0000000100000000, 0x0000000100000000)
eden space 1536K, 0% used [0x00000000ffd80000,0x00000000ffd80000,0x00000000fff00000)
from space 512K, 96% used [0x00000000fff00000,0x00000000fff7c010,0x00000000fff80000)
to space 512K, 0% used [0x00000000fff80000,0x00000000fff80000,0x0000000100000000)
ParOldGen total 5632K, used 64K [0x00000000ff800000, 0x00000000ffd80000, 0x00000000ffd80000)
object space 5632K, 1% used [0x00000000ff800000,0x00000000ff810000,0x00000000ffd80000)
Metaspace used 3136K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 333K, capacity 388K, committed 512K, reserved 1048576K
}
Total time for which application threads were stopped: 0.0029243 seconds, Stopping threads took: 0.0000297 seconds
Application time: 1.0001808 seconds
まず、このログの構造全体を見てみましょう。
最初の部分はGCのヒープメモリの割り当てで、呼び出しはゴミ収集の回数を示し、カッコ内はフルGCの回数です。
次に、以下で詳しく説明するGCの再利用の詳細、そしてGC後のヒープのメモリ割り当てがあり、これはGCのヒープの状況と比較することができます。
PrintGCApplicationStoppedTime 最後の行は、パラメータによって印刷された情報で、GC 2011 によるダウンタイムを示します。 PrintGCApplicationConcurrentTime 最後の行は、パラメータによって表示される情報で、プログラムの実行時間を示します。
GCリカバリーの詳細ですが、上記のログから新世代のエデンエリアが一杯になっていることがわかり、その後、以下のログが表示されます。
[GC (Allocation Failure)
Desired survivor size 524288 bytes, new threshold 7 (max 15)
[PSYoungGen: 1536K->496K(2048K)] 1536K->560K(7680K), 0.0024873 secs]
[Times: user=0.01 sys=0.00, real=0.01 secs]
このログは、新世代でマイナーGCが行われた場所です。
-XX:+PrintTenuringDistribution 1行目は、このGCを開始した理由が新しいメモリの割り当てに失敗したためであることを示しています。 2行目は、新しい世代のオブジェクトの年齢と、オブジェクトが古い世代に入る年齢のしきい値を出力するパラメータが追加されたためで、デフォルトでは7、デフォルトでは15となっており、パラメータによって調整することができます。
3行目は具体的なリサイクル情報で、PSYoungGenは新世代で発生するリサイクルであることを示しています：
- 1536K->496K (2048K)は、この場合、新生代の領域を示しています。
- K->560K(7680K)
- 0.0024873 secs：GCが進行中の時間を秒単位で示します。
- Times: user=0.01 sys=0.00, real=0.01 secs: この部分も GC の時間をカウントしていますが、オペレーティングシステムの観点から、ユーザー時間、カーネル時間、クロック時間に分かれています。
フルGC発生
以下のコードを実行すると、Full GCが発生します：
public class FullGC {
public static void main(String[] args) {
int size = 1024 * 1024;
byte[] b = new byte[size];
b = null;
System.gc();
}
}
フルGCの残りの部分は基本的に上記のGCの部分と同じで、以下はフルGCが発生した場合の各領域のリカバリーを中心に説明します：
[Full GC (System.gc())
[PSYoungGen: 480K->0K(2048K)]
[ParOldGen: 1104K->473K(5632K)]
1584K->473K(7680K),
[Metaspace: 3107K->3107K(1056768K)],
0.0055681 secs]
[Times: user=0.02 sys=0.00, real=0.01 secs]
最初の行は、System.gc()の呼び出しによって開始されたフルGCが発生していることを示すものです。
2行目、3行目はそれぞれ新世代、旧世代の再生であり、再生シーケンスにおける各領域の占有メモリがプリントアウトされます。
4行目も同様に、ヒープメモリ全体の回復を示します。
5行目は、ゴミの回収がメタスペースでも行われたことを示していますが、回収に成功したものはありません。
メモリリークやオーバーフローが発生した場合
OutOfMemoryErrorは一般的なエラーで、この例外がスローされると一般的にFull GCが発生します。
public class Leak2GC {
public static void main(String[] args) {
Vector strings = new Vector();
for (int i = 0; ;i++) {
String str = new String("Hello gc" + i);
strings.add(str);
str = null;
}
}
}
上記のコードを実行すると、ダウンログが表示されます：
[Full GC (Allocation Failure)
[PSYoungGen: 943K->943K(2048K)]
[ParOldGen: 5556K->5539K(5632K)]
6499K->6483K(7680K),
[Metaspace: 3135K->3135K(1056768K)],
0.0260635 secs]
[Times: user=0.14 sys=0.00, real=0.03 secs]
Full GCを実行しても、各領域を効率的に再利用することができず、再利用できなかった後、以下のエラーが報告されます：
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space
at java.util.Arrays.copyOf(Arrays.java:3210)
at java.util.Arrays.copyOf(Arrays.java:3181)
at java.util.Vector.grow(Vector.java:266)
at java.util.Vector.ensureCapacityHelper(Vector.java:246)
at java.util.Vector.add(Vector.java:782)
at.rayjun.java.java8.gc.Leak2GC.main(Leak2GC.java:12)
GC 情報の統計分析
以上により、GCのログメッセージを読むことができるはずです。多くの場合、ログの一部で問題を特定することはできません。
したがって、GCの全体的な状況について統計を取る必要があり、これは通常、他の統計ツールの助けを借りて行われます。
最も直接的な方法は、JDKの組み込みツールであるjstatを使用することです。
$ jstat -gc 24991
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
512.0 512.0 0.0 0.0 1536.0 1024.0 5632.0 4755.0 4864.0 3477.4 512.0 378.3 54 0.082 1 0.018 0.099
各データ項目の意味は以下の通りです：
- S0Cゾーンのサイズ
- S1Cゾーンサイズ
- S1UFrom 使用するゾーンのサイズ
- S1U使用サイズへ
- ECエデンゾーンのサイズ
- EUのサイズを使用するようにしました。
- OC旧世代のサイズ
- OU：老年使用サイズ
- MCメソッド領域のサイズ
- MU：メソッドエリアで使用されるサイズ
- CCSC：圧縮クラス・スペース・サイズ
- CCUS：圧縮クラス・スペース使用サイズ
- YGC：若い世代のゴミ収集数
- YGCT：若い世代のゴミ収集消費時間
- FGC：高齢者向けゴミ収集数
- FGCT：高齢者のゴミ収集消費時間
- GCT：ゴミ収集の総時間
CGログは、 gceasy.io/ビジュアル分析ツールを使用して分析することもできます。
他のコレクターを使用する場合
上記のログでは、GC はデフォルトのコレクターの組み合わせを使用していますが、 UseConcMarkSweepGC パラメータを使用して CMS コレクターを有効にするなど、他のコレクターを使用することも可能です。
このコレクターを使用すると、ログは以下のようになります：
[GC (Allocation Failure) [ParNew: 1384K->256K(2432K), 0.0022504 secs] 1384K->491K(7936K), 0.0022693 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[Full GC (System.gc()) [CMS: 235K->472K(5504K), 0.0016647 secs] 1582K->472K(7936K), [Metaspace: 3009K->3009K(1056768K)], 0.0016851 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
新しい世代のコレクターはParNewコレクターを使用し、古い世代のコレクターはCMSコレクターを使用します。
ニーズに応じて他のコレクターを使用することも可能です。
文／レイジュン
