GCViwerでG1GCのログが解析できない場合

how_to_solve_analysis_gclog_in_gcviwer.md

GCViwerでG1GCのログが解析できない場合

おそらく、明示的に decorator を指定してる場合に、必要な装飾が足りてない。

https://github.com/chewiebug/GCViewer から引用

some support for OpenJDK 9 / 10 unified logging format -Xlog:gc:, the following configurations will work

• -Xlog:gc:file="path-to-file" (uses defaults)
• -Xlog:gc=info:file="path-to-file":tags,uptime,level (minimum configuration needed)
• -Xlog:gc*=trace:file="path-to-file":tags,time,uptime,level (maximum configuration supported, additional tags ok, but ignored; additional decorations will break parsing)

-Xlog:* の書式は以下の通り:

❯❯ 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:
 time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis (um), timenanos (tn), uptimenanos (un), hostname (hn), pid (p), tid (ti), level (l), tags (tg)
 Decorators can also be specified as 'none' for no decoration.

こんな感じで出力されてればOK

[0.001s][info][gc] Using G1
[0.025s][info][gc] GC(0) Pause Full (System.gc()) 2M->1M(14M) 3.960ms
[0.028s][info][gc] GC(1) Pause Full (System.gc()) 1M->1M(8M) 1.918ms

uptime の変わりに timestamp でも大丈夫

[2024-01-18T15:52:18.144+0000][info][gc] Using G1
[2024-01-18T15:52:18.161+0000][info][gc] GC(0) Pause Full (System.gc()) 2M->1M(14M) 3.115ms
[2024-01-18T15:52:18.164+0000][info][gc] GC(1) Pause Full (System.gc()) 1M->1M(8M) 2.111ms

理由

• タグを見て Reader を決めてる
  • https://github.com/chewiebug/GCViewer/blob/af97692884ac918ccbdf7a123fa698460a1d397e/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java#L157
• タグを見てどの行を使うか決めてる
  • https://github.com/chewiebug/GCViewer/blob/af97692884ac918ccbdf7a123fa698460a1d397e/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java#L170-L197

だめな例

java -Xlog:gc=info::utc
java -Xlog:gc*:file=gc.log:utc:filesize=10M,filecount=10
java -Xlog:gc*:file=gc.log:utc:filesize=10M,filecount=10

だいじょうぶな例

java -Xlog:gc
java -Xlog:gc=info::tags,uptime,level
java '-Xlog:gc*::tags,uptime,level'
java '-Xlog:gc*=info::tags,uptime,level'
java -Xlog:gc*::utc,tags,uptime,level:filesize=10M,filecount=10
java -Xlog:gc*:file=gc.log:utc,tags,level:filesize=10M,filecount=10