jstatコマンドでjvmのガベージコレクションの様子を見てみよう

17922 ワード

メモリ管理 jstat 文字列操作ガベージコレクション Java Java テキストリンク

本記事では、jstatコマンドを使って、jvmが動的にガベージコレクションを行う様子を確認する。
java歴1週間の人間が自分用のメモとして書いた記事です。内容自体はn番煎じであること、考察も一部不完全であることをご承知おき下さい。

本記事の作成にあたって、以下の記事を大いに参考にさせていただきました。

JavaのGCの仕組みを整理する
 jstatを使用したJavaアプリのメモリ計測
 Javaのメモリ設定と、jstatの出力結果に関するメモ
 Javaのメモリ調査ことはじめ
 Javaのヒープ・メモリ管理の仕組み
 The jstat Command (公式ドキュメント)
JVMのGCアルゴリズムとチューニング

1. ガベージコレクションとは

ガベージコレクション(英:garbage collection; 以下GC)とは、一言でいえば「不要になったメモリ領域を動的に解放する機能」である。

例として以下のコードを挙げる。

public class TestJstat2 {
    public static void main(String[] args) {
        String s = "abc";
        String s += "d"; //新たなStringインスタンス"abcd"を生成して、その参照をsに代入
    }
}

javaではString型はイミュータブルとして扱われるため、一度生成されるとその内容が書き換えられることはない。
したがって、上記コードにおけるString s += "d";は、内部的には、

"abc"と"d"を結合した新たなStringインスタンス"abcd"を生成する
新たに生成した"abcd"の参照をsに代入する

という処理が行われている。(参考：JavaのStringについて)

この時、もともとsが参照していた文字列"abc"はどこからも参照されなくなる(要出典)。
このような「どこからも参照されなくなったメモリ領域」はガベージと呼ばれ、メモリが不必要に圧迫される要因となる。

こうしたガベージを自動的に開放する仕組みが、ガベージコレクションと呼ばれる技術である。
ガベージコレクションは基本的にはjvmが自動的に実行してくれる(System.gc()コマンドで強制的に実行することも可能)。

2. javaにおけるメモリ管理とガベージコレクション

以下の記事に詳しく解説されている。
JavaのGCの仕組みを整理する
 JVMのGCアルゴリズムとチューニング

以下、かいつまんで書くと、

まず、ヒープ領域の分類に関して、

javaのヒープ領域は、更新頻度が高い順にYoung領域, Old領域, MetaSpace領域に分かれている。
Young領域はさらに更新頻度が高い順にEden領域, Survivor0領域, Survivor1領域に分かれている。

といった仕様になっている。プログラムが使う領域は基本的にはEden領域である。Eden領域が足りなくなると、不要なデータをEden -> Survivor 0,1 -> old へと順次移していく。(下記画像は10 points about Java Heap Space or Java Heap Memoryより転載)

GCの方式として、下の2(+1)種類を紹介する。
下の順番とは前後するが、マイナーGC -> コンカレントGC -> フルGCの順で行われる。

マイナーGC(Young generation GC) :
Young領域に対するGC。Eden領域がいっぱいになった際に行われる。
- Young領域の参照されていないデータを削除
- Eden領域のデータをSurvivor(0,1)に移動
- Survivor0 <-> Survivor1の書き換え(?)
- Young領域に長く存在する(=一定回数以上のGCを経験した)データはOld領域に昇格
が行われる。
フルGC
Young, Old領域全体に対するGC。マイナーGCが失敗する、つまりOld領域がいっぱいになってYoung領域のデータをOld領域に退避できなくなった際に行われる。フルGC中はアプリケーションプロセスが止まるため、フルGCの発生はなるべく避けたいところ。
- 参照されていないデータを削除
- 領域のコンパクト化
が行われる。
コンカレントGC
上記2つが比較的オーソドックスなGC方式であるのに対し、コンカレントGCは簡易的なフルGCのようなものである(要出典)。フルGCを回避するための技術であり、順番としてはフルGCが発生する手前で行われる。コンカレントGCでは、Old領域がある程度(デフォルト7割)埋まった段階で、アプリケーションプロセスを止めずにOld領域に対してGCを行う(CONCURRENT GCと呼ばれるのはこのため)。これにより、フルGCの発生を抑制することが出来る。

