Merge pull request #231 from chewiebug/feature/#228/support-uptimemillis

Feature/#228/support uptimemillis
chewiebug · Sep 17, 2019 · eb89b1f · eb89b1f
2 parents 695f8f4 + 1e4120d
commit eb89b1f
Show file tree

Hide file tree

Showing 6 changed files with 84 additions and 4 deletions.
diff --git a/pom.xml b/pom.xml
@@ -78,6 +78,10 @@
             <name>Maciej Kwiecien</name>
             <url>https://github.com/xylu</url>
         </developer>
+        <developer>
+            <name>Dennis Lawler</name>
+            <url>https://github.com/drawlerr</url>
+        </developer>
         <developer>
             <name>Yanqi Li</name>
             <url>https://github.com/yanqilee</url>

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -59,10 +59,11 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
     // Regex: ^(?:\[(?<time>[0-9-T:.+]*)])?(?:\[(?<uptime>[^s]*)s])?\[(?<level>[^]]+)]\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\((?<gcnumber>[0-9]+)\)[ ](?<type>([-.a-zA-Z ()]+|[a-zA-Z1 ()]+))(?:(?:[ ](?<tail>[0-9]{1}.*))|$)
     //   note for the <type> part: easiest would have been to use [^0-9]+, but the G1 events don't fit there, because of the number in their name
     private static final Pattern PATTERN_DECORATORS = Pattern.compile(
-            "^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
+            "^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^ms]*)(?<uptimeunit>m?s)])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
     );
     private static final String GROUP_DECORATORS_TIME = "time";
     private static final String GROUP_DECORATORS_UPTIME = "uptime";
+    private static final String GROUP_DECORATORS_UPTIME_UNIT = "uptimeunit";
     private static final String GROUP_DECORATORS_LEVEL = "level";
     private static final String GROUP_DECORATORS_TAGS = "tags";
     private static final String GROUP_DECORATORS_GC_NUMBER = "gcnumber";
@@ -451,7 +452,7 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decorator
             event.setExtendedType(type);
             event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
             setDateStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_TIME));
-            setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME));
+            setTimeStampIfPresent(event, decoratorsMatcher.group(GROUP_DECORATORS_UPTIME), decoratorsMatcher.group(GROUP_DECORATORS_UPTIME_UNIT));
             return event;
         } else {
             getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
@@ -503,9 +504,13 @@ private void setDateStampIfPresent(AbstractGCEvent<?> event, String dateStampAsS
         }
     }
 
