#155 support unified jvm logging format with tag "gc" (level = info) …

…and decorations tags,level,uptime (-Xlog:gc:file=<filename>)

README.md

@@ -19,7 +19,9 @@ When logfile rotation (-XX:+UseGCLogFileRotation) is enabled, the logfiles can b
 
 Supported verbose:gc formats are:
 
-- preliminary support for OpenJDK 9 Shenandoah algorithm in unified logging format -Xlog:gc:<file> -XX:+UseShenandoahGC
+- partial support for OpenJDK 9 unified logging format -Xlog:gc:<file>
+  - no heap information is evaluated, but all events with tag "gc" only should be recognised
+  - required decorations: tags,uptime (others will be ignored or parser might fail)
 - Oracle JDK 1.8 -Xloggc:<file> [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps]
 - Sun / Oracle JDK 1.7 with option -Xloggc:<file> [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps]
 - Sun / Oracle JDK 1.6 with option -Xloggc:<file> [-XX:+PrintGCDetails] [-XX:+PrintGCDateStamps]

src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java

@@ -11,8 +11,6 @@
 import java.util.LinkedList;
 import java.util.List;
 import java.util.logging.Level;
-import java.util.regex.Matcher;
-import java.util.regex.Pattern;
 
 import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
 import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType;
