renovated for G1GC with Java 9 and removed parallel and CMS support

bschoening · Dec 8, 2021 · d44b14e · d44b14e
1 parent 023fcff
commit d44b14e
Show file tree

Hide file tree

Showing 3 changed files with 14 additions and 101 deletions.
diff --git 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
@@ -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
@@ -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,58 +428,23 @@ 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:
       self.store_gc_amount(m)
       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'