Fix for Gctoolkit #372 - YoungDetails event not published for GC log collected with -Xlog:gc (no *) (#430)

* Fixing #372, Test cases to come

* Update existing unified test cases for new Diarizer flag, add non-gc* pattern to rules test.

Author: jlittle-ptc

api/src/main/java/com/microsoft/gctoolkit/jvm/Diary.java

@@ -378,6 +378,10 @@ public boolean isJVMEventsKnown() {
         return isApplicationStoppedTimeKnown() && isApplicationRunningTime();
     }
 
+    public boolean isPrintCPUTimes() {
+    	return isStateKnown(SupportedFlags.PRINT_CPU_TIMES);
+    }
+    
     public void setTimeOfFirstEvent(DateTimeStamp startTime) {
         if ( this.timeOfFirstEvent == null)
             this.timeOfFirstEvent = startTime;

api/src/main/java/com/microsoft/gctoolkit/jvm/SupportedFlags.java

@@ -35,6 +35,8 @@ public enum SupportedFlags {
     MAX_TENURING_THRESHOLD_VIOLATION,           // 24
     TLAB_DATA,                                  // 25
     PRINT_PROMOTION_FAILURE,                    // 26
-    PRINT_FLS_STATISTICS                        // 27
+    PRINT_FLS_STATISTICS,                       // 27
+    
+    PRINT_CPU_TIMES								// 28
 
 }

parser/src/main/java/com/microsoft/gctoolkit/parser/UnifiedG1GCParser.java

@@ -252,7 +252,6 @@ public void endOfFile(GCLogTrace trace, String line) {
         publish(new JVMTermination((jvmTerminationEventTime.hasTimeStamp()) ? jvmTerminationEventTime : getClock(),diary.getTimeOfFirstEvent()));
     }
 
-
     /**
      * following records describe heap before the collection
      *
@@ -508,12 +507,29 @@ public void unifiedMetaData(GCLogTrace trace, String line) {
             forwardReference.setMetaspaceSizeAfterCollection(trace.toKBytes(5));
         }
     }
-
+    
     public void youngDetails(GCLogTrace trace, String line) {
         forwardReference.setHeapOccupancyBeforeCollection(trace.toKBytes(5));
         forwardReference.setHeapOccupancyAfterCollection(trace.toKBytes(7));
         forwardReference.setHeapSizeAfterCollection(trace.toKBytes(9));
         forwardReference.setDuration(trace.getDurationInSeconds());
+
+        // Handling -Xlog:gc logs (#372)
+    	// If the GC log was generated using -Xlog:gc instead of -Xlog:gc*, there won't be a CPU breakout
+        // line that will publish the event.  (cpuBreakout() above)
+
+        // If we haven't spotted a CPU decorator in the diarizer, we should be able to publish this line 
+        // after filling in the missing info.
+    	if (forwardReference.getGcType() == null && !diary.isPrintCPUTimes()) {
+    		forwardReference.setGcType(GarbageCollectionTypes.Young);
+    		forwardReference.setGCCause(trace.gcCause(-2));
+    		forwardReference.setStartTime(getClock());
+            try {
+                publishPauseEvent(forwardReference.buildEvent());
+            } catch (MalformedEvent malformedEvent) {
+                LOGGER.warning(malformedEvent.getMessage());
+            }
+    	}
     }
 
     /**

parser/src/main/java/com/microsoft/gctoolkit/parser/jvm/UnifiedDiarizer.java

@@ -117,6 +117,9 @@ else if (decorators.tagsContain("gc,phases") && logLevel.isGreaterThanOrEqualTo(
                 diary.setTrue(GC_DETAILS);
             else if ( decorators.tagsContain("gc,ergo"))
                 diary.setTrue(ADAPTIVE_SIZING);
+            else if (decorators.tagsContain("gc,cpu"))
+            	diary.setTrue(PRINT_CPU_TIMES);
+            
             if (decorators.tagsContain("safepoint"))
                 diary.setTrue(APPLICATION_STOPPED_TIME, APPLICATION_CONCURRENT_TIME);
 

parser/src/test/java/com/microsoft/gctoolkit/parser/G1GCUnifiedParserRulesTest.java

@@ -215,7 +215,8 @@ private void evaluate(GCParseRule rule, String string, boolean dump) {
                     "[6.641s][info][gc           ] GC(0) Pause Young (Normal) (G1 Evacuation Pause) 23M->6M(64M) 6.302ms",
                     "[7.965s][info][gc            ] GC(415) Pause Young (Concurrent Start) (G1 Evacuation Pause) 49M->30M(64M) 1.965ms",
                     "[7.981s][info][gc            ] GC(419) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 43M->16M(64M) 1.734ms",
-                    "[7.984s][info][gc            ] GC(420) Pause Young (Mixed) (G1 Evacuation Pause) 26M->11M(64M) 1.453ms"
+                    "[7.984s][info][gc            ] GC(420) Pause Young (Mixed) (G1 Evacuation Pause) 26M->11M(64M) 1.453ms",
+                    "[19.869s][info][gc] GC(8) Pause Young (Normal) (G1 Evacuation Pause) 170M->42M(1024M) 8.502ms"
             },
             {   //  9
                     "[2018-03-09T11:14:05.002-0100][12.277s][info ][gc,cpu       ] GC(0) User=0.04s Sys=0.01s Real=0.01s"

parser/src/test/java/com/microsoft/gctoolkit/parser/diary/G1DiarizerTest.java

@@ -206,9 +206,9 @@ public void testUnifiedG1GC() {
     };
 
     private static final boolean[][] unifiedDiary = {
-            //   0      1      2      3      4      5      6      7      8      9     10     11     12     13     14     15     16     17     18,    19,    20,    21,    22,    23,    24,    25,    26,    27
-            { true,  true, false, false, false, false, false, false, false,  true, false, false,  true,  true,  true, false, false, false, false, false,  true, false, false,  true, false, false, false, false},
-            { true,  true, false, false, false, false, false, false, false,  true, false, false,  true,  true,  true, false, false, false, false, false,  true, false, false,  true, false, false, false, false}
+            //   0      1      2      3      4      5      6      7      8      9     10     11     12     13     14     15     16     17     18,    19,    20,    21,    22,    23,    24,    25,    26,    27,   28
+            { true,  true, false, false, false, false, false, false, false,  true, false, false,  true,  true,  true, false, false, false, false, false,  true, false, false,  true, false, false, false, false, true},
+            { true,  true, false, false, false, false, false, false, false,  true, false, false,  true,  true,  true, false, false, false, false, false,  true, false, false,  true, false, false, false, false, true}
     };
 
     private static final int[][] unifiedUnknown = {
@@ -217,8 +217,8 @@ public void testUnifiedG1GC() {
     };
 
     private static final int[][] unifiedKnown = {
-            {1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27},
-            {1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27}
+            {1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28},
+            {1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28}
     };
 
 }

parser/src/test/java/com/microsoft/gctoolkit/parser/diary/LogDiaryTest.java

@@ -13,7 +13,6 @@
 import java.io.File;
 import java.io.IOException;
 import java.util.Objects;
-import java.util.stream.Stream;
 
 import static org.junit.jupiter.api.Assertions.fail;
 
@@ -288,6 +287,9 @@ void lookForKnowns(Diarizer jvmConfiguration, String name, int[] knowns) {
                     case 27:
                         assertTrue(name + ":PRINT_FLS_STATISTICS should be known", diary.isPrintFLSStatisticsKnown());
                         break;
+                    case 28:
+                    	assertTrue(name + ":PRINT_CPU_TIMES should be known", diary.isPrintCPUTimes());
+                    	break;
                     default:
                         fail("unknown unknown");
                 }