-    private void setTimeStampIfPresent(AbstractGCEvent<?> event, String timeStampAsString) {
+    private void setTimeStampIfPresent(AbstractGCEvent<?> event, String timeStampAsString, String timeUnit) {
         if (timeStampAsString != null && timeStampAsString.length() > 0) {
-            event.setTimestamp(NumberParser.parseDouble(timeStampAsString));
+            double timestamp = NumberParser.parseDouble(timeStampAsString);
+            if ("ms".equals(timeUnit)) {
+                timestamp = timestamp / 1000;
+            }
+            event.setTimestamp(timestamp);
         }
     }
 

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java
@@ -668,6 +668,7 @@ public String toString() {
         public static final Type UJL_G1_SURVIVOR = new Type("Survivor regions", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_REGION);
         public static final Type UJL_G1_OLD = new Type("Old regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
         public static final Type UJL_G1_HUMongous = new Type("Humongous regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
+        public static final Type UJL_G1_ARCHIVE = new Type("Archive regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
 
         public static final Type UJL_G1_PHASE_PRE_EVACUATE_COLLECTION_SET = new Type("Pre Evacuate Collection Set", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);
         public static final Type UJL_G1_PHASE_EVACUATE_COLLECTION_SET = new Type("Evacuate Collection Set", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/view/AboutDialog.java b/src/main/java/com/tagtraum/perf/gcviewer/view/AboutDialog.java
@@ -52,6 +52,7 @@ public class AboutDialog extends ScreenCenteredDialog implements ActionListener
         "Mary Sunitha Joseph",
         "Johan Kaving",
         "Maciej Kwiecien",
+        "Dennis Lawler",
         "Yanqi Li",
         "Henry Lin",
         "James Livingston",

diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java
@@ -43,6 +43,22 @@ public void testDefaultsPauseYoungNormal() throws Exception {
         assertThat("pause", model.get(0).getPause(), closeTo(0.012615, 0.00000001));
     }
 
+    @Test
+    public void testNewUptimestamp() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("byteArray");
+        gcResource.getLogger().addHandler(handler);
+        InputStream in = new ByteArrayInputStream(
+                ("[113ms][info][gc] GC(4) Pause Young (Normal) (G1 Evacuation Pause) 70M->70M(128M) 12.615ms")
+                        .getBytes());
+
+        DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
+        GCModel model = reader.read();
+
+        assertThat(model.getEvents().next().getTimestamp(), is(0.113));
+    }
+
     @Test
     public void testDefaultsPauseYoungConcurrentStart() throws Exception {
         TestLogHandler handler = new TestLogHandler();

diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK12.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK12.java
@@ -0,0 +1,53 @@
+package com.tagtraum.perf.gcviewer.imp;
+
+import static org.hamcrest.Matchers.closeTo;
+import static org.hamcrest.Matchers.containsString;
+import static org.hamcrest.Matchers.is;
+import static org.junit.Assert.assertThat;
+
+import java.io.ByteArrayInputStream;
+import java.io.InputStream;
+import java.util.logging.Level;
+
+import com.tagtraum.perf.gcviewer.model.GCModel;
+import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.GcResourceFile;
+import org.junit.Test;
+
+/**
+ * Test unified java logging G1 algorithm in OpenJDK 12
+ */
+public class TestDataReaderUJLG1JDK12 {
+    @Test
+    public void testG1ArchiveRegions() throws Exception {
+        TestLogHandler handler = new TestLogHandler();
+        handler.setLevel(Level.WARNING);
+        GCResource gcResource = new GcResourceFile("byteArray");
+        gcResource.getLogger().addHandler(handler);
+        InputStream in = new ByteArrayInputStream(
+                ("[2019-09-16T20:06:59.836+0000][0.153s][info][gc,start     ] GC(0) Pause Young (Normal) (G1 Evacuation Pause)\n" +
+                        "[2019-09-16T20:06:59.836+0000][0.153s][info][gc,task      ] GC(0) Using 2 workers of 2 for evacuation\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,phases    ] GC(0)   Pre Evacuate Collection Set: 0.0ms\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,phases    ] GC(0)   Evacuate Collection Set: 3.1ms\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,phases    ] GC(0)   Post Evacuate Collection Set: 0.7ms\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,phases    ] GC(0)   Other: 0.4ms\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,heap      ] GC(0) Eden regions: 7->0(4)\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,heap      ] GC(0) Survivor regions: 0->1(1)\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,heap      ] GC(0) Old regions: 0->6\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,heap      ] GC(0) Archive regions: 2->2\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,heap      ] GC(0) Humongous regions: 0->0\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,metaspace ] GC(0) Metaspace: 189K->189K(1056768K)\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc           ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 7M->7M(34M) 4.379ms\n" +
+                        "[2019-09-16T20:06:59.840+0000][0.157s][info][gc,cpu       ] GC(0) User=0.00s Sys=0.01s Real=0.01s\n")
+                        .getBytes());
+
+        DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
+        GCModel model = reader.read();
+
+        assertThat("number of warnings", handler.getCount(), is(0));
+        assertThat("number of events", model.size(), is(1));
+        assertThat("pause", model.get(0).getPause(), closeTo(0.004379, 0.0000001));
+        assertThat("name", model.get(0).getTypeAsString(), containsString("Archive regions"));
+    }
+
+}