3. jstatコマンド

jstatコマンドを用いることで、特定のjavaプロセスののメモリ消費に関する統計情報を得ることが出来る。
詳細は公式ドキュメントを参照のこと。

色々オプションが指定できるが、今回はjstat -gcutil -t [当該プロセスのプロセスID] [サンプリング間隔(ms)]の形で用いる。

それぞれのコマンドを簡単に説明すると、

-gcutilオプションでは、主に各領域(Young, Old等)の使用率の情報のほか、GCの回数等が得られる。
-tオプションを用いることで、出力にタイムスタンプの軸を追加する。
[当該プロセスのプロセスID]はjpsコマンドで確認できる。

-gcutilオプションを用いて得られる情報を以下にまとめた。ただし、*がついている項目は公式ドキュメントは記載されていないことに注意。(おそらく今回の実験ではデフォルトでコンカレントGC方式が適用されているもため追加で表示されたものと思われる)

ラベル	説明
S0	Survivor0領域の使用率(%)
S1	Survivor1領域の使用率(%)
E	Eden領域の使用率(%)
O	Old領域の使用率(%)
M	Metaspace領域の使用率(%)
CCS	圧縮されたクラス領域の使用率(%)
YGC	マイナーGC(Young generation GC)の累計回数
YGCT	マイナーGC(Young generation GC)の累計時間
FGC	フルGCの累計回数
FGCT	フルGCの累計時間
CGC	コンカレントGCの累計回数*
CGCT	コンカレントGCの累計時間*
GCT	すべてのGCの累計時間

4. 実験

今回は

意図的にガベージを生成して、
jstatコマンドを用いてjvmがガベージコレクションを行う様子を確認する

ことを目標とする。

4.1. ガベージの生成

[1. ガベージコレクションとは] では、文字列の単純な結合は無駄が多いことを説明したが、逆に言えば文字列を何度も結合すれば意図的にメモリを無駄遣いすることが出来る。
したがって今回は、Stringの結合を何度も行うことで意図的にガベージを発生させ、これに対してjvmが動的にガベージコレクションを行う様子を確認する、という作戦を取る。コードは以下。
実行時間が1分程度になるようにループの回数を調整してある。

TestJstat2.java

public class TestJstat2 {
    public static void main(String[] args) {
        long start = System.currentTimeMillis();  // 開始時刻を取得
        String s = "abc";
        for(int i=0; i<1000; i++) {
            for(int j=0; j<1000; j++) {
                s += "a";  //文字列の結合
            }
        }
        long finish = System.currentTimeMillis(); // 終了時刻の取得
        System.out.printf("実行時間：%f秒",(finish-start)/1000.0);  //処理にかかった時間の表示
    }
}

これをプロンプトで実行する。(下のコードは実行終了後を表す)

>javac TestJstat2.java

>java TestJstat2
実行時間：91.752000秒

4.2. jstatコマンドを用いたメモリの統計情報の取得

実行中に別のプロンプトを開き、jpsコマンドを使って上記のTestJstat2のプロセスIDを取得する。
IDを特定後、jstatコマンドを用いてTestJstat2のメモリに関する統計情報を1 s (or 1 ms)ごとに取得し、TestJstat2.txtに書き込む。

>jps
9472 Jps
9188 BootLanguagServerBootApp
4312
6572 TestJstat2

>jstat -gcutil -t 6572 1000 > TestJstat2.txt

TestJstat2.txtには、以下の結果が格納される。
それぞれの項目の詳細は[3. jstatコマンド]を参照のこと。
タイムスタンプは実際のプログラムの累計動作時間を表す。現状プログラムを実行してからjstatコマンドを叩くまで10 sほど手間取っているため、最初の10 s程度の時間は記録できていない(要改善)。

