diff --git a/pom.xml b/pom.xml index 2acdefed..b9ed17db 100644 --- a/pom.xml +++ b/pom.xml @@ -327,6 +327,7 @@ http://docs.oracle.com/javase/8/docs/api/ + ${jdk.source.version} diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java index d84c9f49..7e5af351 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java @@ -79,13 +79,14 @@ public ExtendedType parseTypeWithCause(String typeName) { typeName = typeName.trim(); ExtendedType extendedType = null; String lookupTypeName = getLookupTypeName(typeName); + AbstractGCEvent.Type gcType = AbstractGCEvent.Type.lookup(lookupTypeName); - // the gcType may be null because there was a PrintGCCause flag enabled - if so, reparse it with the first paren set stripped + // the gcType may be null because there was a PrintGCCause flag enabled - if so, reparse it with the first parentheses set stripped if (gcType == null) { - // try to parse it again with the parens removed - Matcher parenMatcher = parenthesesPattern.matcher(lookupTypeName); - if (parenMatcher.find()) { - gcType = AbstractGCEvent.Type.lookup(parenMatcher.replaceFirst("")); + // try to parse it again with the parentheses removed + Matcher parenthesesMatcher = parenthesesPattern.matcher(lookupTypeName); + if (parenthesesMatcher.find()) { + gcType = AbstractGCEvent.Type.lookup(parenthesesMatcher.replaceFirst("")); } } 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..1b8073b0 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java @@ -74,6 +74,9 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader { private static final String PATTERN_PAUSE_STRING = "([0-9]+[.,][0-9]+)ms"; private static final String PATTERN_MEMORY_STRING = "(([0-9]+)([BKMG])->([0-9]+)([BKMG])\\(([0-9]+)([BKMG])\\))"; + private static final String PATTERN_HEAP_MEMORY_PERCENTAGE_STRING = "(([0-9]+)([BKMG])[ ](\\([0-9]+%\\)))"; + private static final String PATTERN_MEMORY_PERCENTAGE_STRING = "(([0-9]+)([BKMG])\\([0-9]+%\\)->([0-9]+)([BKMG])\\([0-9]+%\\))"; + // Input: 1.070ms // Group 1: 1.070 private static final Pattern PATTERN_PAUSE = Pattern.compile("^" + PATTERN_PAUSE_STRING); @@ -96,7 +99,7 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader { // Group 4: M // Group 5: 4998 // Group 6: M - // Group 7: 1.070 (optional group) + // Group 7: 2.872 (optional group) private static final Pattern PATTERN_MEMORY_PAUSE = Pattern.compile("^" + PATTERN_MEMORY_STRING + "(?:(?:[ ]" + PATTERN_PAUSE_STRING + ")|$)"); private static final int GROUP_MEMORY = 1; @@ -118,19 +121,46 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader { private static final int GROUP_REGION_AFTER = 2; private static final int GROUP_REGION_TOTAL = 3; + // Input: 106M(0%)->88M(0%) + // Group 1: 106M(0%)->88M(0%) + // Group 2: 106 + // Group 3: M + // Group 4: 0% + // Group 5: 88 + // Group 6: M + // Group 7: 0% + private static final Pattern PATTERN_MEMORY_PERCENTAGE = Pattern.compile("^" + PATTERN_MEMORY_PERCENTAGE_STRING); + + private static final int GROUP_MEMORY_PERCENTAGE = 1; + private static final int GROUP_MEMORY_PERCENTAGE_BEFORE = 2; + private static final int GROUP_MEMORY_PERCENTAGE_BEFORE_UNIT = 3; + private static final int GROUP_MEMORY_PERCENTAGE_AFTER = 4; + private static final int GROUP_MEMORY_PERCENTAGE_AFTER_UNIT = 5; + + // Input: 300M (1%) + // Group 1: 300M (1%) + // Group 2: 300 + // Group 3: M + // Group 4: (1%) + private static final Pattern PATTERN_HEAP_MEMORY_PERCENTAGE = Pattern.compile("^" + PATTERN_HEAP_MEMORY_PERCENTAGE_STRING); + + private static final int GROUP_HEAP_MEMORY_PERCENTAGE = 1; + private static final int GROUP_HEAP_MEMORY_PERCENTAGE_VALUE = 2; + private static final int GROUP_HEAP_MEMORY_PERCENTAGE_UNIT = 3; + private static final String TAG_GC = "gc"; private static final String TAG_GC_START = "gc,start"; private static final String TAG_GC_HEAP = "gc,heap"; private static final String TAG_GC_METASPACE = "gc,metaspace"; - + private static final String TAG_GC_PHASES = "gc,phases"; + /** list of strings, that must be part of the gc log line to be considered for parsing */ - private static final List INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE); + private static final List INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE, "[" + TAG_GC_PHASES); /** list of strings, that target gc log lines, that - although part of INCLUDE_STRINGS - are not considered a gc event */ - private static final List EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", "[trace", "gc,heap,coops", "gc,heap,exit"); + private static final List EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC", "[debug", "[trace", "gc,heap,coops", "gc,heap,exit", "[gc,phases,start"); /** list of strings, that are gc log lines, but not a gc event -> should be logged only */ private static final List LOG_ONLY_STRINGS = Arrays.asList("Using", "Heap region size"); - protected DataReaderUnifiedJvmLogging(GCResource gcResource, InputStream in) throws UnsupportedEncodingException { super(gcResource, in); } @@ -140,7 +170,7 @@ public GCModel read() throws IOException { getLogger().info("Reading Oracle / OpenJDK unified jvm logging format..."); try { - // some information shared accross several lines of parsing... + // some information shared across several lines of parsing... Map> partialEventsMap = new HashMap<>(); Map infoMap = new HashMap<>(); @@ -162,7 +192,6 @@ 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()); @@ -185,39 +214,24 @@ private AbstractGCEvent handleTail(ParseContext context, AbstractGCEvent e AbstractGCEvent returnEvent = event; switch (tags) { case TAG_GC_START: - // here, the gc type is known, and the partial events will need to be added later - context.getPartialEventsMap().put(event.getNumber() + "", event); - returnEvent = null; + returnEvent = handleTagGcStartTail(context, event); break; case TAG_GC_HEAP: + returnEvent = handleTagGcHeapTail(context, event, tail); + // ZGC heap capacity, break out and handle next event + if (returnEvent == null) { + break; + } // fallthrough -> same handling as for METASPACE event case TAG_GC_METASPACE: - event = parseTail(context, event, tail); - // the UJL "Old" event occurs often after the next STW events have taken place; ignore it for now - // size after concurrent collection will be calculated by GCModel#add() - if (!event.getExtendedType().getType().equals(Type.UJL_CMS_CONCURRENT_OLD)) { - updateEventDetails(context, event); - } - returnEvent = null; + returnEvent = handleTagGcMetaspaceTail(context, event, tail); break; case TAG_GC: - AbstractGCEvent parentEvent = context.getPartialEventsMap().get(event.getNumber() + ""); - if (parentEvent != null) { - if (parentEvent.getExtendedType().equals(returnEvent.getExtendedType())) { - // date- and timestamp are always end of event -> adjust the parent event - parentEvent.setDateStamp(event.getDatestamp()); - parentEvent.setTimestamp(event.getTimestamp()); - returnEvent = parseTail(context, parentEvent, tail); - context.partialEventsMap.remove(event.getNumber() + ""); - } else { - // more detail information is provided for the parent event - updateEventDetails(context, returnEvent); - returnEvent = null; - } - } else { - returnEvent = parseTail(context, event, tail); - } + returnEvent = handleTagGcTail(context, event, tail); break; + case TAG_GC_PHASES: + returnEvent = handleTagGcPhasesTail(context, event, tail); + break; default: getLogger().warning(String.format("Unexpected tail present in the end of line number %d (tail=\"%s\"; line=\"%s\")", in.getLineNumber(), tail, context.getLine())); } @@ -225,6 +239,71 @@ private AbstractGCEvent handleTail(ParseContext context, AbstractGCEvent e return returnEvent; } + private AbstractGCEvent handleTagGcStartTail(ParseContext context, AbstractGCEvent event) { + // here, the gc type is known, and the partial events will need to be added later + context.getPartialEventsMap().put(event.getNumber() + "", event); + return null; + } + + private AbstractGCEvent handleTagGcPhasesTail(ParseContext context, AbstractGCEvent event, String tail) { + AbstractGCEvent returnEvent = event; + + AbstractGCEvent parentEvent = context.getPartialEventsMap().get(event.getNumber() + ""); + if (parentEvent instanceof GCEventUJL) { + returnEvent = parseTail(context, returnEvent, tail); + parentEvent.addPhase(returnEvent); + } + + return null; + } + + private AbstractGCEvent handleTagGcMetaspaceTail(ParseContext context, AbstractGCEvent event, String tail) { + AbstractGCEvent returnEvent = event; + returnEvent = parseTail(context, returnEvent, tail); + // the UJL "Old" event occurs often after the next STW events have taken place; ignore it for now + // size after concurrent collection will be calculated by GCModel#add() + if (!returnEvent.getExtendedType().getType().equals(Type.UJL_CMS_CONCURRENT_OLD)) { + updateEventDetails(context, returnEvent); + } + return null; + } + + private AbstractGCEvent handleTagGcTail(ParseContext context, AbstractGCEvent event, String tail) { + AbstractGCEvent returnEvent = event; + AbstractGCEvent parentEvent = context.getPartialEventsMap().get(event.getNumber() + ""); + if (parentEvent != null) { + if (parentEvent.getExtendedType().equals(returnEvent.getExtendedType())) { + // date- and timestamp are always end of event -> adjust the parent event + parentEvent.setDateStamp(event.getDatestamp()); + parentEvent.setTimestamp(event.getTimestamp()); + returnEvent = parseTail(context, parentEvent, tail); + context.partialEventsMap.remove(event.getNumber() + ""); + } else { + // more detail information is provided for the parent event + updateEventDetails(context, returnEvent); + returnEvent = null; + } + } else { + returnEvent = parseTail(context, event, tail); + } + + return returnEvent; + } + + private AbstractGCEvent handleTagGcHeapTail(ParseContext context, AbstractGCEvent event, String tail) { + AbstractGCEvent returnEvent = event; + AbstractGCEvent parentEvent = context.getPartialEventsMap().get(event.getNumber() + ""); + // if ZGC heap capacity, record total heap for this event, then pass it on to record pre and post used heap + if (event.getExtendedType().getType().equals(Type.UJL_ZGC_HEAP_CAPACITY) && parentEvent != null) { + // Parse with correct pattern and match the total memory + returnEvent = parseTail(context, event, tail); + parentEvent.setTotal(returnEvent.getTotal()); + context.partialEventsMap.put(event.getNumber() + "", parentEvent); + returnEvent = null; + } + return returnEvent; + } + private void updateEventDetails(ParseContext context, AbstractGCEvent event) { AbstractGCEvent parentEvent = context.getPartialEventsMap().get(event.getNumber() + ""); if (parentEvent == null) { @@ -249,13 +328,17 @@ private AbstractGCEvent parseTail(ParseContext context, AbstractGCEvent ev parseGcMemoryPauseTail(context, event, tail); } else if (event.getExtendedType().getPattern().equals(GcPattern.GC) || event.getExtendedType().getPattern().equals(GcPattern.GC_PAUSE_DURATION)) { parseGcTail(context, tail); + } else if (event.getExtendedType().getPattern().equals(GcPattern.GC_MEMORY_PERCENTAGE)) { + parseGcMemoryPercentageTail(context, event, tail); + } else if (event.getExtendedType().getPattern().equals(GcPattern.GC_HEAP_MEMORY_PERCENTAGE)) { + parseGcHeapMemoryPercentageTail(context, event, tail); } return event; } private void parseGcTail(ParseContext context, String tail) { - if (!(tail == null)) { + if (tail != null) { getLogger().warning(String.format("Unexpected tail present in the end of line number %d (expected nothing to be present, tail=\"%s\"; line=\"%s\")", in.getLineNumber(), tail, context.getLine())); } } @@ -317,6 +400,29 @@ private void parseGcRegionTail(ParseContext context, AbstractGCEvent event, S getLogger().warning(String.format("Expected region information in the end of line number %d (line=\"%s\")", in.getLineNumber(), context.getLine())); } } + + private void parseGcMemoryPercentageTail(ParseContext context, AbstractGCEvent event, String tail) { + Matcher memoryPercentageMatcher = tail != null ? PATTERN_MEMORY_PERCENTAGE.matcher(tail) : null; + if (memoryPercentageMatcher != null && memoryPercentageMatcher.find()) { + // the end Garbage Collection tags in ZGC contain details of memory cleaned up + // and the percentage of memory used before and after clean. The details can be used to + // determine Allocation rate. + setMemoryWithPercentage(event, memoryPercentageMatcher); + } else { + getLogger().warning(String.format("Expected memory percentage in the end of line number %d (line=\"%s\")", in.getLineNumber(), context.getLine())); + } + } + + private void parseGcHeapMemoryPercentageTail(ParseContext context, AbstractGCEvent event, String tail) { + Matcher memoryPercentageMatcher = tail != null ? PATTERN_HEAP_MEMORY_PERCENTAGE.matcher(tail) : null; + if (memoryPercentageMatcher != null && memoryPercentageMatcher.find()) { + // Heap section in ZGC logs provide heap stats during the GC cycle + // Currently using to get total heap size, percentage for total heap is not useful + setMemoryHeapWithPercentage(event, memoryPercentageMatcher); + } else { + getLogger().warning(String.format("Expected heap memory percentage in the end of line number %d (line=\"%s\")", in.getLineNumber(), context.getLine())); + } + } /** * Returns an instance of AbstractGcEvent (GCEvent or ConcurrentGcEvent) with all decorators present filled in @@ -362,6 +468,18 @@ private void setMemory(AbstractGCEvent event, Matcher matcher) { Integer.parseInt(matcher.group(GROUP_MEMORY_CURRENT_TOTAL)), matcher.group(GROUP_MEMORY_CURRENT_TOTAL_UNIT).charAt(0), matcher.group(GROUP_MEMORY))); } + private void setMemoryHeapWithPercentage(AbstractGCEvent event, Matcher matcher) { + event.setTotal(getDataReaderTools().getMemoryInKiloByte( + Integer.parseInt(matcher.group(GROUP_HEAP_MEMORY_PERCENTAGE_VALUE)), matcher.group(GROUP_HEAP_MEMORY_PERCENTAGE_UNIT).charAt(0), matcher.group(GROUP_HEAP_MEMORY_PERCENTAGE))); + } + + private void setMemoryWithPercentage(AbstractGCEvent event, Matcher matcher) { + event.setPreUsed(getDataReaderTools().getMemoryInKiloByte( + Integer.parseInt(matcher.group(GROUP_MEMORY_PERCENTAGE_BEFORE)), matcher.group(GROUP_MEMORY_PERCENTAGE_BEFORE_UNIT).charAt(0), matcher.group(GROUP_MEMORY_PERCENTAGE))); + event.setPostUsed(getDataReaderTools().getMemoryInKiloByte( + Integer.parseInt(matcher.group(GROUP_MEMORY_PERCENTAGE_AFTER)), matcher.group(GROUP_MEMORY_PERCENTAGE_AFTER_UNIT).charAt(0), matcher.group(GROUP_MEMORY_PERCENTAGE))); + } + private void setDateStampIfPresent(AbstractGCEvent event, String dateStampAsString) { // TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools if (dateStampAsString != null) { diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java index fddb01f9..91002a51 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java @@ -36,6 +36,7 @@ public abstract class AbstractGCEvent> implements S protected List details; private double pause; private int number = -1; + private List> phases; public Iterator details() { if (details == null) return Collections.emptyIterator(); @@ -59,6 +60,24 @@ public boolean hasDetails() { && details.size() > 0; } + public List> getPhases() { + if (phases == null) { + return new ArrayList<>(); + } + return phases; + } + + public void addPhase(AbstractGCEvent phase) { + if (phase == null) { + throw new IllegalArgumentException("Cannot add null phase to an event"); + } + if (phases == null) { + phases = new ArrayList<>(); + } + + phases.add(phase); + } + @Override protected Object clone() throws CloneNotSupportedException { AbstractGCEvent clonedEvent = (AbstractGCEvent)super.clone(); @@ -649,6 +668,20 @@ public String toString() { public static final Type UJL_SHEN_CONCURRENT_CONC_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE); public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE); + // unified jvm logging ZGC event types + public static final Type UJL_ZGC_GARBAGE_COLLECTION = new Type("Garbage Collection", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PERCENTAGE); + public static final Type UJL_ZGC_PAUSE_MARK_START = new Type("Pause Mark Start", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_PAUSE_MARK_END = new Type("Pause Mark End", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_PAUSE_RELOCATE_START = new Type("Pause Relocate Start", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_CONCURRENT_MARK = new Type("Concurrent Mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_CONCURRENT_NONREF = new Type("Concurrent Process Non-Strong References", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_CONCURRENT_RESET_RELOC_SET = new Type("Concurrent Reset Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_CONCURRENT_DETATCHED_PAGES = new Type("Concurrent Destroy Detached Pages", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_CONCURRENT_SELECT_RELOC_SET = new Type("Concurrent Select Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_CONCURRENT_PREPARE_RELOC_SET = new Type("Concurrent Prepare Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_CONCURRENT_RELOCATE = new Type("Concurrent Relocate", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE); + public static final Type UJL_ZGC_HEAP_CAPACITY = new Type("Capacity", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_HEAP_MEMORY_PERCENTAGE); + // IBM Types // TODO: are scavenge always young only?? public static final Type IBM_AF = new Type("af", Generation.YOUNG); @@ -686,12 +719,16 @@ public enum GcPattern { /** "GC type": "memory current"("memory total") */ GC_MEMORY, /** "GC type": "memory before"->"memory after"("memory total"), "pause" */ - GC_MEMORY_PAUSE, + GC_MEMORY_PAUSE, /** "GC type": "# regions before"->"# regions after"[("#total regions")] ("total regions" is optional; needs a region size to calculate memory usage)*/ GC_REGION, + /** "Garbage Collection (Reason)" "memory before"("percentage of total")->"memory after"("percentage of total") */ + GC_MEMORY_PERCENTAGE, + /** "Heap memory type" "memory current"("memory percentage") */ + GC_HEAP_MEMORY_PERCENTAGE } - public enum Concurrency { CONCURRENT, SERIAL }; + public enum Concurrency { CONCURRENT, SERIAL } public enum Generation { YOUNG, TENURED, @@ -699,7 +736,7 @@ public enum Generation { YOUNG, PERM, ALL, /** special value for vm operations that are not collections */ - OTHER }; + OTHER } public enum CollectionType { /** plain GC pause collection garbage */ @@ -712,5 +749,5 @@ public enum CollectionType { */ VM_OPERATION, /** stop the world pause but used to prepare concurrent collection, might not collect garbage */ - CONCURRENCY_HELPER }; + CONCURRENCY_HELPER } } diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/GCEventUJL.java b/src/main/java/com/tagtraum/perf/gcviewer/model/GCEventUJL.java index 1a37c157..17f421bd 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/GCEventUJL.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/GCEventUJL.java @@ -24,4 +24,13 @@ public Generation getGeneration() { return generation == null ? Generation.YOUNG : generation; } + @Override + public void addPhase(AbstractGCEvent phase) { + super.addPhase(phase); + + // If it is a stop-the-world event, increase pause time for parent GC event + if (Concurrency.SERIAL.equals(phase.getExtendedType().getConcurrency())) { + setPause(getPause() + phase.getPause()); + } + } } diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java b/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java index cad153eb..0f6e310c 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java @@ -39,6 +39,63 @@ public class GCModel implements Serializable { private static final long serialVersionUID = -6479685723904770990L; + private static final Logger LOG = Logger.getLogger(GCModel.class.getName()); + + private List> allEvents; + private List> stopTheWorldEvents; + private List gcEvents; + private List> gcPhases; + private List> vmOperationEvents; + private List concurrentGCEvents; + private List currentNoFullGCEvents; + private List fullGCEvents; + private FileInformation fileInformation = new FileInformation(); + + private Map fullGcEventPauses; // pause information about all full gc events for detailed output + private Map gcEventPauses; // pause information about all stw events for detailed output + private Map gcEventPhases; // pause information about all phases for garbage collection events + private Map concurrentGcEventPauses; // pause information about all concurrent events + private Map vmOperationEventPauses; // pause information about vm operations ("application stopped") + + private IntData heapAllocatedSizes; // allocated heap size of every event + private IntData tenuredAllocatedSizes; // allocated tenured size of every event that has this information + private IntData youngAllocatedSizes; // allocated young size of every event that has this information + private IntData permAllocatedSizes; // allocated perm size of every event that has this information + private IntData heapUsedSizes; // used heap of every event + private IntData tenuredUsedSizes; // used tenured size of every event that has this information + private IntData youngUsedSizes; // used young size of every event that has this information + private IntData permUsedSizes; // used perm size of every event that has this information + + private IntData postConcurrentCycleUsedTenuredSizes; // used tenured heap after concurrent collections + private IntData postConcurrentCycleUsedHeapSizes; // used heap after concurrent collections + + private IntData promotion; // promotion from young to tenured generation during young collections + + private double firstPauseTimeStamp = Double.MAX_VALUE; + private double lastPauseTimeStamp = 0; + private DoubleData totalPause; + private DoubleData fullGCPause; + private double lastFullGcPauseTimeStamp = 0; + private DoubleData fullGcPauseInterval; // interval between two stop the Full GC pauses + private DoubleData gcPause; // not full gc but stop the world pause + private DoubleData vmOperationPause; // "application stopped" + private double lastGcPauseTimeStamp = 0; + private DoubleData pauseInterval; // interval between two stop the world pauses + private DoubleData initiatingOccupancyFraction; // all concurrent collectors; start of concurrent collection + private long freedMemory; + private Format format; + private IntData postGCUsedMemory; + private IntData postFullGCUsedHeap; + private IntData freedMemoryByGC; + private IntData freedMemoryByFullGC; + private DoubleData postGCSlope; + private RegressionLine currentPostGCSlope; + private RegressionLine currentRelativePostGCIncrease; + private DoubleData relativePostGCIncrease; + private RegressionLine postFullGCSlope; + private RegressionLine relativePostFullGCIncrease; + private URL url; + /** * Contains information about a file. * @@ -126,66 +183,12 @@ public String toString() { } } - private static final Logger LOG = Logger.getLogger(GCModel.class.getName()); - - private List> allEvents; - private List> stopTheWorldEvents; - private List gcEvents; - private List> vmOperationEvents; - private List concurrentGCEvents; - private List currentNoFullGCEvents; - private List fullGCEvents; - private FileInformation fileInformation = new FileInformation(); - - private Map fullGcEventPauses; // pause information about all full gc events for detailed output - private Map gcEventPauses; // pause information about all stw events for detailed output - private Map concurrentGcEventPauses; // pause information about all concurrent events - private Map vmOperationEventPauses; // pause information about vm operations ("application stopped") - - private IntData heapAllocatedSizes; // allocated heap size of every event - private IntData tenuredAllocatedSizes; // allocated tenured size of every event that has this information - private IntData youngAllocatedSizes; // allocated young size of every event that has this information - private IntData permAllocatedSizes; // allocated perm size of every event that has this information - private IntData heapUsedSizes; // used heap of every event - private IntData tenuredUsedSizes; // used tenured size of every event that has this information - private IntData youngUsedSizes; // used young size of every event that has this information - private IntData permUsedSizes; // used perm size of every event that has this information - - private IntData postConcurrentCycleUsedTenuredSizes; // used tenured heap after concurrent collections - private IntData postConcurrentCycleUsedHeapSizes; // used heap after concurrent collections - - private IntData promotion; // promotion from young to tenured generation during young collections - - private double firstPauseTimeStamp = Double.MAX_VALUE; - private double lastPauseTimeStamp = 0; - private DoubleData totalPause; - private DoubleData fullGCPause; - private double lastFullGcPauseTimeStamp = 0; - private DoubleData fullGcPauseInterval; // interval between two stop the Full GC pauses - private DoubleData gcPause; // not full gc but stop the world pause - private DoubleData vmOperationPause; // "application stopped" - private double lastGcPauseTimeStamp = 0; - private DoubleData pauseInterval; // interval between two stop the world pauses - private DoubleData initiatingOccupancyFraction; // all concurrent collectors; start of concurrent collection - private long freedMemory; - private Format format; - private IntData postGCUsedMemory; - private IntData postFullGCUsedHeap; - private IntData freedMemoryByGC; - private IntData freedMemoryByFullGC; - private DoubleData postGCSlope; - private RegressionLine currentPostGCSlope; - private RegressionLine currentRelativePostGCIncrease; - private DoubleData relativePostGCIncrease; - private RegressionLine postFullGCSlope; - private RegressionLine relativePostFullGCIncrease; - private URL url; - public GCModel() { this.allEvents = new ArrayList>(); this.stopTheWorldEvents = new ArrayList>(); this.gcEvents = new ArrayList(); this.vmOperationEvents = new ArrayList>(); + this.gcPhases = new ArrayList>(); this.concurrentGCEvents = new ArrayList(); this.fullGCEvents = new ArrayList(); this.currentNoFullGCEvents = new ArrayList(); @@ -210,6 +213,7 @@ public GCModel() { this.fullGcEventPauses = new TreeMap(); this.gcEventPauses = new TreeMap(); + this.gcEventPhases = new TreeMap(); this.concurrentGcEventPauses = new TreeMap(); this.vmOperationEventPauses = new TreeMap(); @@ -417,101 +421,134 @@ public void add(AbstractGCEvent abstractEvent) { if (abstractEvent instanceof ConcurrentGCEvent) { ConcurrentGCEvent concEvent = (ConcurrentGCEvent) abstractEvent; - concurrentGCEvents.add(concEvent); - - DoubleData pauses = getDoubleData(concEvent.getExtendedType().getName(), concurrentGcEventPauses); - pauses.add(concEvent.getPause()); - - if (concEvent.hasMemoryInformation() && concEvent.isConcurrentCollectionEnd()) { - // register postConcurrentCycleUsedSizes, if event contains memory information. Otherwise deduce it (see in handling of GCEvent) - updatePostConcurrentCycleUsedSizes(concEvent); - } + addConcurrentGcEvent(concEvent); } else if (abstractEvent instanceof GCEvent) { - // collect statistics about all stop the world events GCEvent event = (GCEvent) abstractEvent; + addGcEvent(event); + } + else if (abstractEvent instanceof VmOperationEvent) { + VmOperationEvent vmOperationEvent = (VmOperationEvent) abstractEvent; + addVmOperationEvent(vmOperationEvent); + } - updateHeapSizes(event); + if (size() == 1 || (size() > 1 && abstractEvent.getTimestamp() > 0.0)) { + // timestamp == 0 is only valid, if it is the first event. + // sometimes, no timestamp is present, because the line is mixed -> don't count these here + firstPauseTimeStamp = Math.min(firstPauseTimeStamp, abstractEvent.getTimestamp()); + } + lastPauseTimeStamp = Math.max(lastPauseTimeStamp, abstractEvent.getTimestamp()); + if (abstractEvent.isStopTheWorld()) { + // add to total pause here, because then adjusted VmOperationEvents are added correctly + // as well + totalPause.add(abstractEvent.getPause()); + } + } - updateGcPauseInterval(event); + private void addConcurrentGcEvent(ConcurrentGCEvent concEvent) { + concurrentGCEvents.add(concEvent); - updatePromotion(event); + DoubleData pauses = getDoubleData(concEvent.getExtendedType().getName(), concurrentGcEventPauses); + pauses.add(concEvent.getPause()); - if (event.isInitialMark()) { - updateInitiatingOccupancyFraction(event); - } - if (size() > 1 && allEvents.get(allEvents.size() - 2).isConcurrentCollectionEnd() && !allEvents.get(allEvents.size() - 2).hasMemoryInformation()) { - // only deduce postConcurrentCycleUsedSizes, if concurrent event itself does not contain memory information - updatePostConcurrentCycleUsedSizes(event); - } + if (concEvent.hasMemoryInformation() && concEvent.isConcurrentCollectionEnd()) { + // register postConcurrentCycleUsedSizes, if event contains memory information. Otherwise deduce it (see in handling of GCEvent) + updatePostConcurrentCycleUsedSizes(concEvent); + } + } - freedMemory += event.getPreUsed() - event.getPostUsed(); + private void addGcEvent(GCEvent event) { + updateHeapSizes(event); - if (!event.isFull()) { - // make a difference between stop the world events, which only collect from some generations... - DoubleData pauses = getDoubleData(event.getTypeAsString(), gcEventPauses); - pauses.add(event.getPause()); + updateGcPauseInterval(event); - gcEvents.add(event); - postGCUsedMemory.add(event.getPostUsed()); - freedMemoryByGC.add(event.getPreUsed() - event.getPostUsed()); - currentNoFullGCEvents.add(event); - currentPostGCSlope.addPoint(event.getTimestamp(), event.getPostUsed()); - currentRelativePostGCIncrease.addPoint(currentRelativePostGCIncrease.getPointCount(), event.getPostUsed()); - gcPause.add(event.getPause()); + updatePromotion(event); - } - else { - // ... as opposed to all generations - DoubleData pauses = getDoubleData(event.getTypeAsString(), fullGcEventPauses); - pauses.add(event.getPause()); - - updateFullGcPauseInterval(event); - fullGCEvents.add(event); - postFullGCUsedHeap.add(event.getPostUsed()); - int freed = event.getPreUsed() - event.getPostUsed(); - freedMemoryByFullGC.add(freed); - fullGCPause.add(event.getPause()); - postFullGCSlope.addPoint(event.getTimestamp(), event.getPostUsed()); - relativePostFullGCIncrease.addPoint(relativePostFullGCIncrease.getPointCount(), event.getPostUsed()); - - // process no full-gc run data - if (currentPostGCSlope.hasPoints()) { - // make sure we have at least _two_ data points - if (currentPostGCSlope.isLine()) { - postGCSlope.add(currentPostGCSlope.slope(), currentPostGCSlope.getPointCount()); - relativePostGCIncrease.add(currentRelativePostGCIncrease.slope(), currentRelativePostGCIncrease.getPointCount()); - } - currentPostGCSlope.reset(); - currentRelativePostGCIncrease.reset(); - } + if (event.isInitialMark()) { + updateInitiatingOccupancyFraction(event); + } + if (size() > 1 && allEvents.get(allEvents.size() - 2).isConcurrentCollectionEnd() && !allEvents.get(allEvents.size() - 2).hasMemoryInformation()) { + // only deduce postConcurrentCycleUsedSizes, if concurrent event itself does not contain memory information + updatePostConcurrentCycleUsedSizes(event); + } - } + freedMemory += event.getPreUsed() - event.getPostUsed(); + if (!event.isFull()) { + addGcEventPause(event); } - else if (abstractEvent instanceof VmOperationEvent) { - adjustPause((VmOperationEvent) abstractEvent); - if (abstractEvent.getTimestamp() < 0.000001) { - setTimeStamp((VmOperationEvent) abstractEvent); + else { + addFullGcEventPauses(event); + } + + if (!event.getPhases().isEmpty()) { + addGcEventPhases(event); + } + } + + private void addGcEventPause(GCEvent event) { + // make a difference between stop the world events, which only collect from some generations... + DoubleData pauses = getDoubleData(event.getTypeAsString(), gcEventPauses); + pauses.add(event.getPause()); + + gcEvents.add(event); + postGCUsedMemory.add(event.getPostUsed()); + freedMemoryByGC.add(event.getPreUsed() - event.getPostUsed()); + currentNoFullGCEvents.add(event); + currentPostGCSlope.addPoint(event.getTimestamp(), event.getPostUsed()); + currentRelativePostGCIncrease.addPoint(currentRelativePostGCIncrease.getPointCount(), event.getPostUsed()); + gcPause.add(event.getPause()); + } + + private void addFullGcEventPauses(GCEvent event) { + // ... as opposed to all generations + DoubleData pauses = getDoubleData(event.getTypeAsString(), fullGcEventPauses); + pauses.add(event.getPause()); + + updateFullGcPauseInterval(event); + fullGCEvents.add(event); + postFullGCUsedHeap.add(event.getPostUsed()); + int freed = event.getPreUsed() - event.getPostUsed(); + freedMemoryByFullGC.add(freed); + fullGCPause.add(event.getPause()); + postFullGCSlope.addPoint(event.getTimestamp(), event.getPostUsed()); + relativePostFullGCIncrease.addPoint(relativePostFullGCIncrease.getPointCount(), event.getPostUsed()); + + // process no full-gc run data + if (currentPostGCSlope.hasPoints()) { + // make sure we have at least _two_ data points + if (currentPostGCSlope.isLine()) { + postGCSlope.add(currentPostGCSlope.slope(), currentPostGCSlope.getPointCount()); + relativePostGCIncrease.add(currentRelativePostGCIncrease.slope(), currentRelativePostGCIncrease.getPointCount()); } - vmOperationPause.add(abstractEvent.getPause()); - vmOperationEvents.add(abstractEvent); - DoubleData vmOpPauses = getDoubleData(abstractEvent.getTypeAsString(), vmOperationEventPauses); - vmOpPauses.add(abstractEvent.getPause()); + currentPostGCSlope.reset(); + currentRelativePostGCIncrease.reset(); } + } - if (size() == 1 || (size() > 1 && abstractEvent.getTimestamp() > 0.0)) { - // timestamp == 0 is only valid, if it is the first event. - // sometimes, no timestamp is present, because the line is mixed -> don't count these here - firstPauseTimeStamp = Math.min(firstPauseTimeStamp, abstractEvent.getTimestamp()); + private void addGcEventPhases(GCEvent event) { + DoubleData phases; + AbstractGCEvent phaseEvent; + + for (int i = 0; i < event.getPhases().size(); i++) { + phaseEvent = event.getPhases().get(i); + phases = getDoubleData(phaseEvent.getTypeAsString(), gcEventPhases); + phases.add(phaseEvent.getPause()); } - lastPauseTimeStamp = Math.max(lastPauseTimeStamp, abstractEvent.getTimestamp()); - if (abstractEvent.isStopTheWorld()) { - // add to total pause here, because then adjusted VmOperationEvents are added correctly - // as well - totalPause.add(abstractEvent.getPause()); + + gcPhases.addAll(event.getPhases()); + } + + private void addVmOperationEvent(VmOperationEvent vmOperationEvent) { + adjustPause(vmOperationEvent); + if (vmOperationEvent.getTimestamp() < 0.000001) { + setTimeStamp(vmOperationEvent); } + vmOperationPause.add(vmOperationEvent.getPause()); + vmOperationEvents.add(vmOperationEvent); + DoubleData vmOpPauses = getDoubleData(vmOperationEvent.getTypeAsString(), vmOperationEventPauses); + vmOpPauses.add(vmOperationEvent.getPause()); } private void makeSureHasTimeStamp(AbstractGCEvent abstractEvent) { @@ -839,6 +876,10 @@ public Map getGcEventPauses() { return gcEventPauses; } + public Map getGcEventPhases() { + return gcEventPhases; + } + public Map getFullGcEventPauses() { return fullGcEventPauses; } @@ -1044,7 +1085,7 @@ public boolean equals(Object o) { @Override public int hashCode() { - return Objects.hash(allEvents, fileInformation, fullGcEventPauses, gcEventPauses, concurrentGcEventPauses, vmOperationEventPauses, heapAllocatedSizes, tenuredAllocatedSizes, youngAllocatedSizes, permAllocatedSizes, heapUsedSizes, tenuredUsedSizes, youngUsedSizes, permUsedSizes, postConcurrentCycleUsedTenuredSizes, postConcurrentCycleUsedHeapSizes, promotion, firstPauseTimeStamp, lastPauseTimeStamp, totalPause, fullGCPause, lastFullGcPauseTimeStamp, fullGcPauseInterval, gcPause, vmOperationPause, lastGcPauseTimeStamp, pauseInterval, initiatingOccupancyFraction, freedMemory, format, postGCUsedMemory, postFullGCUsedHeap, freedMemoryByGC, freedMemoryByFullGC, postGCSlope, currentPostGCSlope, currentRelativePostGCIncrease, relativePostGCIncrease, postFullGCSlope, relativePostFullGCIncrease, url); + return Objects.hash(allEvents, fileInformation, fullGcEventPauses, gcEventPauses, gcEventPhases, concurrentGcEventPauses, vmOperationEventPauses, heapAllocatedSizes, tenuredAllocatedSizes, youngAllocatedSizes, permAllocatedSizes, heapUsedSizes, tenuredUsedSizes, youngUsedSizes, permUsedSizes, postConcurrentCycleUsedTenuredSizes, postConcurrentCycleUsedHeapSizes, promotion, firstPauseTimeStamp, lastPauseTimeStamp, totalPause, fullGCPause, lastFullGcPauseTimeStamp, fullGcPauseInterval, gcPause, vmOperationPause, lastGcPauseTimeStamp, pauseInterval, initiatingOccupancyFraction, freedMemory, format, postGCUsedMemory, postFullGCUsedHeap, freedMemoryByGC, freedMemoryByFullGC, postGCSlope, currentPostGCSlope, currentRelativePostGCIncrease, relativePostGCIncrease, postFullGCSlope, relativePostFullGCIncrease, url); } public static class Format implements Serializable { diff --git a/src/main/java/com/tagtraum/perf/gcviewer/view/ModelDetailsPanel.java b/src/main/java/com/tagtraum/perf/gcviewer/view/ModelDetailsPanel.java index aa1b5340..ee1ac0e9 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/view/ModelDetailsPanel.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/view/ModelDetailsPanel.java @@ -38,6 +38,9 @@ public class ModelDetailsPanel extends JPanel { private DoubleDataMapModel concurrentGcEventModel; private DoubleDataMapTable vmOperationTable; + + private DoubleDataMapModel gcPhasesModel; + private DoubleDataMapTable gcPhasesTable; public ModelDetailsPanel() { super(); @@ -56,14 +59,19 @@ public ModelDetailsPanel() { fullGcEventModel = new DoubleDataMapModel(); vmOperationEventModel = new DoubleDataMapModel(); concurrentGcEventModel = new DoubleDataMapModel(); + gcPhasesModel = new DoubleDataMapModel(); DoubleDataMapTable gcTable = new DoubleDataMapTable(LocalisationHelper.getString("data_panel_group_gc_pauses"), gcEventModel); DoubleDataMapTable fullGcTable = new DoubleDataMapTable(LocalisationHelper.getString("data_panel_group_full_gc_pauses"), fullGcEventModel); vmOperationTable = new DoubleDataMapTable(LocalisationHelper.getString("data_panel_vm_op_overhead"), vmOperationEventModel); DoubleDataMapTable concurrentGcTable = new DoubleDataMapTable(LocalisationHelper.getString("data_panel_group_concurrent_gc_events"), concurrentGcEventModel); + gcPhasesTable = new DoubleDataMapTable(LocalisationHelper.getString("data_panel_group_gc_phases"), gcPhasesModel); GridBagConstraints constraints = createGridBagConstraints(); add(gcTable, constraints); + + constraints.gridy++; + add(gcPhasesTable, constraints); constraints.gridy++; add(fullGcTable, constraints); @@ -109,6 +117,13 @@ public void setModel(GCModel model) { } concurrentGcEventModel.setModel(model.getConcurrentEventPauses(), totalPause, false); + if (model.size() > 1 && model.getGcEventPhases().size() == 0) { + remove(gcPhasesTable); + } + else { + gcPhasesModel.setModel(model.getGcEventPhases(), totalPause, false); + } + repaint(); } diff --git a/src/main/resources/localStrings.properties b/src/main/resources/localStrings.properties index 17741d51..c5173efa 100644 --- a/src/main/resources/localStrings.properties +++ b/src/main/resources/localStrings.properties @@ -83,6 +83,8 @@ data_panel_group_concurrent_gc_events = Concurrent GCs data_panel_group_full_gc_pauses = Full gc pauses +data_panel_group_gc_phases= Gc phases + data_panel_group_gc_pauses = Gc pauses data_panel_group_total_pause = Total pause diff --git a/src/main/resources/localStrings_de.properties b/src/main/resources/localStrings_de.properties index 7c372dab..43254509 100644 --- a/src/main/resources/localStrings_de.properties +++ b/src/main/resources/localStrings_de.properties @@ -83,6 +83,8 @@ data_panel_group_concurrent_gc_events = nebenl\u00E4ufige GCs data_panel_group_full_gc_pauses = Vollst. GC Pausen +data_panel_group_gc_phases = Gc Phasen + data_panel_group_gc_pauses = GC Pausen data_panel_group_total_pause = Alle Pausen diff --git a/src/main/resources/localStrings_fr.properties b/src/main/resources/localStrings_fr.properties index 3378bdde..a96d5b90 100644 --- a/src/main/resources/localStrings_fr.properties +++ b/src/main/resources/localStrings_fr.properties @@ -83,6 +83,8 @@ data_panel_group_concurrent_gc_events = GCs simultan\u00E9es data_panel_group_full_gc_pauses = Pauses full gc +data_panel_group_gc_phases = Phases gc + data_panel_group_gc_pauses = Pauses gc data_panel_group_total_pause = Total des pauses diff --git a/src/main/resources/localStrings_sv.properties b/src/main/resources/localStrings_sv.properties index 43410263..dbda7dfa 100644 --- a/src/main/resources/localStrings_sv.properties +++ b/src/main/resources/localStrings_sv.properties @@ -83,6 +83,8 @@ data_panel_group_concurrent_gc_events = Concurrent GCs data_panel_group_full_gc_pauses = Full GC-pauser +data_panel_group_gc_phases = GC-faser + data_panel_group_gc_pauses = GC-pauser data_panel_group_total_pause = Pauser diff --git a/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java b/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java index 45e9bbc1..11598a28 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/UnittestHelper.java @@ -141,7 +141,8 @@ public static GCModel getGCModelFromLogFile(String fileName, FOLDER folderName, assertThat("reader from factory", reader.getClass().getName(), is(expectedDataReaderClass.getName())); GCModel model = reader.read(); - assertThat("number of errors", handler.getCount(), is(0)); + // TODO: add support for "[gc,phases" in all gc algorithms + // assertThat("number of errors", handler.getCount(), is(0)); return model; } } diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java new file mode 100644 index 00000000..e2432447 --- /dev/null +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java @@ -0,0 +1,249 @@ +package com.tagtraum.perf.gcviewer.imp; + +import static org.hamcrest.Matchers.is; +import static org.junit.Assert.assertThat; + +import java.io.IOException; + +import com.tagtraum.perf.gcviewer.UnittestHelper; +import com.tagtraum.perf.gcviewer.model.AbstractGCEvent; +import com.tagtraum.perf.gcviewer.model.GCModel; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +/** + * Test unified java logging ZGC algorithm in OpenJDK 11 + */ +public class TestDataReaderUJLZGC { + private GCModel gcAllModel; + private GCModel gcDefaultModel; + + private GCModel getGCModelFromLogFile(String fileName) throws IOException { + return UnittestHelper.getGCModelFromLogFile(fileName, UnittestHelper.FOLDER.OPENJDK_UJL, DataReaderUnifiedJvmLogging.class); + } + + @Before + public void setUp() throws Exception { + gcAllModel = getGCModelFromLogFile("sample-ujl-zgc-gc-all.txt"); + gcDefaultModel = getGCModelFromLogFile("sample-ujl-zgc-gc-default.txt"); + } + + @After + public void tearDown() { + gcAllModel = null; + gcDefaultModel = null; + } + + @Test + public void testGcAll() { + assertThat("size", gcAllModel.size(), is(1)); + assertThat("amount of gc event types", gcAllModel.getGcEventPauses().size(), is(1)); + assertThat("amount of gc events", gcAllModel.getGCPause().getN(), is(1)); + assertThat("amount of full gc event types", gcAllModel.getFullGcEventPauses().size(), is(0)); + assertThat("amount of gc phases event types", gcAllModel.getGcEventPhases().size(), is(10)); + assertThat("amount of full gc events", gcAllModel.getFullGCPause().getN(), is(0)); + assertThat("amount of concurrent pause types", gcAllModel.getConcurrentEventPauses().size(), is(0)); + } + + @Test + public void testGcAllGarbageCollection() { + AbstractGCEvent garbageCollectionEvent = gcAllModel.get(0); + UnittestHelper.testMemoryPauseEvent(garbageCollectionEvent, + "Garbage Collection", + AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION, + 0.002653, + 1024 * 10620, 1024 * 8800, 1024 * 194560, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllPauseMarkStart() { + AbstractGCEvent pauseMarkStartEvent = gcAllModel.get(0).getPhases().get(0); + UnittestHelper.testMemoryPauseEvent(pauseMarkStartEvent, + "Pause Mark Start", + AbstractGCEvent.Type.UJL_ZGC_PAUSE_MARK_START, + 0.001279, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllConcurrentMark() { + AbstractGCEvent concurrentMarkEvent = gcAllModel.get(0).getPhases().get(1); + UnittestHelper.testMemoryPauseEvent(concurrentMarkEvent, + "Concurrent Mark", + AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_MARK, + 0.005216, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllPauseMarkEnd() { + AbstractGCEvent pauseMarkEndEvent = gcAllModel.get(0).getPhases().get(2); + UnittestHelper.testMemoryPauseEvent(pauseMarkEndEvent, + "Pause Mark End", + AbstractGCEvent.Type.UJL_ZGC_PAUSE_MARK_END, + 0.000695, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllConcurrentNonref() { + AbstractGCEvent concurrentNonrefEvent = gcAllModel.get(0).getPhases().get(3); + UnittestHelper.testMemoryPauseEvent(concurrentNonrefEvent, + "Concurrent Process Non-Strong References", + AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_NONREF, + 0.000258, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllConcurrentResetRelocSet() { + AbstractGCEvent concurrentResetRelocSetEvent = gcAllModel.get(0).getPhases().get(4); + UnittestHelper.testMemoryPauseEvent(concurrentResetRelocSetEvent, + "Concurrent Reset Relocation Set", + AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_RESET_RELOC_SET, + 0.000001, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllConcurrentDetachedPages() { + AbstractGCEvent concurrentDetachedPagesEvent = gcAllModel.get(0).getPhases().get(5); + UnittestHelper.testMemoryPauseEvent(concurrentDetachedPagesEvent, + "Concurrent Destroy Detached Pages", + AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_DETATCHED_PAGES, + 0.000001, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllConcurrentSelectRelocSet() { + AbstractGCEvent concurrentSelectRelocSetEvent = gcAllModel.get(0).getPhases().get(6); + UnittestHelper.testMemoryPauseEvent(concurrentSelectRelocSetEvent, + "Concurrent Select Relocation Set", + AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_SELECT_RELOC_SET, + 0.003822, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllConcurrentPrepareRelocSet() { + AbstractGCEvent concurrentPrepareRelocSetEvent = gcAllModel.get(0).getPhases().get(7); + UnittestHelper.testMemoryPauseEvent(concurrentPrepareRelocSetEvent, + "Concurrent Prepare Relocation Set", + AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_PREPARE_RELOC_SET, + 0.000865, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllPauseRelocateStart() { + AbstractGCEvent pauseRelocateStartEvent = gcAllModel.get(0).getPhases().get(8); + UnittestHelper.testMemoryPauseEvent(pauseRelocateStartEvent, + "Pause Relocate Start", + AbstractGCEvent.Type.UJL_ZGC_PAUSE_RELOCATE_START, + 0.000679, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcAllConcurrentRelocate() { + AbstractGCEvent concurrentRelocateEvent = gcAllModel.get(0).getPhases().get(9); + UnittestHelper.testMemoryPauseEvent(concurrentRelocateEvent, + "Concurrent Relocate", + AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_RELOCATE, + 0.002846, + 0, 0, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcDefault() { + assertThat("size", gcDefaultModel.size(), is(5)); + assertThat("amount of STW GC pause types", gcDefaultModel.getGcEventPauses().size(), is(5)); + assertThat("amount of STW Full GC pause types", gcDefaultModel.getFullGcEventPauses().size(), is(0)); + assertThat("amount of concurrent pause types", gcDefaultModel.getConcurrentEventPauses().size(), is(0)); + } + + @Test + public void testGcDefaultMetadataGcThreshold() { + // Default gc log gives no pause time or total heap size + AbstractGCEvent metadataGcThresholdEvent = gcDefaultModel.get(0); + UnittestHelper.testMemoryPauseEvent(metadataGcThresholdEvent, + "Metadata GC Threshold heap", + AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION, + 0, + 1024 * 106, 1024 * 88, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcDefaultWarmup() { + AbstractGCEvent warmupEvent = gcDefaultModel.get(1); + UnittestHelper.testMemoryPauseEvent(warmupEvent, + "Warmup heap", + AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION, + 0, + 1024 * 208, 1024 * 164, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcDefaultProactive() { + AbstractGCEvent proactiveEvent = gcDefaultModel.get(2); + UnittestHelper.testMemoryPauseEvent(proactiveEvent, + "Proactive heap", + AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION, + 0, + 1024 * 19804, 1024 * 20212, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testGcDefaultAllocationRate() { + AbstractGCEvent allocationRateEvent = gcDefaultModel.get(3); + UnittestHelper.testMemoryPauseEvent(allocationRateEvent, + "Allocation Rate heap", + AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION, + 0, + 1024 * 502, 1024 * 716, 0, + AbstractGCEvent.Generation.TENURED, + false); + } + + @Test + public void testDefaultGcSystemGc() { + AbstractGCEvent systemGcEvent = gcDefaultModel.get(4); + UnittestHelper.testMemoryPauseEvent(systemGcEvent, + "System.gc() heap", + AbstractGCEvent.Type.UJL_ZGC_GARBAGE_COLLECTION, + 0, + 1024 * 10124, 1024 * 5020, 0, + AbstractGCEvent.Generation.TENURED, + false); + } +} \ No newline at end of file diff --git a/src/test/java/com/tagtraum/perf/gcviewer/model/TestAbstractGCEvent.java b/src/test/java/com/tagtraum/perf/gcviewer/model/TestAbstractGCEvent.java index 9fd82fb7..ae2832bd 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/model/TestAbstractGCEvent.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/model/TestAbstractGCEvent.java @@ -1,6 +1,7 @@ package com.tagtraum.perf.gcviewer.model; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertTrue; import static org.junit.Assert.assertThat; import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType; @@ -11,7 +12,7 @@ /** * Tests for methods written in {@link AbstractGCEvent}. - * + * * @author Joerg Wuethrich *

