AWSのEC2(RHEL 7.3)でWildFly 10.1.0のGCログを詳細化する
最終更新日：2021/01/04 | 公開日：2017/10/19
目次
概要
WildFlyインストール後のデフォルトのJVM起動オプションでは、 GCログがファイルに出力されない、GCに関する出力情報が少ない、 発生時間が起動からの相対時間で表示されるため発生タイミングを把握しづらい、などの問題があり、 後からGCの調査を行おうとしたときに困るケースがあります。 そこで、JVMの起動オプションを変更し、これらの問題を解決します。
構成
想定環境
AWS(Amazon Web Services)のEC2上にインストール済みのWildFly 10.1.0の環境でJVMの起動オプションを変更しました。 参考までに、サーバのスペックは以下のとおりです。
■サーバスペック
| 項目 | 内容 |
|---|---|
| インスタンスタイプ | t2.micro |
| vCPU | 1 |
| メモリ | 1GB |
| ディスク | SSD 10GiB |
| リージョン | 日本 |
また、インストール済みのWildFlyの主な設定は以下の通りです。
■主な設定内容
| WildFlyインストールパス | /opt/wildfly-10.1.0.Final/ |
|---|
サーバ構成
OSバージョン
Red Hat Enterprise Linux 7.3 x86_64
ソフトウェア・パッケージ一覧
- jdk1.8.0_131-1.8.0_131-fcs.x86_64.rpm
- wildfly-10.1.0.Final.tar.gz
環境構築
設定
設定ファイルの起動オプションを変更
今回の検証環境ではWildFly(JVM)をstandaloneモードで起動しているため、 設定ファイルは standalone.conf を対象に修正します。 この設定ファイル内にJVMの起動オプションを設定している箇所がありますので、 そこにGCログに関するオプションを追加します。 指定したオプションの意味を簡単に記載しておきます。
■設定内容
| オプション | 意味 |
|---|---|
| -verbose:gc | GCログの有効化 |
| -Xloggc:/opt/wildfly-10.1.0.Final/standalone/log/gc.log_%t | GCログの出力先ファイル名をフルパスで指定、%t部分には2017-10-01_02-29-53の形式でJVMの起動時刻が入る ※指定しない場合は標準出力にログを出力 |
| -XX:+PrintGCDetails | ヒープ領域別のメモリ解放量を出力 ※指定しない場合はヒープサイズ全体のメモリ解放量のみ出力 |
| -XX:+PrintGCDateStamps | GCが発生した年月日時分秒を出力 ※指定しない場合はJVM起動からの相対時間のみ出力 |
注意点としては、この設定だとGCログが出力され続けてしまい、消す仕組みがありません。 GCログが不要となるタイミングで適宜削除orファイルを退避する運用を行ってください。 今回紹介しなかったオプションでログを自動でローテートすることもできます。
$ sudo su - Last login: Fri Sep 29 09:18:59 JST 2017 on pts/0 # cd /opt/wildfly-10.1.0.Final/bin/ # vi standalone.conf
ファイル名：/opt/wildfly-10.1.0.Final/bin/standalone.conf
※以下、該当箇所のみ変更※ # # Specify options to pass to the Java VM. # if [ "x$JAVA_OPTS" = "x" ]; then JAVA_OPTS="-Xms64m -Xmx512m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true" JAVA_OPTS="$JAVA_OPTS -Djboss.modules.system.pkgs=$JBOSS_MODULES_SYSTEM_PKGS -Djava.awt.headless=true" else echo "JAVA_OPTS already set in environment; overriding default settings with values: $JAVA_OPTS" fi ↓変更 # # Specify options to pass to the Java VM. # if [ "x$JAVA_OPTS" = "x" ]; then JAVA_OPTS="-Xms64m -Xmx512m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true" JAVA_OPTS="$JAVA_OPTS -Djboss.modules.system.pkgs=$JBOSS_MODULES_SYSTEM_PKGS -Djava.awt.headless=true" JAVA_OPTS="$JAVA_OPTS -verbose:gc -Xloggc:/opt/wildfly-10.1.0.Final/standalone/log/gc.log_%t" ←追加 JAVA_OPTS="$JAVA_OPTS -XX:+PrintGCDetails -XX:+PrintGCDateStamps" ←追加 else echo "JAVA_OPTS already set in environment; overriding default settings with values: $JAVA_OPTS" fi
WildFlyサービスの再起動
WildFlyサービス(JVM)を再起動します。 再起動後に起動中のプロセスを表示すると、GCログに関するオプションが追加されていることが分かります。
# systemctl restart wildfly # ps -ef | grep java wildfly 15171 15094 99 02:29 ? 00:00:11 java -D[Standalone] -server -Xms64m -Xmx512m -XX:MetaspaceSize=96M -XX:MaxMetaspaceSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -verbose:gc -Xloggc:/opt/wildfly-10.1.0.Final/standalone/log/gc.log_%t -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Dorg.jboss.boot.log.file=/opt/wildfly/standalone/log/server.log -Dlogging.configuration=file:/opt/wildfly/standalone/configuration/logging.properties -jar /opt/wildfly/jboss-modules.jar -mp /opt/wildfly/modules org.jboss.as.standalone -Djboss.home.dir=/opt/wildfly -Djboss.server.base.dir=/opt/wildfly/standalone -c standalone.xml -b 0.0.0.0 root 15276 11379 0 02:29 pts/0 00:00:00 grep --color=auto java
GCログの確認
オプションで指定したパスに指定したファイル名でGCログが出力されていることを確認します。 また、ログの中身を表示し、詳細化されていることを確認します。
# ls -l /opt/wildfly-10.1.0.Final/standalone/log/gc.log_*
-rw-r--r-- 1 wildfly wildfly 19016 Oct 1 02:30 /opt/wildfly-10.1.0.Final/standalone/log/gc.log.2017-10-01_02-29-53
# cat /opt/wildfly-10.1.0.Final/standalone/log/gc.log.2017-10-01_02-29-53
Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for linux-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:40 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 3618496k(2818512k free), swap 1048572k(1048572k free)
CommandLine flags: -XX:InitialHeapSize=67108864 -XX:MaxHeapSize=536870912 -XX:MaxMetaspaceSize=268435456 -XX:MetaspaceSize=100663296 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
2017-10-01T02:29:54.710+0900: 0.376: [GC (Allocation Failure) [PSYoungGen: 16384K->2533K(18944K)] 16384K->3469K(62976K), 0.0041268 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2017-10-01T02:29:55.043+0900: 0.709: [GC (Allocation Failure) [PSYoungGen: 18917K->2528K(35328K)] 19853K->7239K(79360K), 0.0065231 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2017-10-01T02:29:55.380+0900: 1.046: [GC (Allocation Failure) [PSYoungGen: 35296K->2528K(35328K)] 40011K->13780K(79360K), 0.0110143 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2017-10-01T02:29:55.401+0900: 1.067: [GC (GCLocker Initiated GC) [PSYoungGen: 6432K->2544K(68096K)] 17684K->14108K(112128K), 0.0157441 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
2017-10-01T02:29:55.914+0900: 1.580: [GC (Allocation Failure) [PSYoungGen: 68080K->2528K(68096K)] 79644K->23541K(112128K), 0.0250873 secs] [Times: user=0.04 sys=0.00, real=0.03 secs]
2017-10-01T02:29:57.893+0900: 3.560: [GC (Allocation Failure) [PSYoungGen: 68064K->14323K(138752K)] 89077K->41845K(182784K), 0.0244798 secs] [Times: user=0.03 sys=0.01, real=0.02 secs]
2017-10-01T02:29:59.228+0900: 4.894: [GC (Allocation Failure) [PSYoungGen: 138739K->20960K(145408K)] 166261K->66130K(190976K), 0.0416939 secs] [Times: user=0.07 sys=0.01, real=0.05 secs]
2017-10-01T02:29:59.270+0900: 4.936: [Full GC (Ergonomics) [PSYoungGen: 20960K->7622K(145408K)] [ParOldGen: 45170K->45548K(84480K)] 66130K->53171K(229888K), [Metaspace: 46560K->46557K(1093632K)], 0.1845175 secs] [Times: user=0.33 sys=0.00, real=0.18 secs]
（後略）
(おまけ) GCログの内容比較
最後にGCログに関するオプションを追加することで出力内容がどのように変わるかを比較します。 一気に全オプションを追加するとどのオプションでどの項目が出力されるようになったのかわかりづらいので、 上記設定手順とは別で3ステップで設定を変更してGCログの出力の違いを比較しました。
[1] -verbose:gc -Xloggc:/opt/wildfly-10.1.0.Final/standalone/log/gc.log_%t を追加してGCログをファイル出力するようにした場合
3.958: [Full GC (Ergonomics) 53008K->43827K(221184K), 0.1640714 secs]
[2] [1]から更に -XX:+PrintGCDetails を追加してヒープ領域別のメモリ解放量を出力するようにした場合
4.097: [Full GC (Ergonomics) [PSYoungGen: 15330K->4753K(138752K)] [ParOldGen: 36289K->43719K(83456K)] 51619K->48472K(222208K), [Metaspace: 43420K->43415K(1091584K)], 0.1786166 secs] [Times: user=0.34 sys=0.01, real=0.18 secs]
[3] [2]から更に -XX:+PrintGCDateStamps を追加してGC発生年月日時分秒を出力するようにした場合
2017-10-01T01:58:06.567+0900: 4.795: [Full GC (Ergonomics) [PSYoungGen: 20980K->10700K(144896K)] [ParOldGen: 46210K->46333K(88064K)] 67191K->57034K(232960K), [Metaspace: 44522K->44522K(1091584K)], 0.2747308 secs] [Times: user=0.54 sys=0.00, real=0.28 secs]