TestJstat2.txt

Timestamp         S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT   
            9.6   0.00  34.84  22.67   0.59  12.49   8.37    259    0.265     0    0.000     0    0.000    0.265
           10.7   0.00  36.59  69.77   0.59  12.49   8.37    287    0.291     0    0.000     0    0.000    0.291
           11.7   0.00  38.08  27.91   0.59  12.49   8.37    311    0.313     0    0.000     0    0.000    0.313
           12.7   0.00  39.33  94.99   0.59  12.49   8.37    332    0.334     0    0.000     0    0.000    0.334
           13.8   0.00  40.95  41.86   0.59  12.49   8.37    357    0.359     0    0.000     0    0.000    0.359
           14.8   0.00  42.51  30.23   0.59  12.49   8.37    382    0.385     0    0.000     0    0.000    0.385
           15.7   0.00  43.94  84.30   0.59  12.49   8.37    405    0.408     0    0.000     0    0.000    0.408
           16.7   0.00  45.44  10.17   0.59  12.49   8.37    429    0.430     0    0.000     0    0.000    0.430
           17.7   0.00  46.81  83.43   0.59  12.49   8.37    451    0.452     0    0.000     0    0.000    0.452
           18.7   0.00  48.19  71.22   0.59  12.49   8.37    473    0.473     0    0.000     0    0.000    0.473
           19.7   0.00  49.56  19.48   0.59  12.49   8.37    495    0.495     0    0.000     0    0.000    0.495
           20.8   0.00   0.20   0.00  43.35  12.49   8.37    577    0.579     0    0.000   142    0.098    0.677
           21.8   0.00   0.20   0.00  98.23  12.49   8.37    725    0.734     0    0.000   440    0.259    0.994
           22.8   0.00   0.20   0.00  24.88  12.49   8.37    877    0.894     0    0.000   742    0.420    1.315
           23.8   0.00   0.20   0.00  11.36  12.49   8.37   1030    1.054     0    0.000  1048    0.584    1.638
           24.8   0.00   0.20   0.00  26.86  12.49   8.37   1184    1.210     0    0.000  1356    0.744    1.954
...(略)

5. 結果と考察

5.1. 大まかな傾向 (1 sスケール)

まずは全体像をつかむため、サンプリング時間を1 sとしたときの結果を図1,2に示す。また、後で見るように、GC自体は1 sよりも細かい時間スケール(0.01 ~ 0.1 s程度)で発生しているため、図1,2からは各GCの様子は読み取れないことに注意する。

図1, 2を見ると、明らかに10 s(黒線)を境に挙動が異なることが分かる。以下、10 s以前(以後)の挙動についてそれぞれ考察する。


図1 : 各ヒープ領域の使用率。サンプリング間隔は1 s。


図2 : 各GCの累計実行回数。サンプリング間隔は1 s。

5.2. 10 s以前の挙動 (Young generation GCの発生)

TimeStampが10 s以下の段階では、各ヒープ領域の使用率(図1)は

Eden領域は20 ~ 100%の範囲で大きく変動
Suivivor 1領域は徐々に上昇
Old領域は使われていない

となっていることが分かる。

また、GCの累計回数(図2)を見ると、

Young generation GCの累計回数は時間経過とともに増加
concurrent GC, Full GCは行われていない

ことが分かる。

以上から、10 s以前では、Young領域だけでアプリケーションの処理を賄うことが出来ており、都度のYoung generation GCによってEden領域中の不要なメモリがSurvivor領域に移されている様子を確認することが出来たと言える。

このことは、より細かい時間スケールで見てみると明らかである。図3,4に、1 msでサンプリングした際の結果を示す。茶色のパルス(∝YGCの微分値)はYoung generation GCが発生したタイミングを表す。図4は図3の焼き直しだが、Survivor 1の変化が分かりやすくなるように強調してある。

