diff --git a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/event/evnetInfo/CpuTime.java b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/event/evnetInfo/CpuTime.java index 0253c497..08441589 100644 --- a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/event/evnetInfo/CpuTime.java +++ b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/event/evnetInfo/CpuTime.java @@ -32,4 +32,12 @@ public String toString() { return String.format("User=%.2fs Sys=%.2fs Real=%.2fs", user / 1000, sys / 1000, real / 1000); } + public double getValue(String type) { + return switch (type) { + case "USER" -> user; + case "SYS" -> sys; + case "REAL" -> real; + default -> 0; + }; + } } diff --git a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/Context.java b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/Context.java new file mode 100644 index 00000000..cf7a67ef --- /dev/null +++ b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/Context.java @@ -0,0 +1,132 @@ +/******************************************************************************** + * Copyright (c) 2023 Contributors to the Eclipse Foundation + * + * See the NOTICE file(s) distributed with this work for additional + * information regarding copyright ownership. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0 + * + * SPDX-License-Identifier: EPL-2.0 + ********************************************************************************/ +package org.eclipse.jifa.gclog.fragment; + +import com.google.common.collect.ImmutableSet; + +import java.io.BufferedReader; +import java.io.ByteArrayInputStream; +import java.io.InputStream; +import java.io.InputStreamReader; +import java.util.Comparator; +import java.util.List; +import java.util.Set; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + +public class Context { + private List context; + private final ContextComparator contextComparator = new ContextComparator(); + + private Pattern timestampPattern; + + public Context(List context) throws RuntimeException{ + this.context = context; + selectTimestampPattern(); + sort(); + } + + public BufferedReader toBufferedReader() { + String joinedString = String.join("\n", context); + InputStream inputStream = new ByteArrayInputStream(joinedString.getBytes()); + return new BufferedReader(new InputStreamReader(inputStream)); + } + + private void selectTimestampPattern() throws RuntimeException{ + /* to match the following timestamp pattern: + [2023-08-25T14:28:44.980+0800][0.076s] GC(374) Pause Mark Start 4.459ms + 2022-11-28T14:57:05.341+0800: 6.340: [CMS-concurrent-mark-start] + [7.006s] GC(374) Pause Mark Start 4.459ms + 675.461: [CMS-concurrent-mark-start] + */ + Pattern[] timestampPatternToChoose = { + Pattern.compile("\\[[\\d-T:+.]+]\\[(\\d+\\.\\d+)s][\\s\\S]*"), + Pattern.compile("[\\d-T:+.]+ (\\d+\\.\\d+): \\[[\\s\\S]*"), + Pattern.compile("\\[(\\d+\\.\\d+)s][\\s\\S]*"), + Pattern.compile("(\\d+\\.\\d+): \\[[\\s\\S]*") + }; + for (String str : context) { + for (Pattern pattern : timestampPatternToChoose) { + if (pattern.matcher(str).matches()) { + timestampPattern = pattern; + return; + } + } + } + throw new RuntimeException("fail to parse timestamp"); + } + + class ContextComparator implements Comparator { + + boolean isPrecedent(String str) { + Set precedentPatternSet = new ImmutableSet.Builder().add("Pause Young", "Pause Initial Mark", "Concurrent Cycle", "Concurrent Mark").build(); + return precedentPatternSet.stream().anyMatch(str::contains); + } + /* + return value: + 1: place string2 in prior to string1 + -1: place string1 in prior to string2 + */ + @Override + public int compare(String o1, String o2) { + Matcher matcher; + String timestampString1, timestampString2; + if ((matcher = timestampPattern.matcher(o1)).matches()) { + timestampString1 = matcher.group(1); + } else { + // string2 in prior to string1: + // string1 doesn't match, thus place it at the tail of the list. + return 1; + } + if ((matcher = timestampPattern.matcher(o2)).matches()) { + timestampString2 = matcher.group(1); + } else { + // place string1 in prior to string2: + // string2 doesn't match, thus place string1 before it. + return -1; + } + //return Double.parseDouble(timestampString1) > Double.parseDouble(timestampString2) ? 1 : -1; + if (timestampString1.equals(timestampString2)) { + if (isPrecedent(o1)) { + // place string1 in prior to string2: + return -1; + } + if (isPrecedent(o2)) { + // place string2 in prior to string1: + return 1; + } + return 0; + } else { + return Double.parseDouble(timestampString1) > Double.parseDouble(timestampString2) ? 1 : -1; + } + } + } + + private void sort() { + context.sort(contextComparator); + } + + // for debug + private void checkStartWithTimeStamp() { + for (String str : context) { + if (!timestampPattern.matcher(str).matches()) { + throw new RuntimeException("found invalid string which doesn't start with a required timestamp: " + str); + } + } + } + + // for debug + private void filterInvalidFragment() { + context.removeIf(str -> !timestampPattern.matcher(str).matches()); + } +} diff --git a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/GCLogAnalyzer.java b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/GCLogAnalyzer.java new file mode 100644 index 00000000..5f99dcc4 --- /dev/null +++ b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/GCLogAnalyzer.java @@ -0,0 +1,78 @@ +/******************************************************************************** + * Copyright (c) 2023 Contributors to the Eclipse Foundation + * + * See the NOTICE file(s) distributed with this work for additional + * information regarding copyright ownership. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0 + * + * SPDX-License-Identifier: EPL-2.0 + ********************************************************************************/ +package org.eclipse.jifa.gclog.fragment; + +import lombok.NoArgsConstructor; +import lombok.extern.slf4j.Slf4j; +import org.eclipse.jifa.gclog.model.GCModel; +import org.eclipse.jifa.gclog.parser.GCLogParser; +import org.eclipse.jifa.gclog.parser.GCLogParserFactory; + +import java.io.*; +import java.util.*; + +@NoArgsConstructor +@Slf4j +public class GCLogAnalyzer { + private final Map, GCLogParser> parserMap = new HashMap<>(); + + public List parseToMetrics(List rawContext, Map instanceId, long startTime, long endTime) throws Exception { + Context context = new Context(rawContext); + BufferedReader br = context.toBufferedReader(); + GCLogParser parser = selectParser(instanceId, br); + GCModel model = parser.parse(br); + br.close(); + if (!model.isEmpty()) { + model.calculateDerivedInfo(null); + return new GCModelConverter().toMetrics(model, instanceId, startTime, endTime); + } + return null; + } + + public GCModel parseToGCModel(List rawContext) { + Context context = new Context(rawContext); + BufferedReader br = context.toBufferedReader(); + GCModel model = null; + try { + GCLogParser parser = selectParser(null, br); + model = parser.parse(br); + br.close(); + if (!model.isEmpty()) { + model.calculateDerivedInfo(null); + } else { + model = null; + } + } catch (Exception e) { + log.error("fail to parse context "); + log.error(e.getMessage()); + model = null; + } finally { + return model; + } + } + + private GCLogParser selectParser(Map instanceId, BufferedReader br) throws IOException { + GCLogParser parser = parserMap.get(instanceId); + if (parser == null) { + GCLogParserFactory logParserFactory = new GCLogParserFactory(); + // max length in hotspot + int MAX_SINGLE_LINE_LENGTH = 2048; + br.mark(GCLogParserFactory.MAX_ATTEMPT_LINE * MAX_SINGLE_LINE_LENGTH); + parser = logParserFactory.getParser(br); + br.reset(); + parserMap.put(instanceId, parser); + } + return parser; + } +} + diff --git a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/GCModelConverter.java b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/GCModelConverter.java new file mode 100644 index 00000000..6c1d4be5 --- /dev/null +++ b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/GCModelConverter.java @@ -0,0 +1,131 @@ +/******************************************************************************** + * Copyright (c) 2023 Contributors to the Eclipse Foundation + * + * See the NOTICE file(s) distributed with this work for additional + * information regarding copyright ownership. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0 + * + * SPDX-License-Identifier: EPL-2.0 + ********************************************************************************/ +package org.eclipse.jifa.gclog.fragment; + +import com.google.common.collect.ImmutableMap; +import com.google.common.collect.ImmutableSet; +import lombok.extern.slf4j.Slf4j; +import org.eclipse.jifa.gclog.event.GCEvent; +import org.eclipse.jifa.gclog.event.evnetInfo.MemoryArea; +import org.eclipse.jifa.gclog.model.GCModel; + +import org.eclipse.jifa.gclog.util.Constant; + +import java.util.*; + +@Slf4j +public class GCModelConverter { + public List toMetrics(GCModel gcModel, Map instanceId, long startTime, long endTime) { + List result = new ArrayList<>(); + Map sharedLabels = new HashMap<>(instanceId); + sharedLabels.put("gc_type", gcModel.getCollectorType().getName()); + for (GCEvent gcEvent : gcModel.getGcEvents()) { + long timestamp = (long)(gcModel.getReferenceTimestamp() + gcEvent.getStartTime()); + if (timestamp >= startTime && timestamp < endTime) { + result.addAll(new GCEventConverter().toMetrics(gcEvent, timestamp, sharedLabels)); + } + } + return result; + } + + private class GCEventConverter { + private GCEvent gcEvent; + private long timestamp; + private Map sharedLabels; + private List result = new ArrayList<>(); + + public List toMetrics(GCEvent gcEvent, long timestamp, Map sharedLabels) { + this.gcEvent = gcEvent; + this.timestamp = timestamp; + this.sharedLabels = sharedLabels; + addMetricCpuTime(); + addMetricDuration(); + addMetricMemoryUsage(); + addMetricPause(); + addMetricPromotion(); + addMetricSubphase(); + return result; + } + + private Map buildLabel() { + return sharedLabels; + } + private Map buildLabel(String key, String value) { + Map label = new HashMap<>(sharedLabels); + label.put(key, value); + return label; + } + private Map buildLabel(String key1, String value1, String key2, String value2) { + Map label = new HashMap<>(sharedLabels); + label.put(key1, value1); + label.put(key2, value2); + return label; + } + + private void addMetricDuration() { + if (gcEvent.getDuration() == Constant.UNKNOWN_DOUBLE) { + return; + } + result.add(new Metric(timestamp, buildLabel(), "GC_COST_TIME", gcEvent.getDuration())); + } + + private void addMetricPause() { + if (gcEvent.getPause() == Constant.UNKNOWN_DOUBLE) { + return; + } + result.add(new Metric(timestamp, buildLabel("type", gcEvent.getEventType().getName()), "GC_PAUSE_TIME", gcEvent.getPause())); + } + + private void addMetricPromotion() { + if (gcEvent.getPromotion() == Constant.UNKNOWN_INT) { + return; + } + result.add(new Metric(timestamp, buildLabel(), "GC_PROMOTION", gcEvent.getPromotion())); + } + + private void addMetricCpuTime() { + if (gcEvent.getCpuTime() == null) { + return; + } + final Set typeSet = new ImmutableSet.Builder().add("USER", "SYS", "REAL").build(); + typeSet.forEach(type -> + result.add(new Metric(timestamp, buildLabel("type", type), "GC_CPU_USED", gcEvent.getCpuTime().getValue(type))) + ); + } + + private void addMetricMemoryUsage() { + final Map memoryAreaMap = new ImmutableMap.Builder() + .put("Young", MemoryArea.YOUNG) + .put("Old", MemoryArea.OLD) + .put("Heap", MemoryArea.HEAP) + .put("Metaspace", MemoryArea.METASPACE) + .build(); + memoryAreaMap.forEach((key, value) -> { + if (gcEvent.getMemoryItem(value) != null) { + result.add(new Metric(timestamp, buildLabel("type", key), "BEFORE_GC_REGION_SIZE", gcEvent.getMemoryItem(value).getPreUsed())); + result.add(new Metric(timestamp, buildLabel("type", key), "AFTER_GC_REGION_SIZE", gcEvent.getMemoryItem(value).getPostUsed())); + } + }); + } + + private void addMetricSubphase() { + if (gcEvent.getPhases() == null) { + return; + } + gcEvent.getPhases().forEach(subphase -> + result.add(new Metric(timestamp, + buildLabel("subphase", subphase.getEventType().getName(), "type", gcEvent.getEventType().getName()), + "GC_SUBPHASE_TIME", subphase.getDuration()))); + } + } +} diff --git a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/Metric.java b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/Metric.java new file mode 100644 index 00000000..4e1e7370 --- /dev/null +++ b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/fragment/Metric.java @@ -0,0 +1,27 @@ +/******************************************************************************** + * Copyright (c) 2023 Contributors to the Eclipse Foundation + * + * See the NOTICE file(s) distributed with this work for additional + * information regarding copyright ownership. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0 + * + * SPDX-License-Identifier: EPL-2.0 + ********************************************************************************/ +package org.eclipse.jifa.gclog.fragment; + +import lombok.AllArgsConstructor; +import lombok.Getter; + +import java.util.Map; + +@AllArgsConstructor +@Getter +public class Metric { + long timestamp; + Map label; + String name; + double value; +} diff --git a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/parser/GCLogParserFactory.java b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/parser/GCLogParserFactory.java index a7867bdf..97a8558c 100644 --- a/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/parser/GCLogParserFactory.java +++ b/analysis/gc-log/src/main/java/org/eclipse/jifa/gclog/parser/GCLogParserFactory.java @@ -35,7 +35,7 @@ public class GCLogParserFactory { // When -Xlog:gc*=trace is used, a single gc produces at most about 5000 lines of log. // 20000 lines should be enough to cover at least one gc. - static final int MAX_ATTEMPT_LINE = 20000; + public static final int MAX_ATTEMPT_LINE = 20000; private static final ParserMetadataRule[] rules = { // style diff --git a/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToGCModel.java b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToGCModel.java new file mode 100644 index 00000000..62377551 --- /dev/null +++ b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToGCModel.java @@ -0,0 +1,157 @@ +/******************************************************************************** + * Copyright (c) 2023 Contributors to the Eclipse Foundation + * + * See the NOTICE file(s) distributed with this work for additional + * information regarding copyright ownership. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0 + * + * SPDX-License-Identifier: EPL-2.0 + ********************************************************************************/ +package org.eclipse.jifa.gclog; + +import com.google.common.collect.ImmutableSet; +import lombok.extern.slf4j.Slf4j; +import org.eclipse.jifa.analysis.listener.DefaultProgressListener; +import org.eclipse.jifa.gclog.event.GCEvent; +import org.eclipse.jifa.gclog.event.evnetInfo.MemoryArea; +import org.eclipse.jifa.gclog.fragment.GCLogAnalyzer; +import org.eclipse.jifa.gclog.model.*; +import org.eclipse.jifa.gclog.parser.*; + +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import java.util.*; + +import static org.eclipse.jifa.gclog.TestUtil.generateShuffledGCLog; +import static org.eclipse.jifa.gclog.event.evnetInfo.MemoryArea.*; + +/* +This test aims the same as TestFragmentedParserToGCModelLegacy. +Instead of checking each field with so many Assertions.assertEquals, this test barely compares both GC Models +produced by normal parser and fragmented parser. However, considering the large amount of fields in GC Event, +compareGCModel() only takes fields related with Metric into account. +Also, gclog of jdk11 and 17 and 8 with serialGC are excluded for the time being. Furthermore, by design, +IncompleteGCLog and 11_CMS gclogs are not supported. + */ + +@Slf4j +public class TestFragmentedParserToGCModel { + public static final double DELTA = 1e-6; + + @Test + public void test() throws Exception { + Set gcLogSet = new ImmutableSet.Builder(). + add("11G1Parser.log", + "8CMSParser.log", "8CMSPrintGC.log", "8G1PrintGC.log", "8ParallelGCParser.log", "8G1GCParser.log", + "8G1GCParserAdaptiveSize.log", "8ConcurrentPrintDateTimeStamp.log", + "8CMSCPUTime.log", "8CMSPromotionFailed.log", + "8CMSScavengeBeforeRemark.log", "8GenerationalGCInterleave.log").build(); + for (String gclog : gcLogSet) { + compareGCModel(parseByNormalParser(gclog), parseByFragmentedParser(generateShuffledGCLog(gclog))); + } + } + + private void compareGCModel(GCModel left, GCModel right) { + Assertions.assertEquals(left.getGcEvents().size(), right.getGcEvents().size()); + for (int i = 0; i < left.getGcEvents().size(); i++) { + GCEvent l = left.getGcEvents().get(i), r = right.getGcEvents().get(i); + Assertions.assertEquals(l.getGcid(), r.getGcid()); + Assertions.assertEquals(l.getStartTime(), r.getStartTime(), DELTA); + Assertions.assertEquals(l.getDuration(), r.getDuration(), DELTA); + Assertions.assertEquals(l.getPromotion(), r.getPromotion()); + Assertions.assertEquals(l.getPause(), r.getPause(), DELTA); + Assertions.assertEquals(l.toString(), r.toString()); + compareCpuTime(l, r); + compareCause(l, r); + compareEventType(l, r); + compareMemoryArea(l, r); + compareSubPhase(l, r); + compareReferenceGC(l, r); + } + } + + private void compareSubPhase(GCEvent l, GCEvent r) { + if (l.getPhases() == null) { + Assertions.assertNull(r.getPhases()); + return; + } + Assertions.assertEquals(l.getPhases().size(), r.getPhases().size()); + for (GCEvent gcEvent : l.getPhases()) { + boolean find = false; + for (GCEvent another : r.getPhases()) { + if (gcEvent.getEventType().getName().equals(another.getEventType().getName())) { + find = true; + Assertions.assertEquals(gcEvent.getDuration(), another.getDuration(), DELTA); + break; + } + } + Assertions.assertTrue(find); + } + } + + private void compareMemoryArea(GCEvent l, GCEvent r) { + for (MemoryArea memoryArea : new MemoryArea[]{YOUNG, OLD, HEAP, METASPACE}) { + if (l.getMemoryItem(memoryArea) == null) { + Assertions.assertNull(r.getMemoryItem(memoryArea)); + continue; + } + Assertions.assertEquals(l.getMemoryItem(memoryArea), r.getMemoryItem(memoryArea)); + } + } + + private void compareReferenceGC(GCEvent l, GCEvent r) { + if (l.getReferenceGC() == null) { + Assertions.assertNull(r.getReferenceGC()); + return; + } + Assertions.assertEquals(l.getReferenceGC().getSoftReferenceCount(), r.getReferenceGC().getSoftReferenceCount()); + Assertions.assertEquals(l.getReferenceGC().getSoftReferencePauseTime(), r.getReferenceGC().getSoftReferencePauseTime(), DELTA); + Assertions.assertEquals(l.getReferenceGC().getWeakReferenceCount(), r.getReferenceGC().getWeakReferenceCount()); + Assertions.assertEquals(l.getReferenceGC().getWeakReferencePauseTime(), r.getReferenceGC().getWeakReferencePauseTime(), DELTA); + Assertions.assertEquals(l.getReferenceGC().getFinalReferenceCount(), r.getReferenceGC().getFinalReferenceCount()); + Assertions.assertEquals(l.getReferenceGC().getFinalReferencePauseTime(), r.getReferenceGC().getFinalReferencePauseTime(), DELTA); + Assertions.assertEquals(l.getReferenceGC().getPhantomReferenceCount(), r.getReferenceGC().getPhantomReferenceCount()); + Assertions.assertEquals(l.getReferenceGC().getPhantomReferencePauseTime(), r.getReferenceGC().getPhantomReferencePauseTime(), DELTA); + Assertions.assertEquals(l.getReferenceGC().getPhantomReferenceFreedCount(), r.getReferenceGC().getPhantomReferenceFreedCount()); + Assertions.assertEquals(l.getReferenceGC().getJniWeakReferencePauseTime(), r.getReferenceGC().getJniWeakReferencePauseTime(), DELTA); + } + + private void compareCpuTime(GCEvent l, GCEvent r) { + if (l.getCpuTime() == null) { + Assertions.assertNull(r.getCpuTime()); + return; + } + Assertions.assertEquals(l.getCpuTime().toString(), r.getCpuTime().toString()); + } + + private void compareCause(GCEvent l, GCEvent r) { + if (l.getCause() == null) { + Assertions.assertNull(r.getCause()); + return; + } + Assertions.assertEquals(l.getCause().getName(), r.getCause().getName()); + } + + private void compareEventType(GCEvent l, GCEvent r) { + if (l.getEventType() == null) { + Assertions.assertNull(r.getEventType()); + return; + } + Assertions.assertEquals(l.getEventType().getName(), r.getEventType().getName()); + } + + private GCModel parseByFragmentedParser(List context) { + return new GCLogAnalyzer().parseToGCModel(context); + } + + private GCModel parseByNormalParser(String name) throws Exception { + GCLogParser gcLogParser = new GCLogParserFactory().getParser(TestUtil.getGCLog(name)); + GCModel model = gcLogParser.parse(TestUtil.getGCLog(name)); + model.calculateDerivedInfo(new DefaultProgressListener()); + return model; + } +} diff --git a/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToGCModelLegacy.java b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToGCModelLegacy.java new file mode 100644 index 00000000..1dd54a33 --- /dev/null +++ b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToGCModelLegacy.java @@ -0,0 +1,541 @@ +/******************************************************************************** + * Copyright (c) 2023 Contributors to the Eclipse Foundation + * + * See the NOTICE file(s) distributed with this work for additional + * information regarding copyright ownership. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0 + * + * SPDX-License-Identifier: EPL-2.0 + ********************************************************************************/ +package org.eclipse.jifa.gclog; + +import lombok.extern.slf4j.Slf4j; +import org.eclipse.jifa.gclog.event.GCEvent; +import org.eclipse.jifa.gclog.event.Safepoint; +import org.eclipse.jifa.gclog.event.evnetInfo.GCMemoryItem; +import org.eclipse.jifa.gclog.fragment.GCLogAnalyzer; +import org.eclipse.jifa.gclog.model.*; +import org.eclipse.jifa.gclog.model.modeInfo.GCCollectorType; +import org.eclipse.jifa.gclog.model.modeInfo.GCLogMetadata; +import org.eclipse.jifa.gclog.vo.PauseStatistics; +import org.eclipse.jifa.gclog.vo.TimeRange; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import java.util.*; + +import static org.eclipse.jifa.gclog.event.evnetInfo.GCCause.*; +import static org.eclipse.jifa.gclog.event.evnetInfo.GCCause.ALLOCATION_FAILURE; +import static org.eclipse.jifa.gclog.event.evnetInfo.GCEventBooleanType.TO_SPACE_EXHAUSTED; +import static org.eclipse.jifa.gclog.event.evnetInfo.GCEventBooleanType.YOUNG_GC_BECOME_FULL_GC; +import static org.eclipse.jifa.gclog.event.evnetInfo.MemoryArea.*; +import static org.eclipse.jifa.gclog.event.evnetInfo.MemoryArea.HEAP; +import static org.eclipse.jifa.gclog.util.Constant.UNKNOWN_DOUBLE; + +/* +This test borrowed assertions from TestParser, and expects fragment.GCLogAnalyzer +to produce the same result as normal GCLogAnalyzer. +Be advised that assertions about GCEvent.getPhases are excluded, since fragment.GCLogAnalyzer +doesn't guarantee the same order. +Also, gclog of jdk11 and 17 and 8 with serialGC are excluded for the time being. + */ + +@Slf4j +public class TestFragmentedParserToGCModelLegacy { + public static final double DELTA = 1e-6; + + private GCModel parse(List context) { + return new GCLogAnalyzer().parseToGCModel(context); + } + + @Test + public void testJDK11CMSGCParser() throws Exception { + List log = TestUtil.generateShuffledGCLog("11CMSGCParser.log"); + Assertions.assertEquals(log.size(), 38); + + CMSGCModel model = (CMSGCModel) parse(log); + Assertions.assertNotNull(model); + Assertions.assertEquals(model.getGcEvents().size(), 3); + Assertions.assertEquals(model.getParallelThread(), 8); + Assertions.assertEquals(model.getConcurrentThread(), 2); + + GCEvent youngGC = model.getGcEvents().get(0); + Assertions.assertEquals(youngGC.getGcid(), 0); + Assertions.assertEquals(youngGC.getStartTime(), 479, DELTA); + Assertions.assertEquals(youngGC.getDuration(), 31.208, DELTA); + Assertions.assertEquals(youngGC.getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(youngGC.getCause(), ALLOCATION_FAILURE); + Assertions.assertEquals(youngGC.getMemoryItem(YOUNG), new GCMemoryItem(YOUNG, 69952 * 1024, 8703 * 1024, 78656 * 1024)); + Assertions.assertEquals(youngGC.getMemoryItem(OLD), new GCMemoryItem(OLD, 0, 24072 * 1024, 174784 * 1024)); + Assertions.assertEquals(youngGC.getMemoryItem(METASPACE), new GCMemoryItem(METASPACE, 6531 * 1024, 6530 * 1024, 1056768 * 1024)); + Assertions.assertEquals(youngGC.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 68 * 1024 * 1024, 32 * 1024 * 1024, 247 * 1024 * 1024)); + Assertions.assertEquals(youngGC.getCpuTime().getReal(), 30, DELTA); + + GCEvent cms = model.getGcEvents().get(1); + Assertions.assertEquals(cms.getGcid(), 1); + Assertions.assertEquals(cms.getEventType(), GCEventType.CMS_CONCURRENT_MARK_SWEPT); + Assertions.assertEquals(cms.getStartTime(), 3231, DELTA); + Assertions.assertEquals(cms.getPhases().size(), 6); + + GCEvent fullGC = model.getGcEvents().get(2); + Assertions.assertEquals(fullGC.getGcid(), 2); + Assertions.assertEquals(fullGC.getStartTime(), 8970, DELTA); + Assertions.assertEquals(fullGC.getDuration(), 178.617, DELTA); + Assertions.assertEquals(fullGC.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullGC.getCause(), ALLOCATION_FAILURE); + Assertions.assertEquals(fullGC.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 174 * 1024 * 1024, 166 * 1024 * 1024, 247 * 1024 * 1024)); + Assertions.assertEquals(fullGC.getCpuTime().getReal(), 180, DELTA); + Assertions.assertEquals(fullGC.getPhases().size(), 4); + } + + @Test + public void testJDK11G1Parser() throws Exception { + List log = TestUtil.generateShuffledGCLog("11G1Parser.log"); + Assertions.assertEquals(log.size(), 64); + + G1GCModel model = (G1GCModel) parse(log); + + // assert parsing success + Assertions.assertNotNull(model); + Assertions.assertEquals(model.getGcEvents().size(), 3); + + // assert model info + Assertions.assertEquals(model.getStartTime(), 0.0 * 1000, DELTA); + Assertions.assertEquals(model.getEndTime(), 7.123 * 1000, DELTA); + Assertions.assertEquals(model.getCollectorType(), GCCollectorType.G1); + + Assertions.assertEquals(model.getHeapRegionSize(), 1024 * 1024); + Assertions.assertNull(model.getVmOptions()); + Assertions.assertEquals(model.getParallelThread(), 8); + Assertions.assertEquals(model.getConcurrentThread(), 2); + + // assert events correct + Assertions.assertEquals(model.getSafepoints().size(), 1); + + Safepoint safepoint = model.getSafepoints().get(0); + Assertions.assertEquals(safepoint.getStartTime(), 1010 - 10.1229, DELTA); + Assertions.assertEquals(safepoint.getDuration(), 10.1229, DELTA); + Assertions.assertEquals(safepoint.getTimeToEnter(), 0.0077, DELTA); + + List event = model.getGcEvents(); + GCEvent youngGC = event.get(0); + Assertions.assertEquals(youngGC.getGcid(), 0); + Assertions.assertTrue(youngGC.isTrue(TO_SPACE_EXHAUSTED)); + Assertions.assertEquals(youngGC.getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(youngGC.getStartTime(), 1.0 * 1000, DELTA); + Assertions.assertEquals(youngGC.getPause(), 10.709, DELTA); + Assertions.assertEquals(youngGC.getDuration(), 10.709, DELTA); + Assertions.assertEquals(youngGC.getCause(), METADATA_GENERATION_THRESHOLD); + Assertions.assertEquals(youngGC.getCpuTime().getReal(), 0.01 * 1000, DELTA); + Assertions.assertEquals(youngGC.getPhases().size(), 4); + Assertions.assertEquals(youngGC.getMemoryItem(SURVIVOR) + , new GCMemoryItem(SURVIVOR, 0, 3 * 1024 * 1024, 3 * 1024 * 1024)); + Assertions.assertEquals(youngGC.getMemoryItem(METASPACE) + , new GCMemoryItem(METASPACE, 20679 * 1024, 20679 * 1024, 45056 * 1024)); + Assertions.assertEquals(youngGC.getMemoryItem(HEAP) + , new GCMemoryItem(HEAP, 19 * 1024 * 1024, 4 * 1024 * 1024, 64 * 1024 * 1024)); + Assertions.assertTrue(youngGC.toString().contains("To-space Exhausted")); + + GCEvent concurrentMark = event.get(1); + Assertions.assertEquals(concurrentMark.getGcid(), 1); + Assertions.assertEquals(concurrentMark.getEventType(), GCEventType.G1_CONCURRENT_CYCLE); + Assertions.assertEquals(concurrentMark.getDuration(), 14.256, DELTA); + Assertions.assertEquals(concurrentMark.getPause(), 2.381 + 0.094, DELTA); + + GCEvent fullGC = event.get(2); + Assertions.assertEquals(fullGC.getGcid(), 2); + Assertions.assertEquals(fullGC.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullGC.getStartTime(), 7.055 * 1000, DELTA); + Assertions.assertEquals(fullGC.getPause(), 67.806, DELTA); + Assertions.assertEquals(fullGC.getDuration(), 67.806, DELTA); + Assertions.assertEquals(fullGC.getCause(), G1_EVACUATION_PAUSE); + Assertions.assertEquals(fullGC.getPhases().size(), 4); + + GCLogMetadata metadata = model.getGcModelMetadata(); + Assertions.assertTrue(metadata.getImportantEventTypes().contains(GCEventType.G1_CONCURRENT_REBUILD_REMEMBERED_SETS.getName())); + Assertions.assertFalse(metadata.getImportantEventTypes().contains(GCEventType.G1_CONCURRENT_UNDO_CYCLE.getName())); + } + + @Test + public void testJDK8CMSParser() throws Exception { + List log = TestUtil.generateShuffledGCLog("8CMSParser.log"); + Assertions.assertEquals(log.size(), 30); + + CMSGCModel model = (CMSGCModel) parse(log); + + Assertions.assertNotNull(model); + + Assertions.assertEquals(model.getGcEvents().size(), 10); + Assertions.assertEquals(model.getSafepoints().size(), 1); + + Safepoint safepoint = model.getSafepoints().get(0); + Assertions.assertEquals(safepoint.getStartTime(), 675110 - 0.1215, DELTA); + Assertions.assertEquals(safepoint.getDuration(), 0.1215, DELTA); + Assertions.assertEquals(safepoint.getTimeToEnter(), 0.0271, DELTA); + + GCEvent fullgc = model.getGcEvents().get(0); + Assertions.assertEquals(fullgc.getStartTime(), 610956, DELTA); + Assertions.assertEquals(fullgc.getDuration(), 1027.7002, DELTA); + Assertions.assertEquals(fullgc.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullgc.getCause(), HEAP_DUMP); + Assertions.assertEquals(fullgc.getMemoryItem(METASPACE), new GCMemoryItem(METASPACE, 114217 * 1024, 113775 * 1024, 1153024 * 1024)); + Assertions.assertEquals(fullgc.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 1537414 * 1024, 1388294 * 1024, 4915200L * 1024)); + Assertions.assertEquals(fullgc.getMemoryItem(OLD), new GCMemoryItem(OLD, 324459 * 1024, 175339 * 1024, 3072000L * 1024)); + Assertions.assertEquals(fullgc.getPhases().size(), 4); + Assertions.assertEquals(fullgc.getLastPhaseOfType(GCEventType.WEAK_REFS_PROCESSING).getStartTime(), 611637, DELTA); + Assertions.assertEquals(fullgc.getLastPhaseOfType(GCEventType.WEAK_REFS_PROCESSING).getDuration(), 1.8945, DELTA); + Assertions.assertEquals(fullgc.getCpuTime().getUser(), 1710, DELTA); + Assertions.assertEquals(fullgc.getCpuTime().getSys(), 50, DELTA); + Assertions.assertEquals(fullgc.getCpuTime().getReal(), 1030, DELTA); + + fullgc = model.getGcEvents().get(8); + Assertions.assertEquals(fullgc.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullgc.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 3956586L * 1024, 1051300 * 1024, 4019584L * 1024)); + + GCEvent youngGC = model.getGcEvents().get(9); + Assertions.assertEquals(youngGC.getStartTime(), 813396, DELTA); + Assertions.assertEquals(youngGC.getDuration(), 10.5137, DELTA); + Assertions.assertEquals(youngGC.getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(youngGC.getCause(), ALLOCATION_FAILURE); + Assertions.assertEquals(youngGC.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 69952 * 1024, 11354 * 1024, 253440 * 1024)); + Assertions.assertEquals(youngGC.getMemoryItem(YOUNG), new GCMemoryItem(YOUNG, 69952 * 1024, 8704 * 1024, 78656 * 1024)); + Assertions.assertNull(youngGC.getPhases()); + Assertions.assertEquals(youngGC.getReferenceGC().getSoftReferenceStartTime(), 813404, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getSoftReferencePauseTime(), 0.0260, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getSoftReferenceCount(), 4); + Assertions.assertEquals(youngGC.getReferenceGC().getWeakReferenceStartTime(), 813405, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getWeakReferencePauseTime(), 0.0110, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getWeakReferenceCount(), 59); + Assertions.assertEquals(youngGC.getReferenceGC().getFinalReferenceStartTime(), 813406, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getFinalReferencePauseTime(), 2.5979, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getFinalReferenceCount(), 1407); + Assertions.assertEquals(youngGC.getReferenceGC().getPhantomReferenceStartTime(), 813407, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getPhantomReferencePauseTime(), 0.0131, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getPhantomReferenceCount(), 11); + Assertions.assertEquals(youngGC.getReferenceGC().getPhantomReferenceFreedCount(), 10); + Assertions.assertEquals(youngGC.getReferenceGC().getJniWeakReferenceStartTime(), 813408, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getJniWeakReferencePauseTime(), 0.0088, DELTA); + Assertions.assertEquals(youngGC.getCpuTime().getUser(), 40, DELTA); + Assertions.assertEquals(youngGC.getCpuTime().getSys(), 10, DELTA); + Assertions.assertEquals(youngGC.getCpuTime().getReal(), 10, DELTA); + + GCEvent cms = model.getGcEvents().get(2); + Assertions.assertEquals(cms.getEventType(), GCEventType.CMS_CONCURRENT_MARK_SWEPT); + Assertions.assertEquals(cms.getStartTime(), 675164, DELTA); + Assertions.assertEquals(cms.getPhases().size(), 12, DELTA); + for (GCEvent phase : cms.getPhases()) { + Assertions.assertTrue(phase.getStartTime() != UNKNOWN_DOUBLE); + Assertions.assertTrue(phase.getDuration() != UNKNOWN_DOUBLE); + } + Assertions.assertEquals(cms.getLastPhaseOfType(GCEventType.CMS_INITIAL_MARK).getStartTime(), 675164, DELTA); + Assertions.assertEquals(cms.getLastPhaseOfType(GCEventType.CMS_CONCURRENT_MARK).getDuration(), 34415, DELTA); + Assertions.assertEquals(cms.getLastPhaseOfType(GCEventType.CMS_CONCURRENT_MARK).getCpuTime().getUser(), 154390, DELTA); + Assertions.assertEquals(cms.getLastPhaseOfType(GCEventType.CMS_FINAL_REMARK).getCpuTime().getUser(), 770, DELTA); + Assertions.assertEquals(cms.getLastPhaseOfType(GCEventType.CMS_FINAL_REMARK).getDuration(), 431.5, DELTA); + Assertions.assertEquals(cms.getLastPhaseOfType(GCEventType.CMS_CONCURRENT_RESET).getDuration(), 237, DELTA); + } + + @Test + public void testJDK8CMSCPUTime() throws Exception { + List log = TestUtil.generateShuffledGCLog("8CMSCPUTime.log"); + Assertions.assertEquals(log.size(), 12); + + CMSGCModel model = (CMSGCModel) parse(log); + + Assertions.assertNotNull(model); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_INITIAL_MARK).getCpuTime().getReal(),130, DELTA); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_CONCURRENT_MARK).getCpuTime().getUser(),10, DELTA); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_CONCURRENT_PRECLEAN).getCpuTime().getReal(),30, DELTA); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_CONCURRENT_ABORTABLE_PRECLEAN).getCpuTime().getReal(),4650, DELTA); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_FINAL_REMARK).getCpuTime().getReal(),30, DELTA); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_CONCURRENT_SWEEP).getCpuTime().getReal(),20, DELTA); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_CONCURRENT_RESET).getCpuTime().getReal(),40, DELTA); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.YOUNG_GC).getCpuTime().getReal(),50, DELTA); + } + + @Test + public void TestJDK8CMSPromotionFailed() throws Exception { + List log = TestUtil.generateShuffledGCLog("8CMSPromotionFailed.log"); + Assertions.assertEquals(log.size(), 1); + + CMSGCModel model = (CMSGCModel) parse(log); + + Assertions.assertEquals(model.getGcEvents().size(), 1); + GCEvent fullGC = model.getGcEvents().get(0); + Assertions.assertEquals(fullGC.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullGC.getMemoryItem(YOUNG), new GCMemoryItem(YOUNG, 7689600L * 1024, 0, 7689600L * 1024)); + Assertions.assertEquals(fullGC.getMemoryItem(OLD), new GCMemoryItem(OLD, 9258265L * 1024, 5393434L * 1024, 12582912L * 1024)); + Assertions.assertEquals(fullGC.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 16878013L * 1024, 5393434L * 1024, 20272512L * 1024)); + Assertions.assertEquals(fullGC.getMemoryItem(METASPACE), new GCMemoryItem(METASPACE, 208055 * 1024, 203568 * 1024, 1253376 * 1024)); + Assertions.assertEquals(fullGC.getCause(), PROMOTION_FAILED); + Assertions.assertTrue(fullGC.isTrue(YOUNG_GC_BECOME_FULL_GC)); + } + + @Test + public void TestJDK8CMSScavengeBeforeRemark() throws Exception { + List log = TestUtil.generateShuffledGCLog("8CMSScavengeBeforeRemark.log"); + Assertions.assertEquals(log.size(), 14); + + CMSGCModel model = (CMSGCModel) parse(log); + + Assertions.assertEquals(model.getGcEvents().size(), 3); + Assertions.assertEquals(model.getLastEventOfType(GCEventType.CMS_FINAL_REMARK).getCpuTime().getUser(), 830, DELTA); + + GCEvent youngGC = model.getGcEvents().get(1); + Assertions.assertEquals(youngGC.getMemoryItem(YOUNG), new GCMemoryItem(YOUNG, 1922431L * 1024L, 174720L * 1024L, 1922432L * 1024L)); + + youngGC = model.getGcEvents().get(2); + Assertions.assertEquals(youngGC.getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(youngGC.getMemoryItem(YOUNG), new GCMemoryItem(YOUNG, 1056998L * 1024L, 151245L * 1024L, 1922432L * 1024L)); + Assertions.assertEquals(youngGC.getCpuTime().getUser(), 490, DELTA); + Assertions.assertEquals(youngGC.getCause(), CMS_FINAL_REMARK); + + PauseStatistics pause = model.getPauseStatistics(new TimeRange(0, 99999999)); + Assertions.assertEquals(pause.getPauseAvg(), (226.6431 + 362.9243 + 293.1600) / 3.0, DELTA); + } + + @Test + public void testJDK8CMSPrintGC() throws Exception { + List log = TestUtil.generateShuffledGCLog("8CMSPrintGC.log"); + Assertions.assertEquals(log.size(), 14); + + CMSGCModel model = (CMSGCModel) parse(log); + + Assertions.assertEquals(model.getGcEvents().stream().filter(GCEvent::isYoungGC).count(), 3); + Assertions.assertEquals(model.getGcEvents().stream().filter(GCEvent::isOldGC).count(), 4); + Assertions.assertEquals(model.getGcEvents().stream().filter(GCEvent::isFullGC).count(), 3); + for (GCEvent event : model.getGcEvents()) { + Assertions.assertTrue(event.getStartTime() > 0); + if (event.isYoungGC() || event.isFullGC()) { + Assertions.assertTrue(event.getDuration() > 0); + Assertions.assertNotNull(event.getCause()); + Assertions.assertNotNull(event.getMemoryItem(HEAP)); + } + if (event.isOldGC()) { + Assertions.assertEquals(2, event.getPhases().size()); + } + } + } + + @Test + public void testJDK8G1GCParser() throws Exception { + List log = TestUtil.generateShuffledGCLog("8G1GCParser.log"); + Assertions.assertEquals(log.size(), 1); + + G1GCModel model = (G1GCModel) parse(log); + + Assertions.assertNotNull(model); + Assertions.assertEquals(model.getGcEvents().size(), 4); + Assertions.assertEquals(model.getParallelThread(), 4); + + GCEvent youngGC = model.getGcEvents().get(0); + Assertions.assertEquals(youngGC.getStartTime(), 3960, DELTA); + Assertions.assertEquals(youngGC.getDuration(), 56.3085, DELTA); + Assertions.assertEquals(youngGC.getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(youngGC.getCause(), G1_EVACUATION_PAUSE); + Assertions.assertEquals(youngGC.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 184 * 1024 * 1024, 3800L * 1024 * 1024, (int) (19.3 * 1024 * 1024), 3800L * 1024 * 1024)); + Assertions.assertEquals(youngGC.getMemoryItem(EDEN), new GCMemoryItem(EDEN, 184 * 1024 * 1024, 184 * 1024 * 1024, 0, 160 * 1024 * 1024)); + Assertions.assertNotNull(youngGC.getPhases()); + for (GCEvent phase : youngGC.getPhases()) { + Assertions.assertTrue(phase.getDuration() != UNKNOWN_DOUBLE); + } + Assertions.assertEquals(youngGC.getLastPhaseOfType(GCEventType.G1_GC_REFPROC).getDuration(), 15.1, DELTA); + Assertions.assertEquals(youngGC.getLastPhaseOfType(GCEventType.G1_CODE_ROOT_SCANNING).getDuration(), 0.5, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getSoftReferenceStartTime(), 4000, DELTA); + Assertions.assertEquals(youngGC.getReferenceGC().getJniWeakReferencePauseTime(), 0.0057, DELTA); + Assertions.assertEquals(youngGC.getCpuTime().getUser(), 70, DELTA); + Assertions.assertEquals(youngGC.getCpuTime().getSys(), 10, DELTA); + Assertions.assertEquals(youngGC.getCpuTime().getReal(), 60, DELTA); + + GCEvent concurrentCycle = model.getGcEvents().get(1); + Assertions.assertEquals(concurrentCycle.getStartTime(), 4230, DELTA); + Assertions.assertEquals(concurrentCycle.getPhases().size(), 9); + for (GCEvent phase : concurrentCycle.getPhases()) { + if (phase.getEventType() != GCEventType.G1_CONCURRENT_MARK_RESET_FOR_OVERFLOW) { + Assertions.assertTrue(phase.getDuration() != UNKNOWN_DOUBLE); + } + Assertions.assertTrue(phase.getStartTime() != UNKNOWN_DOUBLE); + } + Assertions.assertEquals(concurrentCycle.getLastPhaseOfType(GCEventType.G1_CONCURRENT_SCAN_ROOT_REGIONS).getStartTime(), 4230, DELTA); + Assertions.assertEquals(concurrentCycle.getLastPhaseOfType(GCEventType.G1_CONCURRENT_SCAN_ROOT_REGIONS).getDuration(), 160.8430, DELTA); + Assertions.assertEquals(concurrentCycle.getLastPhaseOfType(GCEventType.G1_REMARK).getStartTime(), 19078, DELTA); + Assertions.assertEquals(concurrentCycle.getLastPhaseOfType(GCEventType.G1_REMARK).getDuration(), 478.5858, DELTA); + Assertions.assertEquals(concurrentCycle.getLastPhaseOfType(GCEventType.G1_PAUSE_CLEANUP).getMemoryItem(HEAP).getPostUsed(), 9863L * 1024 * 1024, DELTA); + Assertions.assertEquals(concurrentCycle.getLastPhaseOfType(GCEventType.G1_REMARK).getCpuTime().getUser(), 1470, DELTA); + Assertions.assertEquals(concurrentCycle.getLastPhaseOfType(GCEventType.G1_PAUSE_CLEANUP).getCpuTime().getSys(), 10, DELTA); + + GCEvent fullGC = model.getGcEvents().get(2); + Assertions.assertEquals(fullGC.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullGC.getStartTime(), 23346, DELTA); + Assertions.assertEquals(fullGC.getDuration(), 1924.2692, DELTA); + Assertions.assertEquals(fullGC.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullGC.getCause(), METADATA_GENERATION_THRESHOLD); + Assertions.assertEquals(fullGC.getMemoryItem(METASPACE), new GCMemoryItem(METASPACE, 1792694 * 1024, 291615 * 1024, 698368 * 1024)); + Assertions.assertEquals(fullGC.getMemoryItem(HEAP), new GCMemoryItem(HEAP, (long) (7521.7 * 1024 * 1024), (long) (46144.0 * 1024 * 1024), (long) (7002.8 * 1024 * 1024), (long) (46144.0 * 1024 * 1024))); + Assertions.assertEquals(fullGC.getCpuTime().getUser(), 2090, DELTA); + Assertions.assertEquals(fullGC.getCpuTime().getSys(), 190, DELTA); + Assertions.assertEquals(fullGC.getCpuTime().getReal(), 1920, DELTA); + + GCEvent mixedGC = model.getGcEvents().get(3); + Assertions.assertEquals(mixedGC.getStartTime(), 79619, DELTA); + Assertions.assertEquals(mixedGC.getDuration(), 26.4971, DELTA); + Assertions.assertEquals(mixedGC.getEventType(), GCEventType.G1_MIXED_GC); + Assertions.assertEquals(mixedGC.getCause(), G1_EVACUATION_PAUSE); + Assertions.assertTrue(mixedGC.isTrue(TO_SPACE_EXHAUSTED)); + Assertions.assertEquals(mixedGC.getMemoryItem(HEAP).getPostCapacity(), (long) (19.8 * 1024 * 1024 * 1024)); + Assertions.assertEquals(mixedGC.getMemoryItem(EDEN).getPreUsed(), 2304L * 1024 * 1024); + Assertions.assertNotNull(mixedGC.getPhases()); + for (GCEvent phase : mixedGC.getPhases()) { + Assertions.assertTrue(phase.getDuration() != UNKNOWN_DOUBLE); + } + + GCLogMetadata metadata = model.getGcModelMetadata(); + Assertions.assertFalse(metadata.getImportantEventTypes().contains(GCEventType.G1_CONCURRENT_REBUILD_REMEMBERED_SETS.getName())); + Assertions.assertFalse(metadata.getImportantEventTypes().contains(GCEventType.G1_CONCURRENT_UNDO_CYCLE.getName())); + } + + @Test + public void testJDK8G1GCParserAdaptiveSize() throws Exception { + List log = TestUtil.generateShuffledGCLog("8G1GCParserAdaptiveSize.log"); + Assertions.assertEquals(log.size(), 1); + + + G1GCModel model = (G1GCModel) parse(log); + + Assertions.assertNotNull(model); + Assertions.assertEquals(model.getGcEvents().size(), 1); + GCEvent youngGC = model.getGcEvents().get(0); + Assertions.assertEquals(youngGC.getStartTime(), 683, DELTA); + Assertions.assertEquals(youngGC.getDuration(), 8.5898, DELTA); + Assertions.assertEquals(youngGC.getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(youngGC.getCause(), G1_EVACUATION_PAUSE); + Assertions.assertEquals(youngGC.getMemoryItem(HEAP).getPreUsed(), 52224 * 1024); + } + + @Test + public void testJDK8G1PrintGC() throws Exception { + List log = TestUtil.generateShuffledGCLog("8G1PrintGC.log"); + Assertions.assertEquals(log.size(), 22); + + G1GCModel model = (G1GCModel) parse(log); + + Assertions.assertEquals(model.getGcEvents().stream().filter(GCEvent::isYoungGC).count(), 8); + Assertions.assertEquals(model.getGcEvents().stream().filter(GCEvent::isOldGC).count(), 2); + Assertions.assertEquals(model.getGcEvents().stream().filter(GCEvent::isFullGC).count(), 1); + Assertions.assertEquals(model.getGcEvents().stream().filter(event -> event.isTrue(TO_SPACE_EXHAUSTED)).count(), 2); + for (GCEvent event : model.getGcEvents()) { + Assertions.assertTrue(event.getStartTime() > 0); + if (event.isYoungGC() || event.isFullGC()) { + Assertions.assertTrue(event.getDuration() > 0); + Assertions.assertNotNull(event.getCause()); + Assertions.assertNotNull(event.getMemoryItem(HEAP)); + } + if (event.isOldGC()) { + Assertions.assertTrue( event.getPhases().size() >= 2); + } + } + } + + @Test + public void testJDK8ParallelGCParser() throws Exception { + List log = TestUtil.generateShuffledGCLog("8ParallelGCParser.log"); + Assertions.assertEquals(log.size(), 6); + + ParallelGCModel model = (ParallelGCModel) parse(log); + + Assertions.assertNotNull(model); + + Assertions.assertEquals(model.getGcEvents().size(), 6); + + GCEvent youngGC = model.getGcEvents().get(2); + Assertions.assertEquals(youngGC.getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(youngGC.getCause(), ALLOCATION_FAILURE); + Assertions.assertEquals(youngGC.getStartTime(), 962, DELTA); + Assertions.assertEquals(youngGC.getDuration(), 46.2864, DELTA); + GCMemoryItem youngGen = youngGC.getMemoryItem(YOUNG); + Assertions.assertEquals(youngGen.getPreUsed(), 51200 * 1024); + Assertions.assertEquals(youngGen.getPostUsed(), 4096 * 1024); + Assertions.assertEquals(youngGen.getPostCapacity(), 77824 * 1024); + GCMemoryItem total = youngGC.getMemoryItem(HEAP); + Assertions.assertEquals(total.getPreUsed(), 118572 * 1024); + Assertions.assertEquals(total.getPostUsed(), 117625 * 1024); + Assertions.assertEquals(total.getPostCapacity(), 252416 * 1024); + Assertions.assertEquals(youngGC.getCpuTime().getUser(), 290, DELTA); + + GCEvent fullGC = model.getGcEvents().get(5); + Assertions.assertEquals(fullGC.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullGC.getCause(), ERGONOMICS); + Assertions.assertEquals(fullGC.getStartTime(), 14608, DELTA); + Assertions.assertEquals(fullGC.getDuration(), 4.6781, DELTA); + youngGen = fullGC.getMemoryItem(YOUNG); + Assertions.assertEquals(youngGen.getPreUsed(), 65530 * 1024); + Assertions.assertEquals(youngGen.getPostUsed(), 0); + Assertions.assertEquals(youngGen.getPostCapacity(), 113664 * 1024); + GCMemoryItem oldGen = fullGC.getMemoryItem(OLD); + Assertions.assertEquals(oldGen.getPreUsed(), 341228 * 1024); + Assertions.assertEquals(oldGen.getPostUsed(), 720 * 1024); + Assertions.assertEquals(oldGen.getPostCapacity(), 302592 * 1024); + GCMemoryItem metaspace = fullGC.getMemoryItem(METASPACE); + Assertions.assertEquals(metaspace.getPreUsed(), 3740 * 1024); + Assertions.assertEquals(metaspace.getPostUsed(), 3737 * 1024); + Assertions.assertEquals(metaspace.getPostCapacity(), 1056768 * 1024); + total = fullGC.getMemoryItem(HEAP); + Assertions.assertEquals(total.getPreUsed(), 406759 * 1024); + Assertions.assertEquals(total.getPostUsed(), 720 * 1024); + Assertions.assertEquals(total.getPostCapacity(), 416256 * 1024); + Assertions.assertEquals(fullGC.getCpuTime().getUser(), 20, DELTA); + } + + @Test + public void testJDK8GenerationalGCInterleave() throws Exception { + List log = TestUtil.generateShuffledGCLog("8GenerationalGCInterleave.log"); + Assertions.assertEquals(log.size(), 1); + + GCModel model = parse(log); + + Assertions.assertNotNull(model); + + Assertions.assertEquals(model.getGcEvents().size(), 1); + GCEvent fullGC = model.getGcEvents().get(0); + Assertions.assertEquals(fullGC.getStartTime(), 61988328, DELTA); + Assertions.assertEquals(fullGC.getDuration(), 2016.0411, DELTA); + Assertions.assertEquals(fullGC.getEventType(), GCEventType.FULL_GC); + Assertions.assertEquals(fullGC.getCause(), ALLOCATION_FAILURE); + Assertions.assertEquals(fullGC.getMemoryItem(YOUNG), new GCMemoryItem(YOUNG, 2621440L * 1024, 0, 2883584L * 1024)); + Assertions.assertEquals(fullGC.getMemoryItem(OLD), new GCMemoryItem(OLD, 1341593L * 1024, 1329988L * 1024, 2097152L * 1024)); + Assertions.assertEquals(fullGC.getMemoryItem(HEAP), new GCMemoryItem(HEAP, 3963033L * 1024, 1329988L * 1024, 4980736L * 1024)); + Assertions.assertEquals(fullGC.getMemoryItem(METASPACE), new GCMemoryItem(METASPACE, 310050L * 1024, 309844L * 1024, 1343488L * 1024)); + Assertions.assertEquals(fullGC.getCpuTime().getReal(), 2010, DELTA); + } + + @Test + public void testJDK8ConcurrentPrintDateTimeStamp() throws Exception { + List log = TestUtil.generateShuffledGCLog("8ConcurrentPrintDateTimeStamp.log"); + Assertions.assertEquals(log.size(), 7); + + G1GCModel model = (G1GCModel) parse(log); + + Assertions.assertEquals(model.getGcEvents().size(), 3); + Assertions.assertEquals(model.getGcEvents().get(0).getEventType(), GCEventType.YOUNG_GC); + Assertions.assertEquals(model.getGcEvents().get(1).getEventType(), GCEventType.G1_CONCURRENT_CYCLE); + Assertions.assertEquals(model.getGcEvents().get(1).getPhases().get(0).getEventType(), GCEventType.G1_CONCURRENT_SCAN_ROOT_REGIONS); + Assertions.assertEquals(model.getGcEvents().get(1).getPhases().get(0).getStartTime(), 725081, DELTA); + Assertions.assertEquals(model.getGcEvents().get(2).getEventType(), GCEventType.YOUNG_GC); + } + + @Test + public void TestIncompleteGCLog() throws Exception { + List log = TestUtil.generateShuffledGCLog("IncompleteGCLog.log"); + Assertions.assertEquals(log.size(), 30); + + CMSGCModel model = (CMSGCModel) parse(log); + + Assertions.assertNotNull(model); + + Assertions.assertEquals(model.getGcEvents().size(), 2); + Assertions.assertEquals(model.getAllEvents().size(), 8); + } +} diff --git a/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToMetrics.java b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToMetrics.java new file mode 100644 index 00000000..9bbd2bc1 --- /dev/null +++ b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestFragmentedParserToMetrics.java @@ -0,0 +1,139 @@ +/******************************************************************************** + * Copyright (c) 2023 Contributors to the Eclipse Foundation + * + * See the NOTICE file(s) distributed with this work for additional + * information regarding copyright ownership. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License 2.0 which is available at + * http://www.eclipse.org/legal/epl-2.0 + * + * SPDX-License-Identifier: EPL-2.0 + ********************************************************************************/ +package org.eclipse.jifa.gclog; + +import com.google.common.collect.ImmutableMap; +import com.google.common.collect.ImmutableSet; +import lombok.extern.slf4j.Slf4j; +import org.eclipse.jifa.gclog.fragment.GCLogAnalyzer; +import org.eclipse.jifa.gclog.fragment.Metric; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +import java.util.*; +import java.util.stream.Collectors; + +@Slf4j +public class TestFragmentedParserToMetrics { + public static final double DELTA = 1e-6; + private static final String INSTANCEIDKEY = "instanceId", INSTANCEIDVALUE = "test-instanceId"; + + private List parse(List context, long startTime, long endTime) { + GCLogAnalyzer gcLogAnalyzer = new GCLogAnalyzer(); + List result = null; + Map instanceId = new ImmutableMap.Builder().put(INSTANCEIDKEY, INSTANCEIDVALUE).build(); + try { + result = gcLogAnalyzer.parseToMetrics(context, instanceId, startTime, endTime); + } catch (Exception e) { + e.printStackTrace(); + } + return result; + } + + public void testAnalyzeSpeed() { + Set files = new ImmutableSet.Builder().build(); + GCLogAnalyzer gcLogAnalyzer = new GCLogAnalyzer(); + files.forEach(file -> { + List gclog = TestUtil.generateShuffledGCLog(file); + Map instanceId = new ImmutableMap.Builder().put(INSTANCEIDKEY, file).build(); + long beginTime = System.currentTimeMillis(); + List result = null; + try { + result = gcLogAnalyzer.parseToMetrics(gclog, instanceId, 0, Long.MAX_VALUE); + } catch (Exception e) { + e.printStackTrace(); + } + double spendTime = (System.currentTimeMillis() - beginTime) / 1000.; + System.out.printf("分析%s,共计%d条数据,生成%d条metrics,耗时%fs,平均1分钟可处理%f条数据,生成%f条metrics\n", + file, gclog.size(), result.size(), spendTime, gclog.size()/spendTime*60, result.size()/spendTime*60); + }); + } + + @Test + public void testMetricLength() { + Map metricSizeForEachGCLog = new ImmutableMap.Builder() + .put("11G1Parser.log", 46) + .put("8CMSParser.log", 130) + .put("8CMSPrintGC.log", 40) + .put("8G1PrintGC.log", 47) + .put("8ParallelGCParser.log", 75) + .put("8G1GCParser.log", 77) + .put("8G1GCParserAdaptiveSize.log", 28) + .put("8ConcurrentPrintDateTimeStamp.log", 65) + .put("8CMSCPUTime.log", 26) + .put("8CMSPromotionFailed.log", 13) + .put("8CMSScavengeBeforeRemark.log", 38) + .put("8GenerationalGCInterleave.log", 13) + .build(); + metricSizeForEachGCLog.forEach((gclog, size) -> + Assertions.assertEquals(Integer.valueOf(parse(TestUtil.generateShuffledGCLog(gclog), 0, Long.MAX_VALUE).size()), size)); + } + + @Test + public void testMetricContent() { + List metrics = parse(TestUtil.generateShuffledGCLog("8CMSCPUTime.log"), 1669618629000L, 1669618630000L); + + Map> valueForEachMetric = new ImmutableMap.Builder>() + .put("GC_CPU_USED", new ImmutableMap.Builder() + .put("USER", 180.0).put("SYS", 30.0).put("REAL", 50.0).build()) + .put("GC_PAUSE_TIME", new ImmutableMap.Builder() + .put("Young GC", 50.0).build()) + .put("BEFORE_GC_REGION_SIZE", new ImmutableMap.Builder() + .put("Young", 1761607680.).put("Old", 0.).put("Heap", 1761607680.).build()) + .put("AFTER_GC_REGION_SIZE", new ImmutableMap.Builder() + .put("Young", 36896768.).put("Old", 0.).put("Heap", 36896768.).build()) + .build(); + + Assertions.assertEquals(metrics.size(), 12); + valueForEachMetric.forEach((metricName, labelMap) -> + labelMap.forEach((label, value) -> { + List actualMetrics = metrics.stream() + .filter(metric -> metric.getName().equals(metricName)) + .filter(metric -> metric.getLabel().get("type").equals(label)) + .filter(metric -> metric.getTimestamp() == 1669618629974L) + .filter(metric -> metric.getLabel().get("gc_type").equals("CMS GC")) + .filter(metric -> metric.getLabel().get(INSTANCEIDKEY).equals(INSTANCEIDVALUE)) + .collect(Collectors.toList()); + Assertions.assertEquals(actualMetrics.size(), 1); + Assertions.assertEquals(actualMetrics.get(0).getValue(), value, DELTA); + }) + ); + } + + @Test + public void testMetricContentSubphase() { + List metrics = parse(TestUtil.generateShuffledGCLog("11CMSUpTime.log"), 0, Long.MAX_VALUE); + Map subphaseMap = new ImmutableMap.Builder() + .put("Initial Mark", 3.41) + .put("Concurrent Mark", 136.57) + .put("Concurrent Preclean", 4.724) + .put("Concurrent Abortable preclean", 197.909) + .put("Final Remark", 75.082) + .put("Concurrent Sweep", 166.162) + .put("Concurrent Reset", 609.769) + .build(); + + subphaseMap.forEach((subphase, value) -> { + List actualMetrics = metrics.stream() + .filter(metric -> metric.getTimestamp() == 1693292160355L) + .filter(metric -> metric.getName().equals("GC_SUBPHASE_TIME")) + .filter(metric -> metric.getLabel().get("gc_type").equals("CMS GC")) + .filter(metric -> metric.getLabel().get(INSTANCEIDKEY).equals(INSTANCEIDVALUE)) + .filter(metric -> metric.getLabel().get("type").equals("CMS")) + .filter(metric -> metric.getLabel().get("subphase").equals(subphase)) + .collect(Collectors.toList()); + Assertions.assertEquals(actualMetrics.size(), 1); + Assertions.assertEquals(actualMetrics.get(0).getValue(), value, DELTA); + }); + } +} diff --git a/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestUtil.java b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestUtil.java index 2585dd7f..7c97cdc2 100644 --- a/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestUtil.java +++ b/analysis/gc-log/src/test/java/org/eclipse/jifa/gclog/TestUtil.java @@ -13,8 +13,11 @@ package org.eclipse.jifa.gclog; +import org.junit.jupiter.api.Assertions; + import java.io.*; -import java.util.Objects; +import java.util.*; +import java.util.stream.Collectors; public class TestUtil { public static BufferedReader stringToBufferedReader(String source) { @@ -26,4 +29,33 @@ public static BufferedReader getGCLog(String name) { InputStream is = Objects.requireNonNull(Thread.currentThread().getContextClassLoader().getResourceAsStream(name)); return new BufferedReader(new InputStreamReader(is)); } + + public static List generateShuffledGCLog(String name) { + StringBuffer gclog = new StringBuffer("\n"); + try { + BufferedReader bufferedReader = getGCLog(name); + String line; + while ((line = bufferedReader.readLine()) != null) { + gclog.append(line); + gclog.append('\n'); + } + } catch (Exception e) { + e.printStackTrace(); + } + + String regexForSplit = null; + switch (name) { + case "11CMSUpTime.log" -> regexForSplit = "(?=\n\\[[\\d-T:+.]+]\\[[0-9]+\\.[0-9]+s])"; + case "11G1Parser.log", "11CMSGCParser.log", "IncompleteGCLog.log" -> regexForSplit = "(?=\n\\[[0-9]+\\.[0-9]+s])"; + case "8CMSParser.log", "8CMSPrintGC.log", "8G1PrintGC.log", "8ParallelGCParser.log" -> regexForSplit = "(?=\n[0-9]+\\.[0-9]+: \\[)"; + case "8G1GCParser.log", "8G1GCParserAdaptiveSize.log", "8ConcurrentPrintDateTimeStamp.log", "8CMSCPUTime.log", "8CMSPromotionFailed.log", "8CMSScavengeBeforeRemark.log", "8GenerationalGCInterleave.log" -> regexForSplit = "(?=\n[\\d-T:+.]+ \\d+\\.\\d+: \\[)"; + default -> Assertions.fail("can't find timestamp pattern for gc log " + name); + } + + String originalLog = gclog.toString(); + List shuffledLog = new ArrayList<>(Arrays.asList(originalLog.split(regexForSplit))); + shuffledLog = shuffledLog.stream().map(str -> str.substring(1)).collect(Collectors.toList()); + Collections.shuffle(shuffledLog); + return shuffledLog; + } }