jvm-gc-logs-analyzer
jvm-gc-logs-analyzer copied to clipboard
krzysztofslusarski
Add intial support for ZGC (Java 15)
JFYI
Don't know if you have any ZGC support planned. I just fixed the most pressing issues
Hmm, I think I got it wrong, as cycleEntries should only be STW GC pauses, is that correct?
But then I think that the form, how the GCLogCycleEntries are collected currently, doesn't match well to ZGC. As each GC phase in ZGC looks more or less the same (AFAI can see, yet), but consists of multiple subphases, where some are STW and some are concurrent.
@krzysztofslusarski any opinion on this? I'd like to get some useful statistics for ZGC, but currently not sure how to proceed.
@kutzi Can you please attach some example of ZGC logs? Or send it to me at pasqal [at] gmail.com?
Unfortunately ZGC logs are in completely differtent format then G1GC. Recognizing it by:
line.contains("Using The Z Garbage Collector")
is not good. This line occurs only at the begging of the log file. My analyzer should work also with logs from the middle of working time of the JVM.
I see 2 possibilities for ZGC:
Collect the most important data Collect only the most important data. You just need to parse lines:
[2021-08-04T15:31:54.546+0000][1021.243s][info ][gc ] GC(51) Garbage Collection (Proactive) 266M(69%)->174M(45%)
[2021-08-04T15:32:17.805+0000][1044.502s][info ][gc ] GC(52) Garbage Collection (Proactive) 272M(71%)->178M(46%)
[2021-08-04T15:32:39.767+0000][1066.464s][info ][gc ] GC(53) Garbage Collection (Proactive) 254M(66%)->178M(46%)
[2021-08-04T15:33:00.447+0000][1087.144s][info ][gc ] GC(54) Garbage Collection (Proactive) 240M(62%)->176M(46%)
[2021-08-04T15:33:19.537+0000][1106.234s][info ][gc ] GC(55) Garbage Collection (Proactive) 248M(65%)->176M(46%)
[2021-08-04T15:33:37.437+0000][1124.134s][info ][gc ] GC(56) Garbage Collection (Proactive) 224M(58%)->176M(46%)
[2021-08-04T15:33:54.559+0000][1141.256s][info ][gc ] GC(57) Garbage Collection (Proactive) 220M(57%)->176M(46%)
[2021-08-04T15:34:12.543+0000][1159.240s][info ][gc ] GC(58) Garbage Collection (Proactive) 246M(64%)->176M(46%)
[2021-08-04T15:34:30.731+0000][1177.428s][info ][gc ] GC(59) Garbage Collection (Proactive) 216M(56%)->176M(46%)
You can check if "%" exists in the log line.
From that lines you can generate "heap after gc", "heap before gc", "allocation rate" graphs. From safepoints logs:
[2021-08-04T15:35:49.414+0000][1256.111s][info ][safepoint ] Safepoint "ZMarkStart", Time since last: 759323993 ns, Reaching safepoint: 270812 ns, At safepoint: 632367 ns, Total: 903179 ns
[2021-08-04T15:35:49.676+0000][1256.373s][info ][safepoint ] Safepoint "ZMarkEnd", Time since last: 261671752 ns, Reaching safepoint: 253829 ns, At safepoint: 112555 ns, Total: 366384 ns
[2021-08-04T15:35:49.740+0000][1256.437s][info ][safepoint ] Safepoint "ZRelocateStart", Time since last: 63530249 ns, Reaching safepoint: 332433 ns, At safepoint: 867854 ns, Total: 1200287 ns
you should have all the stats for stop-the-world phases (this should work already at master branch).
What else do you need at external tool? ZGC has a pretty good statistics:
[2021-08-04T15:36:13.512+0000][1280.210s][info ][gc,stats ] === Garbage Collection Statistics =======================================================================================================================
[2021-08-04T15:36:13.513+0000][1280.210s][info ][gc,stats ] Last 10s Last 10m Last 10h Total
[2021-08-04T15:36:13.513+0000][1280.210s][info ][gc,stats ] Avg / Max Avg / Max Avg / Max Avg / Max
[2021-08-04T15:36:13.513+0000][1280.210s][info ][gc,stats ] Collector: Garbage Collection Cycle 320.092 / 320.092 396.038 / 639.030 377.056 / 685.292 377.056 / 685.292 ms
[2021-08-04T15:36:13.513+0000][1280.210s][info ][gc,stats ] Contention: Mark Segment Reset Contention 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
[2021-08-04T15:36:13.513+0000][1280.210s][info ][gc,stats ] Contention: Mark SeqNum Reset Contention 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
[2021-08-04T15:36:13.513+0000][1280.210s][info ][gc,stats ] Contention: Relocation Contention 0 / 0 0 / 0 0 / 2 0 / 2 ops/s
...
Aren't they enough for any analyze?
Do a dedicated parser for ZGC It's pretty much what you did, but I would start from the point where user set which GC is used.
Unfortunately ZGC logs are in completely differtent format then G1GC. Recognizing it by:
line.contains("Using The Z Garbage Collector")is not good. This line occurs only at the begging of the log file. My analyzer should work also with logs from the middle of working time of the JVM.
I was just trying to get sth. in quickly. I didn't familiarise myself with the UI code, yet
Collect the most important data Collect only the most important data. You just need to parse lines:
I was hoping to get some more GC insights than from just the safepoint logs - I already tried parsing only the safepoint ones and that works fine. TBH, I don't understand all the statistics you generate for G1, but I was hoping to get sth. similar for ZGC. E.g. concurrent vs STW GC phases
From that lines you can generate "heap after gc", "heap before gc", "allocation rate" graphs. From safepoints logs:
Heap before and heap after a now working with my changes. However, I had to declare the ZGC log cycles as 'genuine' GCs - which I think means: STW-ones in the diction of this tool, right?
What else do you need at external tool? ZGC has a pretty good statistics: ... Aren't they enough for any analyze?
I'd like some graphical presentation as with your tool :-)
Maybe integration with https://devblogs.microsoft.com/java/introducing-microsoft-gctoolkit/ is an answer. I have a plan to look into this tool and get rid of GC parser.
Maybe integration with https://devblogs.microsoft.com/java/introducing-microsoft-gctoolkit/ is an answer. I have a plan to look into this tool and get rid of GC parser.
Uh, interesting. Brand new apparently.