From 3560b3e806ea71d1e0c0bb2a418f63bdbf704ccf Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jaros=C5=82aw=20Pa=C5=82ka?= <jaroslaw.palka@symentis.pl>
Date: Fri, 26 Oct 2018 12:38:35 +0200
Subject: [PATCH 1/6] initial refactoring, using to stage pass, first we
 extract log event decorators and then we parse message

---
 .../imp/DataReaderUnifiedJvmLogging.java      | 106 ++++++++++++++----
 .../imp/TestDataReaderUJLSafepoint.java       |  95 ++++++++++++++++
 .../sample-ujl-safepoint-defaults.txt         |  73 ++++++++++++
 3 files changed, 254 insertions(+), 20 deletions(-)
 create mode 100644 src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
 create mode 100644 src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
index 48f2e0ec..b9a8fe1a 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -21,6 +21,7 @@
 import com.tagtraum.perf.gcviewer.model.GCEventUJL;
 import com.tagtraum.perf.gcviewer.model.GCModel;
 import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.VmOperationEvent;
 import com.tagtraum.perf.gcviewer.util.DateHelper;
 import com.tagtraum.perf.gcviewer.util.NumberParser;
 
@@ -47,6 +48,24 @@
  */
 public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
 
+    class LogEvent {
+
+        final String time;
+	final String uptime;
+	final String level;
+	final String tags;
+	final String message;
+
+	LogEvent(String time, String uptime, String level, String tags, String message) {
+	    this.time = time;
+	    this.uptime = uptime;
+	    this.level = level;
+	    this.tags = tags;
+	    this.message = message;
+        }
+
+    }
+
     // matches the whole line and extracts decorators from it (decorators always appear between [] and are independent of the gc algorithm being logged)
     // Input: [0.693s][info][gc           ] GC(0) Pause Init Mark 1.070ms
     // Group 1 / time: <empty> (optional group, no full timestamp present)
@@ -57,13 +76,18 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
     // Group 6 / tail: Pause Init Mark 1.070ms
     // 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>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
-    );
+    
+    private static final Pattern PATTERN_DECORATORS = Pattern.compile("^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](?<message>.*)");
+
+    private static final Pattern PATTERN_GC_MESSAGE = Pattern.compile("^GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)");
+
+    private static final Pattern PATTERN_APPLICATION_STOPPED = Pattern.compile("^Total time for which application threads were stopped: (?<applicationstopped>[0-9]+,[0-9]+) seconds, Stopping threads took: (?<threadsstopping>[0-9]+,[0-9]+) seconds$");
+    
     private static final String GROUP_DECORATORS_TIME = "time";
     private static final String GROUP_DECORATORS_UPTIME = "uptime";
     private static final String GROUP_DECORATORS_LEVEL = "level";
     private static final String GROUP_DECORATORS_TAGS = "tags";
+    private static final String GROUP_DECORATORS_MESSAGE = "message";
     private static final String GROUP_DECORATORS_GC_NUMBER = "gcnumber";
     private static final String GROUP_DECORATORS_GC_TYPE = "type";
     private static final String GROUP_DECORATORS_TAIL = "tail";
@@ -124,13 +148,14 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
     private static final String TAG_GC_METASPACE = "gc,metaspace";
 
     /** 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]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
+    private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[safepoint]","[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
     /** 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", "gc,heap,coops", "gc,heap,exit");
     /** 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", "Heap region size");
 
 
+
     protected DataReaderUnifiedJvmLogging(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
         super(gcResource, in);
     }
@@ -162,25 +187,65 @@ public GCModel read() throws IOException {
 
     private ParseContext parseEvent(ParseContext context) {
         AbstractGCEvent<?> event = null;
-
-        Matcher decoratorsMatcher = PATTERN_DECORATORS.matcher(context.getLine());
-        try {
-            event = createGcEventWithStandardDecorators(decoratorsMatcher, context.getLine());
-            if (event != null) {
-                String tags = decoratorsMatcher.group(GROUP_DECORATORS_TAGS);
-                String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
-                event = handleTail(context, event, tags, tail);
+        String line = context.getLine();
+        
+	// extract log decorators (like time stamp, up time, level, tags and message)
+        Matcher eventDecoratorsMatcher = PATTERN_DECORATORS.matcher(line );
+        LogEvent logEvent = createLogEvent(eventDecoratorsMatcher);
+        
+        if (logEvent==null) {
+            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
+        } else {
+            String message = logEvent.message;
+            Matcher decoratorsMatcher = PATTERN_GC_MESSAGE.matcher(message);
+            try {
+                event = createGcEventWithStandardDecorators(logEvent, decoratorsMatcher, context.getLine());
+                if (event != null) {
+                    String tags = logEvent.tags;
+                    String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
+                    event = handleTail(context, event, tags, tail);
+                } else {
+                    Matcher applicationStoppedMAtcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
+                    event = parseSafepointEvent(logEvent,applicationStoppedMAtcher,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(), context.getLine()));
             }
-        } 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(), context.getLine()));
         }
+        
 
         context.setCurrentEvent(event);
         return context;
     }
 
+    private AbstractGCEvent<?> parseSafepointEvent(LogEvent logEvent, Matcher applicationStoppedMatcher, String line) {
+        if (applicationStoppedMatcher.matches()) {
+            AbstractGCEvent<?> event = new VmOperationEvent();
+            event.setType(Type.APPLICATION_STOPPED_TIME);
+            setPause(event, applicationStoppedMatcher.group("applicationstopped"));
+            setDateStampIfPresent(event, logEvent.time);
+            setTimeStampIfPresent(event, logEvent.uptime);
+            return event;
+        } else {
+            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
+            return null;
+        }
+    }
+
+    private LogEvent createLogEvent(Matcher eventDecoratorsMatcher) {
+        if(eventDecoratorsMatcher.matches()) {
+            String time = eventDecoratorsMatcher.group( GROUP_DECORATORS_TIME );
+            String uptime = eventDecoratorsMatcher.group( GROUP_DECORATORS_UPTIME );            
+            String level = eventDecoratorsMatcher.group( GROUP_DECORATORS_LEVEL );
+            String tags = eventDecoratorsMatcher.group( GROUP_DECORATORS_TAGS );
+            String message = eventDecoratorsMatcher.group( GROUP_DECORATORS_MESSAGE );
+            return new LogEvent(time,uptime,level,tags,message);
+        }
+        return null;
+    }
+
     private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> event, String tags, String tail) {
         AbstractGCEvent<?> returnEvent = event;
         switch (tags) {
@@ -321,19 +386,20 @@ private void parseGcRegionTail(ParseContext context, AbstractGCEvent<?> event, S
     /**
      * Returns an instance of AbstractGcEvent (GCEvent or ConcurrentGcEvent) with all decorators present filled in
      * or <code>null</code> if the line could not be matched.
+     * @param logEvent 
      * @param decoratorsMatcher matcher for decorators to be used for GcEvent creation
      * @param line current line to be parsed
      * @return Instance of <code>AbstractGcEvent</code> or <code>null</code> if the line could not be matched.
      */