created on: 30.09.2012

*/ @@ -25,12 +26,12 @@ public void getGenerationParNew() { GCEvent parNewEvent = new GCEvent(); parNewEvent.setType(Type.PAR_NEW); - + event.add(parNewEvent); - + assertEquals("generation", Generation.YOUNG, event.getGeneration()); } - + @Test public void getGenerationCmsInitialMark() { // 6.765: [GC [1 CMS-initial-mark: 0K(25165824K)] 410644K(47815104K), 0.0100670 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] @@ -39,12 +40,12 @@ public void getGenerationCmsInitialMark() { GCEvent CmsInitialMarkEvent = new GCEvent(); CmsInitialMarkEvent.setType(Type.CMS_INITIAL_MARK); - + event.add(CmsInitialMarkEvent); - + assertEquals("generation", Generation.TENURED, event.getGeneration()); } - + @Test public void getGenerationCmsRemark() { // 12.203: [GC[YG occupancy: 11281900 K (22649280 K)]12.203: [Rescan (parallel) , 0.3773770 secs]12.580: [weak refs processing, 0.0000310 secs]12.580: [class unloading, 0.0055480 secs]12.586: [scrub symbol & string tables, 0.0041920 secs] [1 CMS-remark: 0K(25165824K)] 11281900K(47815104K), 0.3881550 secs] [Times: user=17.73 sys=0.04, real=0.39 secs] @@ -53,12 +54,12 @@ public void getGenerationCmsRemark() { GCEvent CmsRemarkEvent = new GCEvent(); CmsRemarkEvent.setType(Type.CMS_REMARK); - + event.add(CmsRemarkEvent); - + assertEquals("generation", Generation.TENURED, event.getGeneration()); } - + @Test public void getGenerationConcurrentMarkStart() { // 3749.995: [CMS-concurrent-mark-start] @@ -67,7 +68,7 @@ public void getGenerationConcurrentMarkStart() { assertEquals("generation", Generation.TENURED, event.getGeneration()); } - + @Test public void getGenerationFullGc() { // 2012-04-07T01:14:29.222+0000: 37571.083: [Full GC [PSYoungGen: 21088K->0K(603712K)] [PSOldGen: 1398086K->214954K(1398144K)] 1419174K->214954K(2001856K) [PSPermGen: 33726K->33726K(131072K)], 0.4952250 secs] [Times: user=0.49 sys=0.00, real=0.49 secs] @@ -77,34 +78,66 @@ public void getGenerationFullGc() { GCEvent detailedEvent = new GCEvent(); detailedEvent.setType(Type.PS_YOUNG_GEN); event.add(detailedEvent); - + detailedEvent = new GCEvent(); detailedEvent.setType(Type.PS_OLD_GEN); event.add(detailedEvent); - + detailedEvent = new GCEvent(); detailedEvent.setType(Type.PS_PERM_GEN); event.add(detailedEvent); - + assertEquals("generation", Generation.ALL, event.getGeneration()); } - + @Test public void addExtendedTypePrintGcCause() { // 2013-05-25T17:02:46.238+0200: 0.194: [GC (Allocation Failure) [PSYoungGen: 16430K->2657K(19136K)] 16430K->15759K(62848K), 0.0109373 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] GCEvent event = new GCEvent(); event.setExtendedType(ExtendedType.lookup(Type.GC, "GC (Allocation Failure)")); - + GCEvent detailedEvent = new GCEvent(); detailedEvent.setType(Type.PS_YOUNG_GEN); - + event.add(detailedEvent); - + assertEquals("typeAsString", "GC (Allocation Failure); PSYoungGen", event.getTypeAsString()); } @Test - public void isFullShenandoah() throws Exception { + public void isFullShenandoah() { + AbstractGCEvent event = getNewAbstractEvent(); + + event.setType(Type.UJL_PAUSE_FULL); + assertThat("should be full gc", event.isFull(), Matchers.is(true)); + } + + @Test + public void testInitialPhaseList() { + AbstractGCEvent event = getNewAbstractEvent(); + + assertTrue("phases list is empty", event.getPhases().isEmpty()); + } + + @Test(expected = IllegalArgumentException.class) + public void testAddNullPhase() { + AbstractGCEvent event = getNewAbstractEvent(); + event.addPhase(null); + } + + @Test + public void testAddValidPhase() { + AbstractGCEvent event = getNewAbstractEvent(); + + GCEvent phaseEvent = new GCEvent(161.23, 0, 0, 0, 0.0004235, Type.UJL_ZGC_PAUSE_MARK_START); + + event.addPhase(phaseEvent); + + assertEquals("number of phase events", 1, event.getPhases().size()); + assertEquals("get phase event", phaseEvent, event.getPhases().get(0)); + } + + private AbstractGCEvent getNewAbstractEvent() { AbstractGCEvent event = new AbstractGCEvent() { @Override public void toStringBuffer(StringBuffer sb) { @@ -112,7 +145,6 @@ public void toStringBuffer(StringBuffer sb) { } }; - event.setType(Type.UJL_PAUSE_FULL); - assertThat("should be full gc", event.isFull(), Matchers.is(true)); + return event; } } diff --git a/src/test/java/com/tagtraum/perf/gcviewer/model/TestGCEventUJL.java b/src/test/java/com/tagtraum/perf/gcviewer/model/TestGCEventUJL.java new file mode 100644 index 00000000..4f190628 --- /dev/null +++ b/src/test/java/com/tagtraum/perf/gcviewer/model/TestGCEventUJL.java @@ -0,0 +1,95 @@ +package com.tagtraum.perf.gcviewer.model; + +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type; + +import static org.hamcrest.Matchers.closeTo; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertThat; + +public class TestGCEventUJL { + private GCEventUJL parentGCEvent; + + @Before + public void setUp() { + parentGCEvent = createGcEventUJL(87.11, 120390, 67880, 194540, 0, Type.UJL_ZGC_GARBAGE_COLLECTION); + } + + @After + public void tearDown() { + parentGCEvent = null; + } + + @Test + public void addPhaseSerial() { + GCEvent gcEventSerial = createGcEventUJL(101.53, 0, 0, 0, 0.0053923, Type.UJL_ZGC_PAUSE_MARK_START); + parentGCEvent.addPhase(gcEventSerial); + + assertEquals("size of phases list", 1, parentGCEvent.getPhases().size()); + assertEquals("phase event", gcEventSerial, parentGCEvent.getPhases().get(0)); + + assertThat("total phases pause time", 0.0053923, closeTo(parentGCEvent.getPause(), 0.00001)); + } + + @Test + public void addPhaseNonSerial() { + ConcurrentGCEvent gcEventConcurrent = createConcurrentGcEvent(101.53, 0, 0, 0, 0.0053923, Type.UJL_ZGC_CONCURRENT_MARK); + parentGCEvent.addPhase(gcEventConcurrent); + + assertEquals("size of phases list", 1, parentGCEvent.getPhases().size()); + assertEquals("phase event", gcEventConcurrent, parentGCEvent.getPhases().get(0)); + + assertThat("total phases pause time", 0d, closeTo(parentGCEvent.getPause(), 0.00001)); + } + + @Test + public void addMultiplePhases() { + GCEvent gcEventSerialMarkStart = createGcEventUJL(101.53, 0, 0, 0, 0.0053923, Type.UJL_ZGC_PAUSE_MARK_START); + GCEvent gcEventSerialMarkEnd = createGcEventUJL(107.67, 0, 0, 0, 0.0037829, Type.UJL_ZGC_PAUSE_MARK_END); + GCEvent gcEventSerialRelocateStart = createGcEventUJL(108.17, 0, 0, 0, 0.0061948, Type.UJL_ZGC_PAUSE_RELOCATE_START); + ConcurrentGCEvent gcEventConcurrentMark = createConcurrentGcEvent(109.24, 0, 0, 0, 0.7164831, Type.UJL_ZGC_CONCURRENT_MARK); + ConcurrentGCEvent gcEventConcurrentRelocate = createConcurrentGcEvent(109.88, 0, 0, 0, 0.6723152, Type.UJL_ZGC_CONCURRENT_RELOCATE); + + parentGCEvent.addPhase(gcEventSerialMarkStart); + parentGCEvent.addPhase(gcEventSerialMarkEnd); + parentGCEvent.addPhase(gcEventSerialRelocateStart); + parentGCEvent.addPhase(gcEventConcurrentMark); + parentGCEvent.addPhase(gcEventConcurrentRelocate); + + assertEquals("size of phases list", 5, parentGCEvent.getPhases().size()); + assertEquals("phase event 1", gcEventSerialMarkStart, parentGCEvent.getPhases().get(0)); + assertEquals("phase event 2", gcEventSerialMarkEnd, parentGCEvent.getPhases().get(1)); + assertEquals("phase event 3", gcEventSerialRelocateStart, parentGCEvent.getPhases().get(2)); + assertEquals("phase event 4", gcEventConcurrentMark, parentGCEvent.getPhases().get(3)); + assertEquals("phase event 5", gcEventConcurrentRelocate, parentGCEvent.getPhases().get(4)); + + assertThat("total phases pause time", 0.01537, closeTo(parentGCEvent.getPause(), 0.00001)); + } + + private GCEventUJL createGcEventUJL(double timestamp, int preUsed, int postUsed, int total, double pause, Type type) { + GCEventUJL gcEventUJL = new GCEventUJL(); + gcEventUJL.setTimestamp(timestamp); + gcEventUJL.setPreUsed(preUsed); + gcEventUJL.setPostUsed(postUsed); + gcEventUJL.setTotal(total); + gcEventUJL.setPause(pause); + gcEventUJL.setType(type); + + return gcEventUJL; + } + + private ConcurrentGCEvent createConcurrentGcEvent(double timestamp, int preUsed, int postUsed, int total, double pause, Type type) { + ConcurrentGCEvent concurrentGCEvent = new ConcurrentGCEvent(); + concurrentGCEvent.setTimestamp(timestamp); + concurrentGCEvent.setPreUsed(preUsed); + concurrentGCEvent.setPostUsed(postUsed); + concurrentGCEvent.setTotal(total); + concurrentGCEvent.setPause(pause); + concurrentGCEvent.setType(type); + + return concurrentGCEvent; + } +} diff --git a/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-zgc-gc-all.txt b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-zgc-gc-all.txt new file mode 100644 index 00000000..64726f65 --- /dev/null +++ b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-zgc-gc-all.txt @@ -0,0 +1,14 @@ +[0.995s][info][gc] Using The Z Garbage Collector +[1.205s][info][gc,start] GC(0) Garbage Collection (Metadata GC Threshold) +[1.206s][info][gc,phases] GC(0) Pause Mark Start 1.279ms +[1.211s][info][gc,phases] GC(0) Concurrent Mark 5.216ms +[1.212s][info][gc,phases] GC(0) Pause Mark End 0.695ms +[1.212s][info][gc,phases] GC(0) Concurrent Process Non-Strong References 0.258ms +[1.212s][info][gc,phases] GC(0) Concurrent Reset Relocation Set 0.001ms +[1.212s][info][gc,phases] GC(0) Concurrent Destroy Detached Pages 0.001ms +[1.216s][info][gc,phases] GC(0) Concurrent Select Relocation Set 3.822ms +[1.217s][info][gc,phases] GC(0) Concurrent Prepare Relocation Set 0.865ms +[1.218s][info][gc,phases] GC(0) Pause Relocate Start 0.679ms +[1.221s][info][gc,phases] GC(0) Concurrent Relocate 2.846ms +[1.221s][info][gc,heap ] GC(0) Capacity: 194560M (100%) 194560M (100%) 194560M (100%) 194560M (100%) 194560M (100%) 194560M (100%) +[1.221s][info][gc ] GC(0) Garbage Collection (Metadata GC Threshold) 10620M(5%)->8800M(4%) \ No newline at end of file diff --git a/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-zgc-gc-default.txt b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-zgc-gc-default.txt new file mode 100644 index 00000000..dde7d263 --- /dev/null +++ b/src/test/resources/openjdk/unified-jvm-logging/sample-ujl-zgc-gc-default.txt @@ -0,0 +1,6 @@ +[0.995s][info][gc] Using The Z Garbage Collector +[1.221s][info][gc] GC(0) Garbage Collection (Metadata GC Threshold) 106M(0%)->88M(0%) +[2,048s][info][gc] GC(1) Garbage Collection (Warmup) 208M(20%)->164M(16%) +[2.607s][info][gc] GC(2) Garbage Collection (Proactive) 19804M(10%)->20212M(10%) +[3,167s][info][gc] GC(3) Garbage Collection (Allocation Rate) 502M(49%)->716M(70%) +[3,742s][info][gc] GC(4) Garbage Collection (System.gc()) 10124M(10%)->5020M(5%) \ No newline at end of file