図4を見ると、明らかに

Eden領域がいっぱいになるとYoung generation GCが発生し、
不要なデータをEden領域からSurvivor領域に移している

様子が確認できる。


図3 : 各ヒープ領域の使用率。サンプリング間隔は1 ms。茶色のパルス(∝YGCの微分値)はYoung generation GCが発生したタイミングを表す。


図4 : 各GCの累計実行回数。サンプリング間隔は1 ms。ほとんど図3の焼き直しだが、Survivor 1の変化を強調した(緑線)。

5.3. 10 s以降の挙動 (Young generation GC + Concurrent GCの発生)

(加筆予定)
一方、図1,2において、10 s以降の挙動は10 s以前の挙動とは大きく異なる。
10 s以降における、各ヒープ領域の使用率(図1)は

Eden領域は使われていない
Survivor 0,1 領域も使われていない
Oldが20 ~ 100%で変動

となっていることが分かる。

また、GCの累計回数(図2)を見ると、

Young generation GCの累計回数は時間経過とともに増加
Concurrent GCの累計回数も時間経過とともに増加
Full GCは行われていない。

ことが分かる。

以上から、アプリケーションのガベージが一定以上たまると、YOung領域でやりくりしていたデータはすべてOld領域に送られ、Young generation GCに加えてConcurrent GCが生じるようになることが分かる。(なぜ?)

上と同様に、改めて1 msのサンプリング間隔で測定しなおした結果を図5に載せる。茶色(ピンク色)のパルスは、Young generation GC(Concurrent GC)が発生したタイミングを表す(実際は、それぞれYGCとCGCの微分値に対応する)。この領域のGCは発生間隔が非常に早く、残念ながら変化を追うことが難しかった。その分メモリがひっ迫しているものと考えらえる。

図5から読み取れることとして、以下が挙げられる。

Concurrent GCの発生によってOld領域が整理されていることは何となく確認できる。
Concurrent GCはYoung GCよりも発生頻度が高い

一方、現時点ではまだわからないこととして、以下がある。Concurrent GC実行の仕組みを勉強する必要あり。

急にConcurrent GCが発生するようになったのはどういう基準か？
Concurrent GC発生に伴って、いままでYoung領域でやりくりされていたデータが急にOld領域に移されたのはなぜか？

6. まとめ

jstatコマンドを使って、jvmが動的にガベージコレクションを行う様子を確認した。
ガベージの生成は文字列の結合におけるjavaの挙動を応用した。
Young generation GC(マイナーGC)の動作を直接確認できた
その後concurrent GCの発生も確認できたが、詳細はわからない部分が多い。
Full GCを意図的に引き起こすことはできなかった

7. 今後の課題

もっと頑張ればFull GCを拝めるのか？
-> 時間のある時にループ数を増やす、Young, Old領域を制限するなどして再度試す
アプリケーションを実行してから、jstatを叩くまでの約10 sの間はどうなっているのか?
-> アプリケーションを実行後、間髪入れずにjstatを叩くシェルスクリプトを書いて再度試す
concurrent GCの開始タイミングは何で決まっているのか？
-> わからない、しらべる

8. 備考

javaのバージョンは以下。

>java -version
openjdk version "15.0.2" 2021-01-19
OpenJDK Runtime Environment (build 15.0.2+7-27)
OpenJDK 64-Bit Server VM (build 15.0.2+7-27, mixed mode, sharing)

Author And Source

この問題について(jstatコマンドでjvmのガベージコレクションの様子を見てみよう), 我々は、より多くの情報をここで見つけました https://qiita.com/alphajinsei/items/eea00b9ad1e858493fd0

著者帰属：元の著者の情報は、元のURLに含まれています。著作権は原作者に属する。

Content is automatically searched and collected through network algorithms . If there is a violation . Please contact us . We will adjust (correct author information ,or delete content ) as soon as possible .