-    private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decoratorsMatcher, String line) throws UnknownGcTypeException {
-        if (decoratorsMatcher.find()) {
+    private AbstractGCEvent<?> createGcEventWithStandardDecorators(LogEvent logEvent, Matcher decoratorsMatcher, String line) throws UnknownGcTypeException {
+        if (decoratorsMatcher.matches()) {
             AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(decoratorsMatcher.group(GROUP_DECORATORS_GC_TYPE));
 
             AbstractGCEvent<?> event = type.getConcurrency().equals(Concurrency.CONCURRENT) ? new ConcurrentGCEvent() : new GCEventUJL();
             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));
+            setDateStampIfPresent(event, logEvent.time);
+            setTimeStampIfPresent(event, logEvent.uptime);
             return event;
         } else {
             getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
new file mode 100644
index 00000000..b3937bad
--- /dev/null
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
@@ -0,0 +1,95 @@
+package com.tagtraum.perf.gcviewer.imp;
+
+import com.tagtraum.perf.gcviewer.UnittestHelper;
+import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Generation;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
+import com.tagtraum.perf.gcviewer.model.GCModel;
+import org.junit.Ignore;
+import org.junit.Test;
+
+import java.io.IOException;
+
+import static org.hamcrest.Matchers.is;
+import static org.junit.Assert.assertThat;
+
+/**
+ * Tests unified jvm logging parser for safepoint events.
+ */
+public class TestDataReaderUJLSafepoint {
+    private GCModel getGCModelFromLogFile(String fileName) throws IOException {
+        return UnittestHelper.getGCModelFromLogFile(fileName, FOLDER.OPENJDK_UJL, DataReaderUnifiedJvmLogging.class);
+    }
+
+    @Test
+    public void parseGcDefaults() throws Exception {
+        GCModel model = getGCModelFromLogFile("sample-ujl-safepoint-defaults.txt");
+        assertThat("size", model.size(), is(16));
+        assertThat("amount of gc event types", model.getGcEventPauses().size(), is(3));
+        assertThat("amount of gc events", model.getGCPause().getN(), is(5));
+        assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(1));
+        assertThat("amount of full gc events", model.getFullGCPause().getN(), is(1));
+        assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
+
+
+        UnittestHelper.testMemoryPauseEvent(model.get(0),
+                "young",
+                Type.UJL_PAUSE_YOUNG,
+                0.008822,
+                1024 * 41, 1024 * 38,1024 * 150,
+                Generation.YOUNG,
+                false);
+
+        UnittestHelper.testMemoryPauseEvent(model.get(0),
+                "young",
+                Type.UJL_PAUSE_YOUNG,
+                0.008822,
+                1024 * 41, 1024 * 38,1024 * 150,
+                Generation.YOUNG,
+                false);
+
+        AbstractGCEvent<?> event2 = model.get(1);
+        UnittestHelper.testMemoryPauseEvent(event2,
+                "initialMarkEvent",
+                Type.UJL_PAUSE_INITIAL_MARK,
+                0.000136,
+                1024 * 61, 1024 * 61,1024 * 150,
+                Generation.TENURED,
+                false);
+        assertThat("isInitialMark", event2.isInitialMark(), is(true));
+
+        AbstractGCEvent<?> event3 = model.get(10);
+        UnittestHelper.testMemoryPauseEvent(event3,
+                "RemarkEvent",
+                Type.UJL_PAUSE_REMARK,
+                0.000859,
+                1024 * 110, 1024 * 110,1024 * 150,
+                Generation.TENURED,
+                false);
+        assertThat("isRemark", event3.isRemark(), is(true));
+
+        AbstractGCEvent<?> event4 = model.get(15);
+        UnittestHelper.testMemoryPauseEvent(event4,
+                "full",
+                Type.UJL_PAUSE_FULL,
+                0.009775,
+                1024 * 125, 1024 * 31, 1024 * 150,
+                Generation.ALL,
+                true);
+
+        AbstractGCEvent<?> concurrentMarkBeginEvent = model.get(2);
+        assertThat("event is not start of concurrent collection", concurrentMarkBeginEvent.isConcurrentCollectionStart(), is(false));
+
+        AbstractGCEvent<?> concurrentMarkWithPauseEvent = model.get(3);
+        assertThat("event is start of concurrent collection", concurrentMarkWithPauseEvent.isConcurrentCollectionStart(), is(true));
+
+        AbstractGCEvent<?> concurrentResetBeginEvent = model.get(13);
+        assertThat("event is not end of concurrent collection", concurrentResetBeginEvent.isConcurrentCollectionEnd(), is(false));
+
+        AbstractGCEvent<?> concurrentResetEvent = model.get(14);
+        assertThat("event is end of concurrent collection", concurrentResetEvent.isConcurrentCollectionEnd(), is(true));
+
+    }
+
+}
diff --git a/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt
new file mode 100644
index 00000000..9b880040
--- /dev/null
+++ b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt
@@ -0,0 +1,73 @@
+[2018-10-10T17:09:33.823+0200][0.022s][info][gc] Using G1
+[2018-10-10T17:09:33.877+0200][0,077s][info][safepoint] Total time for which application threads were stopped: 0,0000235 seconds, Stopping threads took: 0,0000015 seconds
+[2018-10-10T17:09:33.889+0200][0,089s][info][safepoint] Application time: 0,0118190 seconds
+[2018-10-10T17:09:33.889+0200][0,089s][info][safepoint] Total time for which application threads were stopped: 0,0000495 seconds, Stopping threads took: 0,0000022 seconds
+[2018-10-10T17:09:33.891+0200][0,091s][info][safepoint] Application time: 0,0020922 seconds
+[2018-10-10T17:09:33.891+0200][0,091s][info][safepoint] Total time for which application threads were stopped: 0,0000211 seconds, Stopping threads took: 0,0000022 seconds
+[2018-10-10T17:09:33.892+0200][0,092s][info][safepoint] Application time: 0,0008629 seconds
+[2018-10-10T17:09:33.892+0200][0,092s][info][safepoint] Total time for which application threads were stopped: 0,0001209 seconds, Stopping threads took: 0,0001051 seconds
+[2018-10-10T17:09:33.948+0200][0,147s][info][safepoint] Application time: 0,0550227 seconds
+[2018-10-10T17:09:33.952+0200][0,151s][info][gc       ] GC(0) Pause Young (G1 Evacuation Pause) 24M->4M(250M) 3,496ms
+[2018-10-10T17:09:33.952+0200][0,151s][info][safepoint] Total time for which application threads were stopped: 0,0036337 seconds, Stopping threads took: 0,0000452 seconds
+[2018-10-10T17:09:33.958+0200][0,157s][info][safepoint] Application time: 0,0062028 seconds
+[2018-10-10T17:09:33.958+0200][0,157s][info][safepoint] Total time for which application threads were stopped: 0,0001133 seconds, Stopping threads took: 0,0000901 seconds
+[2018-10-10T17:09:33.958+0200][0,157s][info][safepoint] Application time: 0,0000222 seconds
+[2018-10-10T17:09:33.958+0200][0,158s][info][safepoint] Total time for which application threads were stopped: 0,0000353 seconds, Stopping threads took: 0,0000221 seconds
+[2018-10-10T17:09:33.966+0200][0,165s][info][safepoint] Application time: 0,0076620 seconds
+[2018-10-10T17:09:33.976+0200][0,176s][info][gc       ] GC(1) Pause Young (G1 Evacuation Pause) 151M->27M(250M) 10,363ms
+[2018-10-10T17:09:33.976+0200][0,176s][info][safepoint] Total time for which application threads were stopped: 0,0104689 seconds, Stopping threads took: 0,0000132 seconds
+[2018-10-10T17:09:33.978+0200][0,178s][info][safepoint] Application time: 0,0019993 seconds
+[2018-10-10T17:09:33.986+0200][0,185s][info][gc       ] GC(2) Pause Young (G1 Evacuation Pause) 74M->35M(250M) 7,049ms
+[2018-10-10T17:09:33.986+0200][0,185s][info][safepoint] Total time for which application threads were stopped: 0,0072140 seconds, Stopping threads took: 0,0000628 seconds
+[2018-10-10T17:09:33.991+0200][0,190s][info][safepoint] Application time: 0,0055349 seconds
+[2018-10-10T17:09:33.998+0200][0,197s][info][gc       ] GC(3) Pause Young (G1 Evacuation Pause) 149M->62M(250M) 6,491ms
+[2018-10-10T17:09:33.998+0200][0,197s][info][safepoint] Total time for which application threads were stopped: 0,0065900 seconds, Stopping threads took: 0,0000232 seconds
+[2018-10-10T17:09:34.001+0200][0,201s][info][safepoint] Application time: 0,0036755 seconds
+[2018-10-10T17:09:34.010+0200][0,209s][info][gc       ] GC(4) Pause Young (G1 Evacuation Pause) 152M->78M(528M) 8,153ms
+[2018-10-10T17:09:34.010+0200][0,209s][info][safepoint] Total time for which application threads were stopped: 0,0082641 seconds, Stopping threads took: 0,0000321 seconds
+[2018-10-10T17:09:34.050+0200][0,250s][info][safepoint] Application time: 0,0404274 seconds
+[2018-10-10T17:09:34.056+0200][0,255s][info][gc       ] GC(5) Pause Young (G1 Evacuation Pause) 364M->105M(528M) 5,773ms
+[2018-10-10T17:09:34.056+0200][0,255s][info][safepoint] Total time for which application threads were stopped: 0,0058898 seconds, Stopping threads took: 0,0000181 seconds
+[2018-10-10T17:09:34.067+0200][0,267s][info][safepoint] Application time: 0,0113116 seconds
+[2018-10-10T17:09:34.077+0200][0,277s][info][gc       ] GC(6) Pause Young (G1 Evacuation Pause) 378M->134M(528M) 9,668ms
+[2018-10-10T17:09:34.077+0200][0,277s][info][safepoint] Total time for which application threads were stopped: 0,0098035 seconds, Stopping threads took: 0,0000481 seconds
+[2018-10-10T17:09:34.087+0200][0,286s][info][safepoint] Application time: 0,0098326 seconds
+[2018-10-10T17:09:34.095+0200][0,294s][info][gc       ] GC(7) Pause Young (G1 Evacuation Pause) 355M->160M(528M) 7,487ms
+[2018-10-10T17:09:34.095+0200][0,294s][info][safepoint] Total time for which application threads were stopped: 0,0076406 seconds, Stopping threads took: 0,0000551 seconds
+[2018-10-10T17:09:34.108+0200][0,307s][info][safepoint] Application time: 0,0128880 seconds
+[2018-10-10T17:09:34.125+0200][0,324s][info][gc       ] GC(8) Pause Young (G1 Evacuation Pause) 346M->188M(1391M) 16,934ms
+[2018-10-10T17:09:34.125+0200][0,324s][info][safepoint] Total time for which application threads were stopped: 0,0170773 seconds, Stopping threads took: 0,0000110 seconds
+[2018-10-10T17:09:34.199+0200][0,398s][info][safepoint] Application time: 0,0740680 seconds
+[2018-10-10T17:09:34.211+0200][0,410s][info][gc       ] GC(9) Pause Young (G1 Evacuation Pause) 820M->260M(1391M) 11,688ms
+[2018-10-10T17:09:34.211+0200][0,410s][info][safepoint] Total time for which application threads were stopped: 0,0118661 seconds, Stopping threads took: 0,0000682 seconds
+[2018-10-10T17:09:34.247+0200][0,446s][info][safepoint] Application time: 0,0357840 seconds
+[2018-10-10T17:09:34.265+0200][0,465s][info][gc       ] GC(10) Pause Young (G1 Evacuation Pause) 976M->270M(1391M) 18,726ms
+[2018-10-10T17:09:34.265+0200][0,465s][info][safepoint] Total time for which application threads were stopped: 0,0188810 seconds, Stopping threads took: 0,0000239 seconds
+[2018-10-10T17:09:34.297+0200][0,496s][info][safepoint] Application time: 0,0310386 seconds
+[2018-10-10T17:09:34.311+0200][0,511s][info][gc       ] GC(11) Pause Young (G1 Evacuation Pause) 990M->314M(1391M) 14,837ms
+[2018-10-10T17:09:34.312+0200][0,511s][info][safepoint] Total time for which application threads were stopped: 0,0149630 seconds, Stopping threads took: 0,0000093 seconds
+[2018-10-10T17:09:34.340+0200][0,539s][info][safepoint] Application time: 0,0282094 seconds
+[2018-10-10T17:09:34.372+0200][0,571s][info][gc       ] GC(12) Pause Young (G1 Evacuation Pause) 984M->419M(2428M) 31,622ms
+[2018-10-10T17:09:34.372+0200][0,571s][info][safepoint] Total time for which application threads were stopped: 0,0317558 seconds, Stopping threads took: 0,0000101 seconds
+[2018-10-10T17:09:34.528+0200][0,727s][info][safepoint] Application time: 0,1560104 seconds
+[2018-10-10T17:09:34.548+0200][0,748s][info][gc       ] GC(13) Pause Young (G1 Evacuation Pause) 1778M->473M(2428M) 20,424ms
+[2018-10-10T17:09:34.548+0200][0,748s][info][safepoint] Total time for which application threads were stopped: 0,0206292 seconds, Stopping threads took: 0,0000112 seconds
+[2018-10-10T17:09:34.604+0200][0,804s][info][safepoint] Application time: 0,0559395 seconds
+[2018-10-10T17:09:34.637+0200][0,837s][info][gc       ] GC(14) Pause Young (G1 Evacuation Pause) 1769M->537M(2428M) 32,996ms
+[2018-10-10T17:09:34.637+0200][0,837s][info][safepoint] Total time for which application threads were stopped: 0,0331996 seconds, Stopping threads took: 0,0000114 seconds
+[2018-10-10T17:09:34.695+0200][0,895s][info][safepoint] Application time: 0,0580040 seconds
+[2018-10-10T17:09:34.729+0200][0,928s][info][gc       ] GC(15) Pause Young (G1 Evacuation Pause) 1746M->590M(2428M) 33,492ms
+[2018-10-10T17:09:34.729+0200][0,929s][info][safepoint] Total time for which application threads were stopped: 0,0336745 seconds, Stopping threads took: 0,0000104 seconds
+[2018-10-10T17:09:34.781+0200][0,981s][info][safepoint] Application time: 0,0519908 seconds
+[2018-10-10T17:09:34.817+0200][1,017s][info][gc       ] GC(16) Pause Young (G1 Evacuation Pause) 1749M->626M(3050M) 35,972ms
+[2018-10-10T17:09:34.817+0200][1,017s][info][safepoint] Total time for which application threads were stopped: 0,0362033 seconds, Stopping threads took: 0,0000112 seconds
+[2018-10-10T17:09:34.933+0200][1,132s][info][safepoint] Application time: 0,1150617 seconds
+[2018-10-10T17:09:34.961+0200][1,161s][info][gc       ] GC(17) Pause Young (G1 Evacuation Pause) 2066M->675M(3050M) 28,515ms
+[2018-10-10T17:09:34.961+0200][1,161s][info][safepoint] Total time for which application threads were stopped: 0,0287366 seconds, Stopping threads took: 0,0000249 seconds
+[2018-10-10T17:09:35.030+0200][1,229s][info][safepoint] Application time: 0,0688478 seconds
+[2018-10-10T17:09:35.068+0200][1,267s][info][gc       ] GC(18) Pause Young (G1 Evacuation Pause) 2124M->730M(3050M) 37,778ms
+[2018-10-10T17:09:35.068+0200][1,267s][info][safepoint] Total time for which application threads were stopped: 0,0379313 seconds, Stopping threads took: 0,0000207 seconds
+[2018-10-10T17:09:35.126+0200][1,326s][info][safepoint] Application time: 0,0583244 seconds
+[2018-10-10T17:09:35.158+0200][1,357s][info][gc       ] GC(19) Pause Young (G1 Evacuation Pause) 2103M->778M(3050M) 31,486ms
+[2018-10-10T17:09:35.158+0200][1,357s][info][safepoint] Total time for which application threads were stopped: 0,0316063 seconds, Stopping threads took: 0,0000080 seconds
+[2018-10-10T17:09:35.191+0200][1,390s][info][safepoint] Application time: 0,0326633 seconds

From 2eab1e8b7f6918364bba847c3773cd262f58e494 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jaros=C5=82aw=20Pa=C5=82ka?= <jaroslaw.palka@symentis.pl>
Date: Mon, 29 Oct 2018 12:32:32 +0100
Subject: [PATCH 2/6] minor refactoring, code should be more readable now

---
 .../imp/DataReaderUnifiedJvmLogging.java      | 51 ++++++-----
 .../imp/TestDataReaderUJLSafepoint.java       | 86 +++++--------------
 2 files changed, 46 insertions(+), 91 deletions(-)

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
index b9a8fe1a..3dec72b7 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -77,11 +77,14 @@ class LogEvent {
     // 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
     
+    // matches log decorators (like time stamp, up time, level, tags and message)
     private static final Pattern PATTERN_DECORATORS = Pattern.compile("^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](?<message>.*)");
 
+    // matches gc event
     private static final Pattern PATTERN_GC_MESSAGE = Pattern.compile("^GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)");
 
-    private static final Pattern PATTERN_APPLICATION_STOPPED = Pattern.compile("^Total time for which application threads were stopped: (?<applicationstopped>[0-9]+,[0-9]+) seconds, Stopping threads took: (?<threadsstopping>[0-9]+,[0-9]+) seconds$");
+    // matches application stopped time (entries with [safepoint] tag
+    private static final Pattern PATTERN_APPLICATION_STOPPED = Pattern.compile("Total time for which application threads were stopped: (?<applicationstopped>[0-9]+,[0-9]+) seconds, Stopping threads took: (?<threadsstopping>[0-9]+,[0-9]+) seconds");
     
     private static final String GROUP_DECORATORS_TIME = "time";
     private static final String GROUP_DECORATORS_UPTIME = "uptime";
@@ -150,7 +153,7 @@ class LogEvent {
     /** 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]", "[safepoint]","[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
     /** 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", "gc,heap,coops", "gc,heap,exit");
+    private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", "[trace", "gc,heap,coops", "gc,heap,exit", "Application time:");
     /** 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", "Heap region size");
 
@@ -191,23 +194,20 @@ private ParseContext parseEvent(ParseContext context) {
         
 	// extract log decorators (like time stamp, up time, level, tags and message)
         Matcher eventDecoratorsMatcher = PATTERN_DECORATORS.matcher(line );
-        LogEvent logEvent = createLogEvent(eventDecoratorsMatcher);
+        LogEvent logEvent = parseLogEvent(eventDecoratorsMatcher);
         
         if (logEvent==null) {
             getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
         } else {
             String message = logEvent.message;
-            Matcher decoratorsMatcher = PATTERN_GC_MESSAGE.matcher(message);
             try {
-                event = createGcEventWithStandardDecorators(logEvent, decoratorsMatcher, context.getLine());
-                if (event != null) {
-                    String tags = logEvent.tags;
-                    String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
-                    event = handleTail(context, event, tags, tail);
-                } else {
-                    Matcher applicationStoppedMAtcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
-                    event = parseSafepointEvent(logEvent,applicationStoppedMAtcher,line);
-                }
+        	if("safepoint".equals(logEvent.tags)) {
+        	    Matcher applicationStoppedMatcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
+        	    event = parseSafepointEvent(context, logEvent, applicationStoppedMatcher);        	    
+        	} else {
+        	    Matcher gcMatcher = PATTERN_GC_MESSAGE.matcher(message);
+                    event = createGcEvent(context, logEvent, gcMatcher);        	    
+        	}
             } catch (UnknownGcTypeException | NumberFormatException e) {
                 // prevent incomplete event from being added to the GCModel
                 event = null;
@@ -220,21 +220,19 @@ private ParseContext parseEvent(ParseContext context) {
         return context;
     }
 
-    private AbstractGCEvent<?> parseSafepointEvent(LogEvent logEvent, Matcher applicationStoppedMatcher, String line) {
-        if (applicationStoppedMatcher.matches()) {
+    private AbstractGCEvent<?> parseSafepointEvent(ParseContext context, LogEvent logEvent, Matcher applicationStoppedMatcher) { 
+	if (applicationStoppedMatcher.find()) {
             AbstractGCEvent<?> event = new VmOperationEvent();
             event.setType(Type.APPLICATION_STOPPED_TIME);
             setPause(event, applicationStoppedMatcher.group("applicationstopped"));
             setDateStampIfPresent(event, logEvent.time);
             setTimeStampIfPresent(event, logEvent.uptime);
             return event;
-        } else {
-            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
-            return null;
-        }
+        } 
+	return null;
     }
 
-    private LogEvent createLogEvent(Matcher eventDecoratorsMatcher) {
+    private LogEvent parseLogEvent(Matcher eventDecoratorsMatcher) {
         if(eventDecoratorsMatcher.matches()) {
             String time = eventDecoratorsMatcher.group( GROUP_DECORATORS_TIME );
             String uptime = eventDecoratorsMatcher.group( GROUP_DECORATORS_UPTIME );            
@@ -391,7 +389,7 @@ private void parseGcRegionTail(ParseContext context, AbstractGCEvent<?> event, S
      * @param line current line to be parsed
      * @return Instance of <code>AbstractGcEvent</code> or <code>null</code> if the line could not be matched.
      */
-    private AbstractGCEvent<?> createGcEventWithStandardDecorators(LogEvent logEvent, Matcher decoratorsMatcher, String line) throws UnknownGcTypeException {
+    private AbstractGCEvent<?> createGcEvent(ParseContext context, LogEvent logEvent, Matcher decoratorsMatcher) throws UnknownGcTypeException {
         if (decoratorsMatcher.matches()) {
             AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(decoratorsMatcher.group(GROUP_DECORATORS_GC_TYPE));
 
@@ -400,14 +398,15 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(LogEvent logEvent
             event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
             setDateStampIfPresent(event, logEvent.time);
             setTimeStampIfPresent(event, logEvent.uptime);
+            String tags = logEvent.tags;
+            String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
+            event = handleTail(context, event, tags, tail);
             return event;
-        } else {
-            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
-            return null;
         }
+        return null;
     }
 
-    private void setPause(AbstractGCEvent event, String pauseAsString) {
+    private void setPause(AbstractGCEvent<?> event, String pauseAsString) {
         // TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
         if (pauseAsString != null && pauseAsString.length() > 0) {
             event.setPause(NumberParser.parseDouble(pauseAsString) / 1000);
@@ -418,7 +417,7 @@ private boolean hasMemory(AbstractGCEvent<?> event) {
         return event.getTotal() > 0;
     }
 
-    private void setMemory(AbstractGCEvent event, Matcher matcher) {
+    private void setMemory(AbstractGCEvent<?> event, Matcher matcher) {
         // TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
         event.setPreUsed(getDataReaderTools().getMemoryInKiloByte(
                 Integer.parseInt(matcher.group(GROUP_MEMORY_BEFORE)), matcher.group(GROUP_MEMORY_BEFORE_UNIT).charAt(0), matcher.group(GROUP_MEMORY)));
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
index b3937bad..4ebcb457 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
@@ -3,13 +3,13 @@
 import com.tagtraum.perf.gcviewer.UnittestHelper;
 import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
 import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
-import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Generation;
-import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
 import com.tagtraum.perf.gcviewer.model.GCModel;
-import org.junit.Ignore;
 import org.junit.Test;
 
 import java.io.IOException;
+import java.util.ArrayList;
+import java.util.Iterator;
+import java.util.List;
 
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertThat;
@@ -18,6 +18,7 @@
  * Tests unified jvm logging parser for safepoint events.
  */
 public class TestDataReaderUJLSafepoint {
+
     private GCModel getGCModelFromLogFile(String fileName) throws IOException {
         return UnittestHelper.getGCModelFromLogFile(fileName, FOLDER.OPENJDK_UJL, DataReaderUnifiedJvmLogging.class);
     }
@@ -25,71 +26,26 @@ private GCModel getGCModelFromLogFile(String fileName) throws IOException {
     @Test
     public void parseGcDefaults() throws Exception {
         GCModel model = getGCModelFromLogFile("sample-ujl-safepoint-defaults.txt");
-        assertThat("size", model.size(), is(16));
-        assertThat("amount of gc event types", model.getGcEventPauses().size(), is(3));
-        assertThat("amount of gc events", model.getGCPause().getN(), is(5));
-        assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(1));
-        assertThat("amount of full gc events", model.getFullGCPause().getN(), is(1));
-        assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
-
-
-        UnittestHelper.testMemoryPauseEvent(model.get(0),
-                "young",
-                Type.UJL_PAUSE_YOUNG,
-                0.008822,
-                1024 * 41, 1024 * 38,1024 * 150,
-                Generation.YOUNG,
-                false);
-
-        UnittestHelper.testMemoryPauseEvent(model.get(0),
-                "young",
-                Type.UJL_PAUSE_YOUNG,
-                0.008822,
-                1024 * 41, 1024 * 38,1024 * 150,
-                Generation.YOUNG,
-                false);
-
-        AbstractGCEvent<?> event2 = model.get(1);
-        UnittestHelper.testMemoryPauseEvent(event2,
-                "initialMarkEvent",
-                Type.UJL_PAUSE_INITIAL_MARK,
-                0.000136,
-                1024 * 61, 1024 * 61,1024 * 150,
-                Generation.TENURED,
-                false);
-        assertThat("isInitialMark", event2.isInitialMark(), is(true));
+        assertThat("size", model.size(), is(46));
+        assertThat("amount of gc event types", model.getGcEventPauses().size(), is(1));
+        assertThat("amount of gc events", model.getGCPause().getN(), is(20));
+        assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(0));
+        assertThat("amount of full gc events", model.getFullGCPause().getN(), is(0));
+        assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));
 
-        AbstractGCEvent<?> event3 = model.get(10);
-        UnittestHelper.testMemoryPauseEvent(event3,
-                "RemarkEvent",
-                Type.UJL_PAUSE_REMARK,
-                0.000859,
-                1024 * 110, 1024 * 110,1024 * 150,
-                Generation.TENURED,
-                false);
-        assertThat("isRemark", event3.isRemark(), is(true));
+        List<AbstractGCEvent<?>> vmOperationsEvents = toList(model.getVmOperationsEvents());
+	assertThat("amount of application stopped types", vmOperationsEvents.size(), is(26));
 
-        AbstractGCEvent<?> event4 = model.get(15);
-        UnittestHelper.testMemoryPauseEvent(event4,
-                "full",
-                Type.UJL_PAUSE_FULL,
-                0.009775,
-                1024 * 125, 1024 * 31, 1024 * 150,
-                Generation.ALL,
-                true);
-
-        AbstractGCEvent<?> concurrentMarkBeginEvent = model.get(2);
-        assertThat("event is not start of concurrent collection", concurrentMarkBeginEvent.isConcurrentCollectionStart(), is(false));
-
-        AbstractGCEvent<?> concurrentMarkWithPauseEvent = model.get(3);
-        assertThat("event is start of concurrent collection", concurrentMarkWithPauseEvent.isConcurrentCollectionStart(), is(true));
-
-        AbstractGCEvent<?> concurrentResetBeginEvent = model.get(13);
-        assertThat("event is not end of concurrent collection", concurrentResetBeginEvent.isConcurrentCollectionEnd(), is(false));
-
-        AbstractGCEvent<?> concurrentResetEvent = model.get(14);
-        assertThat("event is end of concurrent collection", concurrentResetEvent.isConcurrentCollectionEnd(), is(true));
 
+        AbstractGCEvent<?> event = model.get(0);
+        assertThat(event.getTypeAsString(),is("Total time for which application threads were stopped"));
+        assertThat(event.getPause(),is(0.0000000235));
+    }
+    
+    private static <T> List<T> toList(Iterator<T> iterator){
+	ArrayList<T> list = new ArrayList<>();
+	iterator.forEachRemaining(list::add);
+	return list;
     }
 
 }

From 772c33a4a4265562693e0385f060617fa559ae78 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jaros=C5=82aw=20Pa=C5=82ka?= <jaroslaw.palka@symentis.pl>
Date: Mon, 29 Oct 2018 13:08:06 +0100
Subject: [PATCH 3/6] fixed code style issues

---
 .../imp/DataReaderUnifiedJvmLogging.java      | 40 +++++++++----------
 1 file changed, 20 insertions(+), 20 deletions(-)

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
index 3dec72b7..a2f86c9d 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -48,24 +48,6 @@
  */
 public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
 
-    class LogEvent {
-
-        final String time;
-	final String uptime;
-	final String level;
-	final String tags;
-	final String message;
-
-	LogEvent(String time, String uptime, String level, String tags, String message) {
-	    this.time = time;
-	    this.uptime = uptime;
-	    this.level = level;
-	    this.tags = tags;
-	    this.message = message;
-        }
-
-    }
-
     // matches the whole line and extracts decorators from it (decorators always appear between [] and are independent of the gc algorithm being logged)
     // Input: [0.693s][info][gc           ] GC(0) Pause Init Mark 1.070ms
     // Group 1 / time: <empty> (optional group, no full timestamp present)
@@ -203,7 +185,7 @@ private ParseContext parseEvent(ParseContext context) {
             try {
         	if("safepoint".equals(logEvent.tags)) {
         	    Matcher applicationStoppedMatcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
-        	    event = parseSafepointEvent(context, logEvent, applicationStoppedMatcher);        	    
+        	    event = parseSafepointEvent(logEvent, applicationStoppedMatcher);        	    
         	} else {
         	    Matcher gcMatcher = PATTERN_GC_MESSAGE.matcher(message);
                     event = createGcEvent(context, logEvent, gcMatcher);        	    
@@ -220,7 +202,7 @@ private ParseContext parseEvent(ParseContext context) {
         return context;
     }
 
-    private AbstractGCEvent<?> parseSafepointEvent(ParseContext context, LogEvent logEvent, Matcher applicationStoppedMatcher) { 
+    private AbstractGCEvent<?> parseSafepointEvent(LogEvent logEvent, Matcher applicationStoppedMatcher) { 
 	if (applicationStoppedMatcher.find()) {
             AbstractGCEvent<?> event = new VmOperationEvent();
             event.setType(Type.APPLICATION_STOPPED_TIME);
@@ -522,5 +504,23 @@ public String toString() {
         }
 
     }
+    
+    class LogEvent {
+
+        private final String time;
+	private final String uptime;
+	private final String level;
+	private final String tags;
+	private final String message;
+
+	LogEvent(String time, String uptime, String level, String tags, String message) {
+	    this.time = time;
+	    this.uptime = uptime;
+	    this.level = level;
+	    this.tags = tags;
+	    this.message = message;
+        }
+
+    }
 
 }
\ No newline at end of file

From 0e2834b6485d8f9ef42d3e48f5f4aae4b1446bdf Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jaros=C5=82aw=20Pa=C5=82ka?= <jaroslaw.palka@symentis.pl>
Date: Fri, 26 Oct 2018 12:38:35 +0200
Subject: [PATCH 4/6] initial refactoring, using to stage pass, first we
 extract log event decorators and then we parse message

---
 .../imp/DataReaderUnifiedJvmLogging.java      | 106 ++++++++++++++----
 .../imp/TestDataReaderUJLSafepoint.java       |  95 ++++++++++++++++
 .../sample-ujl-safepoint-defaults.txt         |  73 ++++++++++++
 3 files changed, 254 insertions(+), 20 deletions(-)
 create mode 100644 src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
 create mode 100644 src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
index 48f2e0ec..b9a8fe1a 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -21,6 +21,7 @@
 import com.tagtraum.perf.gcviewer.model.GCEventUJL;
 import com.tagtraum.perf.gcviewer.model.GCModel;
 import com.tagtraum.perf.gcviewer.model.GCResource;
+import com.tagtraum.perf.gcviewer.model.VmOperationEvent;
 import com.tagtraum.perf.gcviewer.util.DateHelper;
 import com.tagtraum.perf.gcviewer.util.NumberParser;
 
@@ -47,6 +48,24 @@
  */
 public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
 
+    class LogEvent {
+
+        final String time;
+	final String uptime;
+	final String level;
+	final String tags;
+	final String message;
+
+	LogEvent(String time, String uptime, String level, String tags, String message) {
+	    this.time = time;
+	    this.uptime = uptime;
+	    this.level = level;
+	    this.tags = tags;
+	    this.message = message;
+        }
+
+    }
+
     // matches the whole line and extracts decorators from it (decorators always appear between [] and are independent of the gc algorithm being logged)
     // Input: [0.693s][info][gc           ] GC(0) Pause Init Mark 1.070ms
     // Group 1 / time: <empty> (optional group, no full timestamp present)
@@ -57,13 +76,18 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
     // Group 6 / tail: Pause Init Mark 1.070ms
     // 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>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
-    );
+    
+    private static final Pattern PATTERN_DECORATORS = Pattern.compile("^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](?<message>.*)");
+
+    private static final Pattern PATTERN_GC_MESSAGE = Pattern.compile("^GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)");
+
+    private static final Pattern PATTERN_APPLICATION_STOPPED = Pattern.compile("^Total time for which application threads were stopped: (?<applicationstopped>[0-9]+,[0-9]+) seconds, Stopping threads took: (?<threadsstopping>[0-9]+,[0-9]+) seconds$");
+    
     private static final String GROUP_DECORATORS_TIME = "time";
     private static final String GROUP_DECORATORS_UPTIME = "uptime";
     private static final String GROUP_DECORATORS_LEVEL = "level";
     private static final String GROUP_DECORATORS_TAGS = "tags";
+    private static final String GROUP_DECORATORS_MESSAGE = "message";
     private static final String GROUP_DECORATORS_GC_NUMBER = "gcnumber";
     private static final String GROUP_DECORATORS_GC_TYPE = "type";
     private static final String GROUP_DECORATORS_TAIL = "tail";
@@ -124,13 +148,14 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
     private static final String TAG_GC_METASPACE = "gc,metaspace";
 
     /** 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]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
+    private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[safepoint]","[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
     /** 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", "gc,heap,coops", "gc,heap,exit");
     /** 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", "Heap region size");
 
 
+
     protected DataReaderUnifiedJvmLogging(GCResource gcResource, InputStream in) throws UnsupportedEncodingException {
         super(gcResource, in);
     }
@@ -162,25 +187,65 @@ public GCModel read() throws IOException {
 
     private ParseContext parseEvent(ParseContext context) {
         AbstractGCEvent<?> event = null;
-
-        Matcher decoratorsMatcher = PATTERN_DECORATORS.matcher(context.getLine());
-        try {
-            event = createGcEventWithStandardDecorators(decoratorsMatcher, context.getLine());
-            if (event != null) {
-                String tags = decoratorsMatcher.group(GROUP_DECORATORS_TAGS);
-                String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
-                event = handleTail(context, event, tags, tail);
+        String line = context.getLine();
+        
+	// extract log decorators (like time stamp, up time, level, tags and message)
+        Matcher eventDecoratorsMatcher = PATTERN_DECORATORS.matcher(line );
+        LogEvent logEvent = createLogEvent(eventDecoratorsMatcher);
+        
+        if (logEvent==null) {
+            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
+        } else {
+            String message = logEvent.message;
+            Matcher decoratorsMatcher = PATTERN_GC_MESSAGE.matcher(message);
+            try {
+                event = createGcEventWithStandardDecorators(logEvent, decoratorsMatcher, context.getLine());
+                if (event != null) {
+                    String tags = logEvent.tags;
+                    String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
+                    event = handleTail(context, event, tags, tail);
+                } else {
+                    Matcher applicationStoppedMAtcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
+                    event = parseSafepointEvent(logEvent,applicationStoppedMAtcher,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(), context.getLine()));
             }
-        } 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(), context.getLine()));
         }
+        
 
         context.setCurrentEvent(event);
         return context;
     }
 
+    private AbstractGCEvent<?> parseSafepointEvent(LogEvent logEvent, Matcher applicationStoppedMatcher, String line) {
+        if (applicationStoppedMatcher.matches()) {
+            AbstractGCEvent<?> event = new VmOperationEvent();
+            event.setType(Type.APPLICATION_STOPPED_TIME);
+            setPause(event, applicationStoppedMatcher.group("applicationstopped"));
+            setDateStampIfPresent(event, logEvent.time);
+            setTimeStampIfPresent(event, logEvent.uptime);
+            return event;
+        } else {
+            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
+            return null;
+        }
+    }
+
+    private LogEvent createLogEvent(Matcher eventDecoratorsMatcher) {
+        if(eventDecoratorsMatcher.matches()) {
+            String time = eventDecoratorsMatcher.group( GROUP_DECORATORS_TIME );
+            String uptime = eventDecoratorsMatcher.group( GROUP_DECORATORS_UPTIME );            
+            String level = eventDecoratorsMatcher.group( GROUP_DECORATORS_LEVEL );
+            String tags = eventDecoratorsMatcher.group( GROUP_DECORATORS_TAGS );
+            String message = eventDecoratorsMatcher.group( GROUP_DECORATORS_MESSAGE );
+            return new LogEvent(time,uptime,level,tags,message);
+        }
+        return null;
+    }
+
     private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> event, String tags, String tail) {
         AbstractGCEvent<?> returnEvent = event;
         switch (tags) {
@@ -321,19 +386,20 @@ private void parseGcRegionTail(ParseContext context, AbstractGCEvent<?> event, S
     /**
      * Returns an instance of AbstractGcEvent (GCEvent or ConcurrentGcEvent) with all decorators present filled in
      * or <code>null</code> if the line could not be matched.
+     * @param logEvent 
      * @param decoratorsMatcher matcher for decorators to be used for GcEvent creation
      * @param line current line to be parsed
      * @return Instance of <code>AbstractGcEvent</code> or <code>null</code> if the line could not be matched.
      */
-    private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decoratorsMatcher, String line) throws UnknownGcTypeException {
-        if (decoratorsMatcher.find()) {
+    private AbstractGCEvent<?> createGcEventWithStandardDecorators(LogEvent logEvent, Matcher decoratorsMatcher, String line) throws UnknownGcTypeException {
+        if (decoratorsMatcher.matches()) {
             AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(decoratorsMatcher.group(GROUP_DECORATORS_GC_TYPE));
 
             AbstractGCEvent<?> event = type.getConcurrency().equals(Concurrency.CONCURRENT) ? new ConcurrentGCEvent() : new GCEventUJL();
             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));
+            setDateStampIfPresent(event, logEvent.time);
+            setTimeStampIfPresent(event, logEvent.uptime);
             return event;
         } else {
             getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
new file mode 100644
index 00000000..b3937bad
--- /dev/null
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
@@ -0,0 +1,95 @@
+package com.tagtraum.perf.gcviewer.imp;
+
+import com.tagtraum.perf.gcviewer.UnittestHelper;
+import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Generation;
+import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
+import com.tagtraum.perf.gcviewer.model.GCModel;
+import org.junit.Ignore;
+import org.junit.Test;
+
+import java.io.IOException;
+
+import static org.hamcrest.Matchers.is;
+import static org.junit.Assert.assertThat;
+
+/**
+ * Tests unified jvm logging parser for safepoint events.
+ */
+public class TestDataReaderUJLSafepoint {
+    private GCModel getGCModelFromLogFile(String fileName) throws IOException {
+        return UnittestHelper.getGCModelFromLogFile(fileName, FOLDER.OPENJDK_UJL, DataReaderUnifiedJvmLogging.class);
+    }
+
+    @Test
+    public void parseGcDefaults() throws Exception {
+        GCModel model = getGCModelFromLogFile("sample-ujl-safepoint-defaults.txt");
+        assertThat("size", model.size(), is(16));
+        assertThat("amount of gc event types", model.getGcEventPauses().size(), is(3));
+        assertThat("amount of gc events", model.getGCPause().getN(), is(5));
+        assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(1));
+        assertThat("amount of full gc events", model.getFullGCPause().getN(), is(1));
+        assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
+
+
+        UnittestHelper.testMemoryPauseEvent(model.get(0),
+                "young",
+                Type.UJL_PAUSE_YOUNG,
+                0.008822,
+                1024 * 41, 1024 * 38,1024 * 150,
+                Generation.YOUNG,
+                false);
+
+        UnittestHelper.testMemoryPauseEvent(model.get(0),
+                "young",
+                Type.UJL_PAUSE_YOUNG,
+                0.008822,
+                1024 * 41, 1024 * 38,1024 * 150,
+                Generation.YOUNG,
+                false);
+
+        AbstractGCEvent<?> event2 = model.get(1);
+        UnittestHelper.testMemoryPauseEvent(event2,
+                "initialMarkEvent",
+                Type.UJL_PAUSE_INITIAL_MARK,
+                0.000136,
+                1024 * 61, 1024 * 61,1024 * 150,
+                Generation.TENURED,
+                false);
+        assertThat("isInitialMark", event2.isInitialMark(), is(true));
+
+        AbstractGCEvent<?> event3 = model.get(10);
+        UnittestHelper.testMemoryPauseEvent(event3,
+                "RemarkEvent",
+                Type.UJL_PAUSE_REMARK,
+                0.000859,
+                1024 * 110, 1024 * 110,1024 * 150,
+                Generation.TENURED,
+                false);
+        assertThat("isRemark", event3.isRemark(), is(true));
+
+        AbstractGCEvent<?> event4 = model.get(15);
+        UnittestHelper.testMemoryPauseEvent(event4,
+                "full",
+                Type.UJL_PAUSE_FULL,
+                0.009775,
+                1024 * 125, 1024 * 31, 1024 * 150,
+                Generation.ALL,
+                true);
+
+        AbstractGCEvent<?> concurrentMarkBeginEvent = model.get(2);
+        assertThat("event is not start of concurrent collection", concurrentMarkBeginEvent.isConcurrentCollectionStart(), is(false));
+
+        AbstractGCEvent<?> concurrentMarkWithPauseEvent = model.get(3);
+        assertThat("event is start of concurrent collection", concurrentMarkWithPauseEvent.isConcurrentCollectionStart(), is(true));
+
+        AbstractGCEvent<?> concurrentResetBeginEvent = model.get(13);
+        assertThat("event is not end of concurrent collection", concurrentResetBeginEvent.isConcurrentCollectionEnd(), is(false));
+
+        AbstractGCEvent<?> concurrentResetEvent = model.get(14);
+        assertThat("event is end of concurrent collection", concurrentResetEvent.isConcurrentCollectionEnd(), is(true));
+
+    }
+
+}
diff --git a/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt
new file mode 100644
index 00000000..9b880040
--- /dev/null
+++ b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-safepoint-defaults.txt
@@ -0,0 +1,73 @@
+[2018-10-10T17:09:33.823+0200][0.022s][info][gc] Using G1
+[2018-10-10T17:09:33.877+0200][0,077s][info][safepoint] Total time for which application threads were stopped: 0,0000235 seconds, Stopping threads took: 0,0000015 seconds
+[2018-10-10T17:09:33.889+0200][0,089s][info][safepoint] Application time: 0,0118190 seconds
+[2018-10-10T17:09:33.889+0200][0,089s][info][safepoint] Total time for which application threads were stopped: 0,0000495 seconds, Stopping threads took: 0,0000022 seconds
+[2018-10-10T17:09:33.891+0200][0,091s][info][safepoint] Application time: 0,0020922 seconds
+[2018-10-10T17:09:33.891+0200][0,091s][info][safepoint] Total time for which application threads were stopped: 0,0000211 seconds, Stopping threads took: 0,0000022 seconds
+[2018-10-10T17:09:33.892+0200][0,092s][info][safepoint] Application time: 0,0008629 seconds
+[2018-10-10T17:09:33.892+0200][0,092s][info][safepoint] Total time for which application threads were stopped: 0,0001209 seconds, Stopping threads took: 0,0001051 seconds
+[2018-10-10T17:09:33.948+0200][0,147s][info][safepoint] Application time: 0,0550227 seconds
+[2018-10-10T17:09:33.952+0200][0,151s][info][gc       ] GC(0) Pause Young (G1 Evacuation Pause) 24M->4M(250M) 3,496ms
+[2018-10-10T17:09:33.952+0200][0,151s][info][safepoint] Total time for which application threads were stopped: 0,0036337 seconds, Stopping threads took: 0,0000452 seconds
+[2018-10-10T17:09:33.958+0200][0,157s][info][safepoint] Application time: 0,0062028 seconds
+[2018-10-10T17:09:33.958+0200][0,157s][info][safepoint] Total time for which application threads were stopped: 0,0001133 seconds, Stopping threads took: 0,0000901 seconds
+[2018-10-10T17:09:33.958+0200][0,157s][info][safepoint] Application time: 0,0000222 seconds
+[2018-10-10T17:09:33.958+0200][0,158s][info][safepoint] Total time for which application threads were stopped: 0,0000353 seconds, Stopping threads took: 0,0000221 seconds
+[2018-10-10T17:09:33.966+0200][0,165s][info][safepoint] Application time: 0,0076620 seconds
+[2018-10-10T17:09:33.976+0200][0,176s][info][gc       ] GC(1) Pause Young (G1 Evacuation Pause) 151M->27M(250M) 10,363ms
+[2018-10-10T17:09:33.976+0200][0,176s][info][safepoint] Total time for which application threads were stopped: 0,0104689 seconds, Stopping threads took: 0,0000132 seconds
+[2018-10-10T17:09:33.978+0200][0,178s][info][safepoint] Application time: 0,0019993 seconds
+[2018-10-10T17:09:33.986+0200][0,185s][info][gc       ] GC(2) Pause Young (G1 Evacuation Pause) 74M->35M(250M) 7,049ms
+[2018-10-10T17:09:33.986+0200][0,185s][info][safepoint] Total time for which application threads were stopped: 0,0072140 seconds, Stopping threads took: 0,0000628 seconds
+[2018-10-10T17:09:33.991+0200][0,190s][info][safepoint] Application time: 0,0055349 seconds
+[2018-10-10T17:09:33.998+0200][0,197s][info][gc       ] GC(3) Pause Young (G1 Evacuation Pause) 149M->62M(250M) 6,491ms
+[2018-10-10T17:09:33.998+0200][0,197s][info][safepoint] Total time for which application threads were stopped: 0,0065900 seconds, Stopping threads took: 0,0000232 seconds
+[2018-10-10T17:09:34.001+0200][0,201s][info][safepoint] Application time: 0,0036755 seconds
+[2018-10-10T17:09:34.010+0200][0,209s][info][gc       ] GC(4) Pause Young (G1 Evacuation Pause) 152M->78M(528M) 8,153ms
+[2018-10-10T17:09:34.010+0200][0,209s][info][safepoint] Total time for which application threads were stopped: 0,0082641 seconds, Stopping threads took: 0,0000321 seconds
+[2018-10-10T17:09:34.050+0200][0,250s][info][safepoint] Application time: 0,0404274 seconds
+[2018-10-10T17:09:34.056+0200][0,255s][info][gc       ] GC(5) Pause Young (G1 Evacuation Pause) 364M->105M(528M) 5,773ms
+[2018-10-10T17:09:34.056+0200][0,255s][info][safepoint] Total time for which application threads were stopped: 0,0058898 seconds, Stopping threads took: 0,0000181 seconds
+[2018-10-10T17:09:34.067+0200][0,267s][info][safepoint] Application time: 0,0113116 seconds
+[2018-10-10T17:09:34.077+0200][0,277s][info][gc       ] GC(6) Pause Young (G1 Evacuation Pause) 378M->134M(528M) 9,668ms
+[2018-10-10T17:09:34.077+0200][0,277s][info][safepoint] Total time for which application threads were stopped: 0,0098035 seconds, Stopping threads took: 0,0000481 seconds
+[2018-10-10T17:09:34.087+0200][0,286s][info][safepoint] Application time: 0,0098326 seconds
+[2018-10-10T17:09:34.095+0200][0,294s][info][gc       ] GC(7) Pause Young (G1 Evacuation Pause) 355M->160M(528M) 7,487ms
+[2018-10-10T17:09:34.095+0200][0,294s][info][safepoint] Total time for which application threads were stopped: 0,0076406 seconds, Stopping threads took: 0,0000551 seconds
+[2018-10-10T17:09:34.108+0200][0,307s][info][safepoint] Application time: 0,0128880 seconds
+[2018-10-10T17:09:34.125+0200][0,324s][info][gc       ] GC(8) Pause Young (G1 Evacuation Pause) 346M->188M(1391M) 16,934ms
+[2018-10-10T17:09:34.125+0200][0,324s][info][safepoint] Total time for which application threads were stopped: 0,0170773 seconds, Stopping threads took: 0,0000110 seconds
+[2018-10-10T17:09:34.199+0200][0,398s][info][safepoint] Application time: 0,0740680 seconds
+[2018-10-10T17:09:34.211+0200][0,410s][info][gc       ] GC(9) Pause Young (G1 Evacuation Pause) 820M->260M(1391M) 11,688ms
+[2018-10-10T17:09:34.211+0200][0,410s][info][safepoint] Total time for which application threads were stopped: 0,0118661 seconds, Stopping threads took: 0,0000682 seconds
+[2018-10-10T17:09:34.247+0200][0,446s][info][safepoint] Application time: 0,0357840 seconds
+[2018-10-10T17:09:34.265+0200][0,465s][info][gc       ] GC(10) Pause Young (G1 Evacuation Pause) 976M->270M(1391M) 18,726ms
+[2018-10-10T17:09:34.265+0200][0,465s][info][safepoint] Total time for which application threads were stopped: 0,0188810 seconds, Stopping threads took: 0,0000239 seconds
+[2018-10-10T17:09:34.297+0200][0,496s][info][safepoint] Application time: 0,0310386 seconds
+[2018-10-10T17:09:34.311+0200][0,511s][info][gc       ] GC(11) Pause Young (G1 Evacuation Pause) 990M->314M(1391M) 14,837ms
+[2018-10-10T17:09:34.312+0200][0,511s][info][safepoint] Total time for which application threads were stopped: 0,0149630 seconds, Stopping threads took: 0,0000093 seconds
+[2018-10-10T17:09:34.340+0200][0,539s][info][safepoint] Application time: 0,0282094 seconds
+[2018-10-10T17:09:34.372+0200][0,571s][info][gc       ] GC(12) Pause Young (G1 Evacuation Pause) 984M->419M(2428M) 31,622ms
+[2018-10-10T17:09:34.372+0200][0,571s][info][safepoint] Total time for which application threads were stopped: 0,0317558 seconds, Stopping threads took: 0,0000101 seconds
+[2018-10-10T17:09:34.528+0200][0,727s][info][safepoint] Application time: 0,1560104 seconds
+[2018-10-10T17:09:34.548+0200][0,748s][info][gc       ] GC(13) Pause Young (G1 Evacuation Pause) 1778M->473M(2428M) 20,424ms
+[2018-10-10T17:09:34.548+0200][0,748s][info][safepoint] Total time for which application threads were stopped: 0,0206292 seconds, Stopping threads took: 0,0000112 seconds
+[2018-10-10T17:09:34.604+0200][0,804s][info][safepoint] Application time: 0,0559395 seconds
+[2018-10-10T17:09:34.637+0200][0,837s][info][gc       ] GC(14) Pause Young (G1 Evacuation Pause) 1769M->537M(2428M) 32,996ms
+[2018-10-10T17:09:34.637+0200][0,837s][info][safepoint] Total time for which application threads were stopped: 0,0331996 seconds, Stopping threads took: 0,0000114 seconds
+[2018-10-10T17:09:34.695+0200][0,895s][info][safepoint] Application time: 0,0580040 seconds
+[2018-10-10T17:09:34.729+0200][0,928s][info][gc       ] GC(15) Pause Young (G1 Evacuation Pause) 1746M->590M(2428M) 33,492ms
+[2018-10-10T17:09:34.729+0200][0,929s][info][safepoint] Total time for which application threads were stopped: 0,0336745 seconds, Stopping threads took: 0,0000104 seconds
+[2018-10-10T17:09:34.781+0200][0,981s][info][safepoint] Application time: 0,0519908 seconds
+[2018-10-10T17:09:34.817+0200][1,017s][info][gc       ] GC(16) Pause Young (G1 Evacuation Pause) 1749M->626M(3050M) 35,972ms
+[2018-10-10T17:09:34.817+0200][1,017s][info][safepoint] Total time for which application threads were stopped: 0,0362033 seconds, Stopping threads took: 0,0000112 seconds
+[2018-10-10T17:09:34.933+0200][1,132s][info][safepoint] Application time: 0,1150617 seconds
+[2018-10-10T17:09:34.961+0200][1,161s][info][gc       ] GC(17) Pause Young (G1 Evacuation Pause) 2066M->675M(3050M) 28,515ms
+[2018-10-10T17:09:34.961+0200][1,161s][info][safepoint] Total time for which application threads were stopped: 0,0287366 seconds, Stopping threads took: 0,0000249 seconds
+[2018-10-10T17:09:35.030+0200][1,229s][info][safepoint] Application time: 0,0688478 seconds
+[2018-10-10T17:09:35.068+0200][1,267s][info][gc       ] GC(18) Pause Young (G1 Evacuation Pause) 2124M->730M(3050M) 37,778ms
+[2018-10-10T17:09:35.068+0200][1,267s][info][safepoint] Total time for which application threads were stopped: 0,0379313 seconds, Stopping threads took: 0,0000207 seconds
+[2018-10-10T17:09:35.126+0200][1,326s][info][safepoint] Application time: 0,0583244 seconds
+[2018-10-10T17:09:35.158+0200][1,357s][info][gc       ] GC(19) Pause Young (G1 Evacuation Pause) 2103M->778M(3050M) 31,486ms
+[2018-10-10T17:09:35.158+0200][1,357s][info][safepoint] Total time for which application threads were stopped: 0,0316063 seconds, Stopping threads took: 0,0000080 seconds
+[2018-10-10T17:09:35.191+0200][1,390s][info][safepoint] Application time: 0,0326633 seconds

From facaa58b790b49416ecb00d636bcb511bd7e1d29 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jaros=C5=82aw=20Pa=C5=82ka?= <jaroslaw.palka@symentis.pl>
Date: Mon, 29 Oct 2018 12:32:32 +0100
Subject: [PATCH 5/6] minor refactoring, code should be more readable now

---
 .../imp/DataReaderUnifiedJvmLogging.java      | 51 ++++++-----
 .../imp/TestDataReaderUJLSafepoint.java       | 86 +++++--------------
 2 files changed, 46 insertions(+), 91 deletions(-)

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
index b9a8fe1a..3dec72b7 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -77,11 +77,14 @@ class LogEvent {
     // 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
     
+    // matches log decorators (like time stamp, up time, level, tags and message)
     private static final Pattern PATTERN_DECORATORS = Pattern.compile("^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^s]*)s])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](?<message>.*)");
 
+    // matches gc event
     private static final Pattern PATTERN_GC_MESSAGE = Pattern.compile("^GC\\((?<gcnumber>[0-9]+)\\)[ ](?<type>[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)");
 
-    private static final Pattern PATTERN_APPLICATION_STOPPED = Pattern.compile("^Total time for which application threads were stopped: (?<applicationstopped>[0-9]+,[0-9]+) seconds, Stopping threads took: (?<threadsstopping>[0-9]+,[0-9]+) seconds$");
+    // matches application stopped time (entries with [safepoint] tag
+    private static final Pattern PATTERN_APPLICATION_STOPPED = Pattern.compile("Total time for which application threads were stopped: (?<applicationstopped>[0-9]+,[0-9]+) seconds, Stopping threads took: (?<threadsstopping>[0-9]+,[0-9]+) seconds");
     
     private static final String GROUP_DECORATORS_TIME = "time";
     private static final String GROUP_DECORATORS_UPTIME = "uptime";
@@ -150,7 +153,7 @@ class LogEvent {
     /** 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]", "[safepoint]","[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE);
     /** 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", "gc,heap,coops", "gc,heap,exit");
+    private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", "[trace", "gc,heap,coops", "gc,heap,exit", "Application time:");
     /** 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", "Heap region size");
 
@@ -191,23 +194,20 @@ private ParseContext parseEvent(ParseContext context) {
         
 	// extract log decorators (like time stamp, up time, level, tags and message)
         Matcher eventDecoratorsMatcher = PATTERN_DECORATORS.matcher(line );
-        LogEvent logEvent = createLogEvent(eventDecoratorsMatcher);
+        LogEvent logEvent = parseLogEvent(eventDecoratorsMatcher);
         
         if (logEvent==null) {
             getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
         } else {
             String message = logEvent.message;
-            Matcher decoratorsMatcher = PATTERN_GC_MESSAGE.matcher(message);
             try {
-                event = createGcEventWithStandardDecorators(logEvent, decoratorsMatcher, context.getLine());
-                if (event != null) {
-                    String tags = logEvent.tags;
-                    String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
-                    event = handleTail(context, event, tags, tail);
-                } else {
-                    Matcher applicationStoppedMAtcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
-                    event = parseSafepointEvent(logEvent,applicationStoppedMAtcher,line);
-                }
+        	if("safepoint".equals(logEvent.tags)) {
+        	    Matcher applicationStoppedMatcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
+        	    event = parseSafepointEvent(context, logEvent, applicationStoppedMatcher);        	    
+        	} else {
+        	    Matcher gcMatcher = PATTERN_GC_MESSAGE.matcher(message);
+                    event = createGcEvent(context, logEvent, gcMatcher);        	    
+        	}
             } catch (UnknownGcTypeException | NumberFormatException e) {
                 // prevent incomplete event from being added to the GCModel
                 event = null;
@@ -220,21 +220,19 @@ private ParseContext parseEvent(ParseContext context) {
         return context;
     }
 
-    private AbstractGCEvent<?> parseSafepointEvent(LogEvent logEvent, Matcher applicationStoppedMatcher, String line) {
-        if (applicationStoppedMatcher.matches()) {
+    private AbstractGCEvent<?> parseSafepointEvent(ParseContext context, LogEvent logEvent, Matcher applicationStoppedMatcher) { 
+	if (applicationStoppedMatcher.find()) {
             AbstractGCEvent<?> event = new VmOperationEvent();
             event.setType(Type.APPLICATION_STOPPED_TIME);
             setPause(event, applicationStoppedMatcher.group("applicationstopped"));
             setDateStampIfPresent(event, logEvent.time);
             setTimeStampIfPresent(event, logEvent.uptime);
             return event;
-        } else {
-            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
-            return null;
-        }
+        } 
+	return null;
     }
 
-    private LogEvent createLogEvent(Matcher eventDecoratorsMatcher) {
+    private LogEvent parseLogEvent(Matcher eventDecoratorsMatcher) {
         if(eventDecoratorsMatcher.matches()) {
             String time = eventDecoratorsMatcher.group( GROUP_DECORATORS_TIME );
             String uptime = eventDecoratorsMatcher.group( GROUP_DECORATORS_UPTIME );            
@@ -391,7 +389,7 @@ private void parseGcRegionTail(ParseContext context, AbstractGCEvent<?> event, S
      * @param line current line to be parsed
      * @return Instance of <code>AbstractGcEvent</code> or <code>null</code> if the line could not be matched.
      */
-    private AbstractGCEvent<?> createGcEventWithStandardDecorators(LogEvent logEvent, Matcher decoratorsMatcher, String line) throws UnknownGcTypeException {
+    private AbstractGCEvent<?> createGcEvent(ParseContext context, LogEvent logEvent, Matcher decoratorsMatcher) throws UnknownGcTypeException {
         if (decoratorsMatcher.matches()) {
             AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(decoratorsMatcher.group(GROUP_DECORATORS_GC_TYPE));
 
@@ -400,14 +398,15 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(LogEvent logEvent
             event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
             setDateStampIfPresent(event, logEvent.time);
             setTimeStampIfPresent(event, logEvent.uptime);
+            String tags = logEvent.tags;
+            String tail = decoratorsMatcher.group(GROUP_DECORATORS_TAIL);
+            event = handleTail(context, event, tags, tail);
             return event;
-        } else {
-            getLogger().warning(String.format("Failed to parse line number %d (no match; line=\"%s\")", in.getLineNumber(), line));
-            return null;
         }
+        return null;
     }
 
-    private void setPause(AbstractGCEvent event, String pauseAsString) {
+    private void setPause(AbstractGCEvent<?> event, String pauseAsString) {
         // TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
         if (pauseAsString != null && pauseAsString.length() > 0) {
             event.setPause(NumberParser.parseDouble(pauseAsString) / 1000);
@@ -418,7 +417,7 @@ private boolean hasMemory(AbstractGCEvent<?> event) {
         return event.getTotal() > 0;
     }
 
-    private void setMemory(AbstractGCEvent event, Matcher matcher) {
+    private void setMemory(AbstractGCEvent<?> event, Matcher matcher) {
         // TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
         event.setPreUsed(getDataReaderTools().getMemoryInKiloByte(
                 Integer.parseInt(matcher.group(GROUP_MEMORY_BEFORE)), matcher.group(GROUP_MEMORY_BEFORE_UNIT).charAt(0), matcher.group(GROUP_MEMORY)));
diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
index b3937bad..4ebcb457 100644
--- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
+++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSafepoint.java
@@ -3,13 +3,13 @@
 import com.tagtraum.perf.gcviewer.UnittestHelper;
 import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
 import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
-import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Generation;
-import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
 import com.tagtraum.perf.gcviewer.model.GCModel;
-import org.junit.Ignore;
 import org.junit.Test;
 
 import java.io.IOException;
+import java.util.ArrayList;
+import java.util.Iterator;
+import java.util.List;
 
 import static org.hamcrest.Matchers.is;
 import static org.junit.Assert.assertThat;
@@ -18,6 +18,7 @@
  * Tests unified jvm logging parser for safepoint events.
  */
 public class TestDataReaderUJLSafepoint {
+
     private GCModel getGCModelFromLogFile(String fileName) throws IOException {
         return UnittestHelper.getGCModelFromLogFile(fileName, FOLDER.OPENJDK_UJL, DataReaderUnifiedJvmLogging.class);
     }
@@ -25,71 +26,26 @@ private GCModel getGCModelFromLogFile(String fileName) throws IOException {
     @Test
     public void parseGcDefaults() throws Exception {
         GCModel model = getGCModelFromLogFile("sample-ujl-safepoint-defaults.txt");
-        assertThat("size", model.size(), is(16));
-        assertThat("amount of gc event types", model.getGcEventPauses().size(), is(3));
-        assertThat("amount of gc events", model.getGCPause().getN(), is(5));
-        assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(1));
-        assertThat("amount of full gc events", model.getFullGCPause().getN(), is(1));
-        assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5));
-
-
-        UnittestHelper.testMemoryPauseEvent(model.get(0),
-                "young",
-                Type.UJL_PAUSE_YOUNG,
-                0.008822,
-                1024 * 41, 1024 * 38,1024 * 150,
-                Generation.YOUNG,
-                false);
-
-        UnittestHelper.testMemoryPauseEvent(model.get(0),
-                "young",
-                Type.UJL_PAUSE_YOUNG,
-                0.008822,
-                1024 * 41, 1024 * 38,1024 * 150,
-                Generation.YOUNG,
-                false);
-
-        AbstractGCEvent<?> event2 = model.get(1);
-        UnittestHelper.testMemoryPauseEvent(event2,
-                "initialMarkEvent",
-                Type.UJL_PAUSE_INITIAL_MARK,
-                0.000136,
-                1024 * 61, 1024 * 61,1024 * 150,
-                Generation.TENURED,
-                false);
-        assertThat("isInitialMark", event2.isInitialMark(), is(true));
+        assertThat("size", model.size(), is(46));
+        assertThat("amount of gc event types", model.getGcEventPauses().size(), is(1));
+        assertThat("amount of gc events", model.getGCPause().getN(), is(20));
+        assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(0));
+        assertThat("amount of full gc events", model.getFullGCPause().getN(), is(0));
+        assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));
 
-        AbstractGCEvent<?> event3 = model.get(10);
-        UnittestHelper.testMemoryPauseEvent(event3,
-                "RemarkEvent",
-                Type.UJL_PAUSE_REMARK,
-                0.000859,
-                1024 * 110, 1024 * 110,1024 * 150,
-                Generation.TENURED,
-                false);
-        assertThat("isRemark", event3.isRemark(), is(true));
+        List<AbstractGCEvent<?>> vmOperationsEvents = toList(model.getVmOperationsEvents());
+	assertThat("amount of application stopped types", vmOperationsEvents.size(), is(26));
 
-        AbstractGCEvent<?> event4 = model.get(15);
-        UnittestHelper.testMemoryPauseEvent(event4,
-                "full",
-                Type.UJL_PAUSE_FULL,
-                0.009775,
-                1024 * 125, 1024 * 31, 1024 * 150,
-                Generation.ALL,
-                true);
-
-        AbstractGCEvent<?> concurrentMarkBeginEvent = model.get(2);
-        assertThat("event is not start of concurrent collection", concurrentMarkBeginEvent.isConcurrentCollectionStart(), is(false));
-
-        AbstractGCEvent<?> concurrentMarkWithPauseEvent = model.get(3);
-        assertThat("event is start of concurrent collection", concurrentMarkWithPauseEvent.isConcurrentCollectionStart(), is(true));
-
-        AbstractGCEvent<?> concurrentResetBeginEvent = model.get(13);
-        assertThat("event is not end of concurrent collection", concurrentResetBeginEvent.isConcurrentCollectionEnd(), is(false));
-
-        AbstractGCEvent<?> concurrentResetEvent = model.get(14);
-        assertThat("event is end of concurrent collection", concurrentResetEvent.isConcurrentCollectionEnd(), is(true));
 
+        AbstractGCEvent<?> event = model.get(0);
+        assertThat(event.getTypeAsString(),is("Total time for which application threads were stopped"));
+        assertThat(event.getPause(),is(0.0000000235));
+    }
+    
+    private static <T> List<T> toList(Iterator<T> iterator){
+	ArrayList<T> list = new ArrayList<>();
+	iterator.forEachRemaining(list::add);
+	return list;
     }
 
 }

From 38db187ca4601942d0380bc69daa67a078331b96 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Jaros=C5=82aw=20Pa=C5=82ka?= <jaroslaw.palka@symentis.pl>
Date: Mon, 29 Oct 2018 13:08:06 +0100
Subject: [PATCH 6/6] fixed code style issues

---
 .../imp/DataReaderUnifiedJvmLogging.java      | 40 +++++++++----------
 1 file changed, 20 insertions(+), 20 deletions(-)

diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
index 3dec72b7..a2f86c9d 100644
--- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
+++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java
@@ -48,24 +48,6 @@
  */
 public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
 
-    class LogEvent {
-
-        final String time;
-	final String uptime;
-	final String level;
-	final String tags;
-	final String message;
-
-	LogEvent(String time, String uptime, String level, String tags, String message) {
-	    this.time = time;
-	    this.uptime = uptime;
-	    this.level = level;
-	    this.tags = tags;
-	    this.message = message;
-        }
-
-    }
-
     // matches the whole line and extracts decorators from it (decorators always appear between [] and are independent of the gc algorithm being logged)
     // Input: [0.693s][info][gc           ] GC(0) Pause Init Mark 1.070ms
     // Group 1 / time: <empty> (optional group, no full timestamp present)
@@ -203,7 +185,7 @@ private ParseContext parseEvent(ParseContext context) {
             try {
         	if("safepoint".equals(logEvent.tags)) {
         	    Matcher applicationStoppedMatcher = PATTERN_APPLICATION_STOPPED.matcher(logEvent.message);
-        	    event = parseSafepointEvent(context, logEvent, applicationStoppedMatcher);        	    
+        	    event = parseSafepointEvent(logEvent, applicationStoppedMatcher);        	    
         	} else {
         	    Matcher gcMatcher = PATTERN_GC_MESSAGE.matcher(message);
                     event = createGcEvent(context, logEvent, gcMatcher);        	    
@@ -220,7 +202,7 @@ private ParseContext parseEvent(ParseContext context) {
         return context;
     }
 
-    private AbstractGCEvent<?> parseSafepointEvent(ParseContext context, LogEvent logEvent, Matcher applicationStoppedMatcher) { 
+    private AbstractGCEvent<?> parseSafepointEvent(LogEvent logEvent, Matcher applicationStoppedMatcher) { 
 	if (applicationStoppedMatcher.find()) {
             AbstractGCEvent<?> event = new VmOperationEvent();
             event.setType(Type.APPLICATION_STOPPED_TIME);
@@ -522,5 +504,23 @@ public String toString() {
         }
 
     }
+    
+    class LogEvent {
+
+        private final String time;
+	private final String uptime;
+	private final String level;
+	private final String tags;
+	private final String message;
+
+	LogEvent(String time, String uptime, String level, String tags, String message) {
+	    this.time = time;
+	    this.uptime = uptime;
+	    this.level = level;
+	    this.tags = tags;
+	    this.message = message;
+        }
+
+    }
 
 }
\ No newline at end of file