@@ -38,8 +36,6 @@ public abstract class AbstractDataReaderSun extends AbstractDataReader {
 
     private static final String CMS_PRINT_PROMOTION_FAILURE = "promotion failure size";
 
-    private static Pattern parenthesesPattern = Pattern.compile("\\([^()]*\\) ?");
-
     // java 8 log output
     protected static final String LOG_INFORMATION_OPENJDK = "OpenJDK";
     protected static final String LOG_INFORMATION_HOTSPOT = "Java HotSpot";
@@ -301,35 +297,12 @@ protected String parseTypeString(String line, ParseInformation pos) throws Parse
 
     protected ExtendedType parseType(String line, ParseInformation pos) throws ParseException {
         String typeString = parseTypeString(line, pos);
-        ExtendedType gcType = extractTypeFromParsedString(typeString);
-        if (gcType == null) {
-            throw new UnknownGcTypeException(typeString, line, pos);
-        }
-
-        return gcType;
+        return getDataReaderTools().parseType(typeString);
     }
 
 
     protected ExtendedType extractTypeFromParsedString(String typeName) throws UnknownGcTypeException {
-        ExtendedType extendedType = null;
-        String lookupTypeName = typeName.endsWith("--")
-                ? typeName.substring(0, typeName.length()-2)
-                        : typeName;
-        AbstractGCEvent.Type gcType = AbstractGCEvent.Type.lookup(lookupTypeName);
-        // the gcType may be null because there was a PrintGCCause flag enabled - if so, reparse it with the first paren set stripped
-        if (gcType == null) {
-            // try to parse it again with the parens removed
-            Matcher parenMatcher = parenthesesPattern.matcher(lookupTypeName);
-            if (parenMatcher.find()) {
-                gcType = AbstractGCEvent.Type.lookup(parenMatcher.replaceFirst(""));
-            }
-        }
-
-        if (gcType != null) {
-            extendedType = ExtendedType.lookup(gcType, typeName);
-        }
-
-        return extendedType;
+        return getDataReaderTools().extractTypeFromParsedString(typeName);
     }
 
     /**

src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java

@@ -1,8 +1,5 @@
 package com.tagtraum.perf.gcviewer.imp;
 
-import com.tagtraum.perf.gcviewer.model.GCResource;
-import com.tagtraum.perf.gcviewer.util.LocalisationHelper;
-
 import java.io.BufferedInputStream;
 import java.io.EOFException;
 import java.io.IOException;
@@ -12,6 +9,9 @@
 import java.util.logging.Logger;
 import java.util.zip.GZIPInputStream;
 
+import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.util.LocalisationHelper;
+
 /**
  *
  * Date: Jan 30, 2002
@@ -152,6 +152,11 @@ else if (s.indexOf("<AF") != -1) {
             if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: IBM <1.3.0");
             return new DataReaderIBM1_3_0(gcResource, in);
         }
+        // ...][info][gc       ] Using Shenandoah <or any other gc algorithm in unified jvm logging format>
+        else if (s.contains("][gc")) {
+            if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Oracle / OpenJDK unified jvm logging");
+            return new DataReaderUnifiedJvmLogging(gcResource, in);
+        }
         else if (s.indexOf(" (young)") > 0 || s.indexOf("G1Ergonomics") > 0) {
             // G1 logger usually starts with "<timestamp>: [GC pause (young)...]"
             // but can start with  <timestamp>: [G1Ergonomics (Heap Sizing) expand the heap...
@@ -202,11 +207,6 @@ else if (s.indexOf("starting collection, threshold allocation reached.") != -1)
             if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: IBM i5/OS 1.4.2");
             return new DataReaderIBMi5OS1_4_2(gcResource, in);
         }
-        // Shenandoah
-        else if (s.contains("Using Shenandoah")) {
-            if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Red Hat Shenandoah");
-            return new DataReaderShenandoah(gcResource, in);
-        }
         return null;
     }
 

src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java

@@ -2,12 +2,19 @@
 
 import java.util.logging.Level;
 import java.util.logging.Logger;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
+
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType;
 
 /**
  * Tools useful for (most) DataReader implementations.
  */
 public class DataReaderTools {
 
+    private static Pattern parenthesesPattern = Pattern.compile("\\([^()]*\\) ?");
+
     private Logger logger;
 
     public DataReaderTools(Logger logger) {
@@ -43,4 +50,46 @@ else if ('G' == memUnit) {
         }
     }
 
+    /**
+     * Returns the <code>ExtendedType</code> for <code>typeString</code>, if it can find one. If there is a type name
+     * including gc cause ("ParNew (promotion failed)", where (promotion failed) is the gc cause), the cause is removed
+     * while trying to find the type.
+     *
+     * @param typeString string representation of the gc event
+     * @return <code>ExtendedType</code> representing <code>typeString</code>
+     * @throws UnknownGcTypeException If <code>typeString</code> can't be converted to an <code>ExtendedType</code>
+     */
+    public ExtendedType parseType(String typeString) throws UnknownGcTypeException {
+        ExtendedType gcType = extractTypeFromParsedString(typeString.trim());
+        if (gcType == null) {
+            throw new UnknownGcTypeException(typeString);
+        }
+
+        return gcType;
+    }
+
+    public ExtendedType extractTypeFromParsedString(String typeName) {
+        typeName = typeName.trim();
+        ExtendedType extendedType = null;
+        String lookupTypeName = typeName.endsWith("--")
+                ? typeName.substring(0, typeName.length()-2)
+                : typeName;
+        AbstractGCEvent.Type gcType = AbstractGCEvent.Type.lookup(lookupTypeName);
+        // the gcType may be null because there was a PrintGCCause flag enabled - if so, reparse it with the first paren set stripped
+        if (gcType == null) {
+            // try to parse it again with the parens removed
+            Matcher parenMatcher = parenthesesPattern.matcher(lookupTypeName);
+            if (parenMatcher.find()) {
+                gcType = AbstractGCEvent.Type.lookup(parenMatcher.replaceFirst(""));
+            }
+        }
+
+        if (gcType != null) {
+            extendedType = ExtendedType.lookup(gcType, typeName);
+        }
+
+        return extendedType;
+    }
+
+
 }

src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderShenandoah.java → src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java

@@ -19,34 +19,32 @@
 import com.tagtraum.perf.gcviewer.model.GCResource;
 
 /**
- * DataReaderShenandoah can parse all the main messages for GCViewer with default decorations. <p>
- * Initial mark, Final mark, Init Update Refs, Final Update Refs, Pause Full Allocation Failure, Pause Full (System.gc()),
- * Concurrent mark, Concurrent evacuation, Concurrent reset bitmaps, Concurrent update references, Concurrent precleaning
+ * DataReaderUnifiedJvmLogging can parse all gc events of unified jvm logs with default decorations.
  * <p>
- * For more information: <a href="https://wiki.openjdk.java.net/display/shenandoah/Main">Shenandoah Wiki at OpenJDK</a>
+ * Currently needs the "gc" selector with "info" level and "uptime,level,tags" decorators (Java 9.0.1).
+ * <ul>
+ * <li>minimum configuration with defaults: <code>-Xlog:gc:file="path-to-file"</code></li>
+ * <li>configuration with tags + decorations: <code>-Xlog:gc=info:file="path-to-file":tags,uptime,level</code></li>
+ * </ul>
+ * Only processes the following information format for Serial, Parallel, CMS, G1 and Shenandoah algorithms, everything else is ignored:
+ * <pre>
+ * [0.731s][info][gc           ] GC(0) Pause Init Mark 1.021ms
+ * [0.735s][info][gc           ] GC(0) Concurrent marking 74M-&gt;74M(128M) 3.688ms
+ * [43.948s][info][gc             ] GC(831) Pause Full (Allocation Failure) 7943M-&gt;6013M(8192M) 14289.335ms
+ * </pre>
  *
  * <p>
- * Example Format
- * <p>[0.730s][info][gc,start     ] GC(0) Pause Init Mark
- * <p>[0.731s][info][gc           ] GC(0) Pause Init Mark 1.021ms
- * <p>[0.731s][info][gc,start     ] GC(0) Concurrent marking
- * <p>[0.735s][info][gc           ] GC(0) Concurrent marking 74M-&gt;74M(128M) 3.688ms
- * <p>[0.735s][info][gc,start     ] GC(0) Pause Final Mark
- * <p>[0.736s][info][gc           ] GC(0) Pause Final Mark 74M-&gt;76M(128M) 0.811ms
- * <p>[0.736s][info][gc,start     ] GC(0) Concurrent evacuation
- * <p>...
- * <p>[43.948s][info][gc             ] GC(831) Pause Full (Allocation Failure) 7943M-&gt;6013M(8192M) 14289.335ms
+ * For more information about Shenandoah see: <a href="https://wiki.openjdk.java.net/display/shenandoah/Main">Shenandoah Wiki at OpenJDK</a>
  */
-public class DataReaderShenandoah extends AbstractDataReader {
-
+public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
 
     // Input: [0.693s][info][gc           ] GC(0) Pause Init Mark 1.070ms
     // Group 1: 0.693
     // Group 2: Pause Init Mark
-    // Group 3: 1.070
+    // Group 3: 1.070 -> optional
     // Regex: ^\[([^s\]]*)[^\-]*\)[ ]([^\-]*)[ ]([0-9]+[.,][0-9]+)
     private static final Pattern PATTERN_WITHOUT_HEAP = Pattern.compile(
-            "^\\[([^s\\]]*)[^\\-]*\\)[ ]([^\\-]*)[ ]([0-9]+[.,][0-9]+)");
+            "^\\[([^s\\]]*)[^\\-]*\\)[ ]([^\\d]*)(([0-9]+[.,][0-9]+)|$)");
 
     // Input: [13.522s][info][gc            ] GC(708) Concurrent evacuation  4848M->4855M(4998M) 2.872ms
     // Group 1: 13.522
@@ -84,27 +82,29 @@ public class DataReaderShenandoah extends AbstractDataReader {
     private static final int HEAP_CURRENT_TOTAL = 5;
     private static final int HEAP_CURRENT_TOTAL_UNIT = 6;
 
-    private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Using Shenandoah", "Cancelling concurrent GC",
-            "[gc,start", "[gc,ergo", "[gc,stringtable", "[gc,init", "[gc,heap", "[pagesize", "[class", "[os", "[startuptime",
-            "[os,thread", "[gc,heap,exit", "Cancelling concurrent GC: Allocation Failure", "Phase ",
-            "[gc,stats", "[biasedlocking", "[logging", "[verification", "[modules,startuptime", "[safepoint", "[stacktrace",
-            "[exceptions", "thrown", "at bci", "for thread", "[module,load", "[module,startuptime");
+    /** list of strings, that must be part of the gc log line to be considered for parsing */
+    private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]");
+    /** list of strings, that target gc log lines, that - although part of INCLUDE_STRINGS - are not considered a gc event */
+    private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", "[trace");
+    /** list of strings, that are gc log lines, but not a gc event -&gt; should be logged only */
+    private static final List<String> LOG_ONLY_STRINGS = Arrays.asList("Using");
+
 
-    protected DataReaderShenandoah(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
+    protected DataReaderUnifiedJvmLogging(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
         super(gcResource, in);
     }
 
     @Override
     public GCModel read() throws IOException {
-        getLogger().info("Reading Shenandoah format...");
+        getLogger().info("Reading Oracle / OpenJDK unified jvm logging format...");
 
         try {
             GCModel model = new GCModel();
-            model.setFormat(GCModel.Format.RED_HAT_SHENANDOAH_GC);
+            model.setFormat(GCModel.Format.UNIFIED_JVM_LOGGING);
 
             Stream<String> lines = in.lines();
-            lines.filter(this::lineNotInExcludedStrings)
-                    .map(this::parseShenandoahEvent)
+            lines.filter(this::lineContainsParseableEvent)
+                    .map(this::parseEvent)
                     .filter(Objects::nonNull)
                     .forEach(model::add);
 
@@ -114,24 +114,31 @@ public GCModel read() throws IOException {
         }
     }
 
-    private AbstractGCEvent<?> parseShenandoahEvent(String line) {
+    private AbstractGCEvent<?> parseEvent(String line) {
         AbstractGCEvent<?> event = null;
 
         Matcher noHeapMatcher = PATTERN_WITHOUT_HEAP.matcher(line);
         Matcher withHeapMatcher = PATTERN_WITH_HEAP.matcher(line);
-        if (noHeapMatcher.find()) {
-            event = new GCEvent();
-            AbstractGCEvent.Type type = AbstractGCEvent.Type.lookup(noHeapMatcher.group(NO_HEAP_EVENT_NAME));
-            event.setType(type);
-            setPauseAndDateOrTimestamp(event, noHeapMatcher.group(NO_HEAP_TIMESTAMP), noHeapMatcher.group(NO_HEAP_DURATION));
-        } else if (withHeapMatcher.find()) {
+        try {
             event = line.contains("Concurrent") ? new ConcurrentGCEvent() : new GCEvent();
-            AbstractGCEvent.Type type = AbstractGCEvent.Type.lookup(withHeapMatcher.group(WITH_HEAP_EVENT_NAME));
-            event.setType(type);
-            setPauseAndDateOrTimestamp(event, withHeapMatcher.group(WITH_HEAP_TIMESTAMP), withHeapMatcher.group(WITH_HEAP_DURATION));
-            addHeapDetailsToEvent(event, withHeapMatcher.group(WITH_HEAP_MEMORY));
-        } else {
-            getLogger().warning(String.format("Failed to parse line number %d in the log file: %s", in.getLineNumber(), line));
+            if (noHeapMatcher.find()) {
+                AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(noHeapMatcher.group(NO_HEAP_EVENT_NAME));
+                event.setExtendedType(type);
+                setPauseAndDateOrTimestamp(event, noHeapMatcher.group(NO_HEAP_TIMESTAMP), noHeapMatcher.groupCount() > 2 ? noHeapMatcher.group(NO_HEAP_DURATION) : null);
+            } else if (withHeapMatcher.find()) {
+                AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(withHeapMatcher.group(WITH_HEAP_EVENT_NAME));
+                event.setExtendedType(type);
+                setPauseAndDateOrTimestamp(event, withHeapMatcher.group(WITH_HEAP_TIMESTAMP), withHeapMatcher.group(WITH_HEAP_DURATION));
+                addHeapDetailsToEvent(event, withHeapMatcher.group(WITH_HEAP_MEMORY));
+            } else {
+                // prevent incomplete event from being added to the GCModel
+                event = null;
+                getLogger().warning(String.format("Failed to parse line number %d (line=\"%s\")", in.getLineNumber(), line));
+            }
+        } catch (UnknownGcTypeException | NumberFormatException e) {
+            // prevent incomplete event from being added to the GCModel
+            event = null;
+            getLogger().warning(String.format("Failed to parse gc event (%s) on line number %d (line=\"%s\")", e.toString(), in.getLineNumber(), line));
         }
 
         return event;
@@ -143,8 +150,10 @@ private AbstractGCEvent<?> parseShenandoahEvent(String line) {
      * @param dateOrTimeStampAsString   Date- or timestamp information from regex group as string
      */
     private void setPauseAndDateOrTimestamp(AbstractGCEvent<?> event, String dateOrTimeStampAsString, String pauseAsString) {
-        double pause = Double.parseDouble(pauseAsString.replace(",", "."));
-        event.setPause(pause / 1000);
+        if (pauseAsString != null && pauseAsString.length() > 0) {
+            double pause = Double.parseDouble(pauseAsString.replace(",", "."));
+            event.setPause(pause / 1000);
+        }
         if (PATTERN_ISO8601_DATE.matcher(dateOrTimeStampAsString).find()) {
             ZonedDateTime dateTime = ZonedDateTime.parse(dateOrTimeStampAsString, AbstractDataReaderSun.DATE_TIME_FORMATTER);
             event.setDateStamp(dateTime);
@@ -169,12 +178,32 @@ private void addHeapDetailsToEvent(AbstractGCEvent<?> event, String memoryString
                     Integer.parseInt(matcher.group(HEAP_CURRENT_TOTAL)), matcher.group(HEAP_CURRENT_TOTAL_UNIT).charAt(0), memoryString));
             event.setExtendedType(event.getExtendedType());
         } else {
-            getLogger().warning("Failed to find heap details from line: " + memoryString);
+            getLogger().warning("Failed to find heap details from string: \"" + memoryString + "\"");
         }
     }
 
-    private boolean lineNotInExcludedStrings(String line) {
-        return EXCLUDE_STRINGS.stream().noneMatch(line::contains);
+    private boolean isExcludedLine(String line) {
+        return EXCLUDE_STRINGS.stream().anyMatch(line::contains);
+    }
+
+    private boolean isCandidateForParseableEvent(String line) {
+        return INCLUDE_STRINGS.stream().anyMatch(line::contains);
+    }
+
+    private boolean isLogOnlyLine(String line) {
+        return LOG_ONLY_STRINGS.stream().anyMatch(line::contains);
+    }
+
+    private boolean lineContainsParseableEvent(String line) {
+        if (isCandidateForParseableEvent(line) && !isExcludedLine(line)) {
+            if (isLogOnlyLine(line)) {
+                getLogger().info(line.substring(line.lastIndexOf("]")+1));
+                return false;
+            } else {
+                return true;
+            }
+        }
+        return false;
     }
 
 }