From d44b14e38bd5f01addef5b396f9b6c8563eb631d Mon Sep 17 00:00:00 2001 From: Brad Schoening <5796692+bschoening@users.noreply.github.com> Date: Tue, 7 Dec 2021 22:31:32 -0500 Subject: [PATCH] renovated for G1GC with Java 9 and removed parallel and CMS support --- GCAllocationTest.jsh | 2 +- README.md | 10 ++++- gc_log_visualizer.py | 103 ++----------------------------------------- 3 files changed, 14 insertions(+), 101 deletions(-) diff --git a/GCAllocationTest.jsh b/GCAllocationTest.jsh index e82ee54..1e49467 100755 --- a/GCAllocationTest.jsh +++ b/GCAllocationTest.jsh @@ -1,7 +1,7 @@ //usr/bin/env jshell --show-version --execution local '-J-Xlog:gc+ergo*=trace:/tmp/gc.log' "$0" "$@"; exit $? /* - usage: jshell '-J-Xlog:gc*=trace:/tmp/gc.log' --execution local GCAllocationTest.jsh + usage: jshell '-J-Xlog:gc*=debug:/tmp/gc.log:tags,uptime' --execution local GCAllocationTest.jsh */ import java.util.stream.IntStream; diff --git a/README.md b/README.md index cbadff1..98fc7d1 100644 --- a/README.md +++ b/README.md @@ -27,8 +27,16 @@ found 858 humongous objects in /tmp/gc.log # GC Log Preparation -The script has been run on ParallelGC and G1GC logs. There may be some oddities/issues with ParallelGC as profiling it hasn't proven overly useful. +The script is for G1GC logs. The following gc params are required for full functionality. +java 8: + `-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintAdaptiveSizePolicy` + +Java 9: + +`-Xlog:gc*` + + diff --git a/gc_log_visualizer.py b/gc_log_visualizer.py index 6b92371..fd81765 100644 --- a/gc_log_visualizer.py +++ b/gc_log_visualizer.py @@ -5,6 +5,7 @@ import os import dateutil.parser +# usage: python gc_log_visualizer.py gc.log class StwSubTimings: def __init__(self): @@ -27,9 +28,6 @@ def unknown_time(self, total): class LogParser: heapG1GCPattern = '\s*\[Eden: ([0-9.]+)([BKMG])\(([0-9.]+)([BKMG])\)->[0-9.BKMG()]+ Survivors: ([0-9.]+)([BKMG])->([0-9.]+)([BKMG]) Heap: ([0-9.]+)([BKMG])\([0-9.BKMG]+\)->([0-9.]+)([BKMG])\([0-9.BKMG]+\)' - parallelPattern = '\s*\[PSYoungGen: ([0-9.]+)([BKMG])->([0-9.]+)([BKMG])\([0-9.MKBG]+\)\] ([0-9.]+)([MKBG])->([0-9.]+)([MKBG])\([0-9.MKBG]+\),' - parallelFullPattern = '\s*\[PSYoungGen: ([0-9.]+)([BKMG])->([0-9.]+)([BKMG])\([0-9.MKBG]+\)\] \[ParOldGen: [0-9.BKMG]+->[0-9.BKMG]+\([0-9.MKBG]+\)\] ([0-9.]+)([MKBG])->([0-9.]+)([MKBG])\([0-9.MKBG]+\),' - heapCMSPattern = '.*\[ParNew: ([0-9.]+)([BKMG])->([0-9.]+)([BKMG])\([0-9.BKMG]+\), [.0-9]+ secs\] ([0-9.]+)([BKMG])->([0-9.]+)([BKMG])\([0-9.BKMG]+\).*' rootScanStartPattern = '[0-9T\-\:\.\+]* ([0-9.]*): \[GC concurrent-root-region-scan-start\]' rootScanMarkEndPattern = '[0-9T\-\:\.\+]* ([0-9.]*): \[GC concurrent-mark-end, .*' rootScanEndPattern = '[0-9T\-\:\.\+]* ([0-9.]*): \[GC concurrent-cleanup-end, .*' @@ -52,15 +50,11 @@ def __init__(self, input_file): self.gc_file = open('gc.dat', "w") self.young_file = open('young.dat', "w") self.root_scan_file = open('rootscan.dat', "w") - self.cms_mark_file = open('cms_mark.dat', "w") - self.cms_rescan_file = open('cms_rescan.dat', "w") self.mixed_duration_file = open('mixed_duration.dat', "w") self.exhaustion_file = open('exhaustion.dat', "w") self.humongous_objects_file = open('humongous_objects.dat', "w") self.reclaimable_file = open('reclaimable.dat', "w") self.gc_alg_g1gc = False - self.gc_alg_cms = False - self.gc_alg_parallel = False self.pre_gc_total = 0 self.post_gc_total = 0 self.pre_gc_young = 0 @@ -92,8 +86,6 @@ def cleanup(self): os.unlink(self.gc_file.name) os.unlink(self.young_file.name) os.unlink(self.root_scan_file.name) - os.unlink(self.cms_mark_file.name) - os.unlink(self.cms_rescan_file.name) os.unlink(self.mixed_duration_file.name) os.unlink(self.exhaustion_file.name) os.unlink(self.humongous_objects_file.name) @@ -109,8 +101,6 @@ def close_files(self): self.full_gc_file.close() self.young_file.close() self.root_scan_file.close() - self.cms_mark_file.close() - self.cms_rescan_file.close() self.mixed_duration_file.close() self.exhaustion_file.close() self.humongous_objects_file.close() @@ -126,15 +116,7 @@ def gnuplot(self, name, start, end): occupancy_threshold_arrow = "" if self.occupancy_threshold: occupancy_threshold_arrow = "set arrow 10 from graph 0,first %d to graph 1, first %d nohead; " % (self.occupancy_threshold, self.occupancy_threshold) - occupancy_threshold_arrow += "set label \"%s\" at graph 0,first %d offset 1,1; " % ('IOF' if self.gc_alg_cms else 'IHOP', self.occupancy_threshold) - - # example of how to cap the y-range of the graph at .2 - #gnuplot_cmd = "gnuplot -e 'set term png size %s; set yrange [0:0.2]; set output \"%s-stw-200ms-cap.png\"; set xdata time; set timefmt \"%%Y-%%m-%%d:%%H:%%M:%%S\"; %s plot \"%s\" using 1:2'" % (self.size, name, xrange, self.pause_file.name) - #os.system(gnuplot_cmd) - - if self.gc_alg_parallel: - gnuplot_cmd = "gnuplot -e 'set term png size %s; set output \"%s-stw.png\"; set xdata time; set ylabel \"Secs\"; set timefmt \"%%Y-%%m-%%d:%%H:%%M:%%S\"; %s plot \"%s\" using 1:2 title \"all stw\"'" % (self.size, name, xrange, self.pause_file.name) - os.system(gnuplot_cmd) + occupancy_threshold_arrow += "set label \"%s\" at graph 0,first %d offset 1,1; " % ('IHOP', self.occupancy_threshold) # Separate young and mixed stw events if self.gc_alg_g1gc: @@ -151,24 +133,6 @@ def gnuplot(self, name, start, end): os.system(gnuplot_cmd) # Separate young and mixed stw events - if self.gc_alg_cms: - gnuplot_cmd = "gnuplot -e 'set term png size %s; set output \"%s-stw-young.png\"; set xdata time; set ylabel \"Secs\"; set timefmt \"%%Y-%%m-%%d:%%H:%%M:%%S\"; %s plot \"%s\" using 1:2 title \"young\"'" % (self.size, name, xrange, self.pause_file.name) - os.system(gnuplot_cmd) - gnuplot_cmd = "gnuplot -e 'set term png size %s; set output \"%s-stw-all.png\"; set xdata time; " \ - "set ylabel \"Secs\"; " \ - "set timefmt \"%%Y-%%m-%%d:%%H:%%M:%%S\"; " \ - "%s " \ - "plot \"%s\" using 1:2 title \"young\"" \ - ", \"%s\" using 1:2 title \"mark\"" \ - ", \"%s\" using 1:2 title \"rescan\"'" % (self.size, name, xrange, self.pause_file.name, self.cms_mark_file.name, self.cms_rescan_file.name) - os.system(gnuplot_cmd) - gnuplot_cmd = "gnuplot -e 'set term png size %s; set output \"%s-stw-old.png\"; set xdata time; " \ - "set ylabel \"Secs\"; " \ - "set timefmt \"%%Y-%%m-%%d:%%H:%%M:%%S\"; " \ - "%s " \ - "plot \"%s\" using 1:2 title \"mark\"" \ - ", \"%s\" using 1:2 title \"rescan\"'" % (self.size, name, xrange, self.cms_mark_file.name, self.cms_rescan_file.name) - os.system(gnuplot_cmd) # Stw sub-timings if self.gc_alg_g1gc: @@ -286,32 +250,11 @@ def determine_gc_alg(self): self.occupancy_threshold = int(max * (pct / 100.0) / 1048576.0) return - elif re.match(".*-XX:\+UseConcMarkSweepGC.*", line, flags=0): - self.gc_alg_cms = True - pct = self.get_long_field(line, '-XX:CMSInitiatingOccupancyFraction') - max = self.get_long_field(line, '-XX:MaxHeapSize') - if pct and max: - self.occupancy_threshold = int(max * (pct / 100.0) / 1048576.0) - return - elif re.match(".*-XX:\+UseParallelGC.*", line, flags=0): - self.gc_alg_parallel = True - return - m = re.match(LogParser.heapG1GCPattern, line, flags=0) if m: self.gc_alg_g1gc = True return - m = re.match(LogParser.heapCMSPattern, line, flags=0) - if m: - self.gc_alg_cms = True - return - - m = re.match(LogParser.parallelPattern, line, flags=0) - if m: - self.gc_alg_parallel = True - return - def get_long_field(self, line, field, def_value=0): m = re.match(".*%s=([0-9]+).*" % field, line, flags=0) if m: @@ -339,9 +282,6 @@ def parse_log(self): if not self.occupancy_threshold: self.collect_occupancy_threshold_pattern(line) - if self.gc_alg_cms: - self.write_cms_data(line) - # This needs to be last if self.line_has_pause_time(line): self.output_data() @@ -488,21 +428,6 @@ def parseMaxTiming(self, term, line, current_value): else: return current_value - def write_cms_data(self, line): - # collect stw times - # 1) initial marking step, checks from roots - # 2016-04-30T06:11:03.626+0000: 120634.808: [CMS-concurrent-mark: 0.922/0.922 secs] [Times: user=7.25 sys=0.59, real=0.93 secs] - m = re.match(".*\[CMS-concurrent-mark: .*, real=([.0-9]+) secs.*", line, flags=0) - if m: - self.cms_mark_file.write("%s %.6f\n" % (self.timestamp_string(), float(m.group(1)))) - - # 2) rescan phase - # 2016-04-30T06:11:09.341+0000: 120640.523: [GC (CMS Final Remark) [YG occupancy: 737574 K (996800 K)]2016-04-30T06:11:09.341+0000: 120640.523: [Rescan (parallel) , 0.0728015 secs]2016-04-30T06:11:09.414+0000: 120640.596: [weak refs processing, 0.0236183 secs]2016-04-30T06:11:09.437+0000: 120640.619: [class unloading, 0.0157037 secs]2016-04-30T06:11:09.453+0000: 120640.635: [scrub symbol table, 0.0069954 secs]2016-04-30T06:11:09.460+0000: 120640.642: [scrub string table, 0.0007916 secs][1 CMS-remark: 22933820K(30349760K)] 23671395K(31346560K), 0.1314855 secs] [Times: user=0.83 sys=0.17, real=0.13 secs] - m = re.match(".*\[Rescan .*, real=([.0-9]+) secs.*", line, flags=0) - if m: - self.cms_rescan_file.write("%s %.6f\n" % (self.timestamp_string(), float(m.group(1)))) - - def line_has_gc(self, line): m = re.match(LogParser.heapG1GCPattern, line, flags=0) if m: @@ -510,36 +435,16 @@ def line_has_gc(self, line): self.gc = True return - m = re.match(LogParser.parallelPattern, line, flags=0) - if m: - self.store_gc_amount(m) - self.gc = True - return - - m = re.match(LogParser.parallelFullPattern, line, flags=0) - if m: - self.store_gc_amount(m) - self.full_gc = True - - m = re.match(LogParser.heapCMSPattern, line, flags=0) - if m: - self.store_gc_amount(m) - self.gc = True - return def store_gc_amount(self, matcher): i = 1 self.pre_gc_young = self.scale(matcher.group(i), matcher.group(i+1)) - if self.gc_alg_g1gc or self.gc_alg_parallel: + if self.gc_alg_g1gc: i += 2 self.pre_gc_young_target = self.scale(matcher.group(i), matcher.group(i+1)) - if self.gc_alg_cms: - i += 2 - self.post_gc_young = self.scale(matcher.group(i), matcher.group(i+1)) - if self.gc_alg_g1gc: i += 2 self.pre_gc_survivor = self.scale(matcher.group(i), matcher.group(i+1)) @@ -595,7 +500,7 @@ def main(): logParser = LogParser(sys.argv[1]) try: logParser.determine_gc_alg() - print(("gc alg: parallel=%s, g1gc=%s, cms=%s" % (logParser.gc_alg_parallel, logParser.gc_alg_g1gc, logParser.gc_alg_cms))) + print(("gc alg: g1gc=%s" % (logParser.gc_alg_g1gc))) logParser.parse_log() logParser.close_files() basefilename = sys.argv[2] if len(sys.argv) > 2 else 'default'