Skip to content

Fix for Legacy ZGC log files without details (-Xlog:gc) #440

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
jlittle-ptc wants to merge 4 commits into from
Closed

Fix for Legacy ZGC log files without details (-Xlog:gc) #440

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
7ef9111
#433 - Adjust offsets to match G1GC Young event examples.
jlittle-ptc Apr 22, 2025
f73bf14
Fixes issue where legacy (non-generational) ZGC logs that are generat…
jlittle-ptc Apr 29, 2025
b298233
Merge branch 'main' into ZGC-FixNoDetailParsing
jlittle-ptc Apr 30, 2025
110296f
Uncomment missing ParserTest method now that #438 is merged and repla…
jlittle-ptc Apr 30, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
22 changes: 15 additions & 7 deletions parser/src/main/java/com/microsoft/gctoolkit/parser/ZGCParser.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -534,25 +534,33 @@ private void endOfPhaseMemorySummary(GCLogTrace trace, String s) {
}

private void memorySummary(GCLogTrace trace, String s) {
ZGCCollectionType type = ZGCCollectionType.get(trace.getGroup(1));
long gcID = trace.getLongGroup(1);
ZGCCollectionType type = ZGCCollectionType.get(trace.getGroup(2));

switch (type) {
case FULL:
// Legacy ZGC Logs generated with -Xlog:gc instead of -Xlog:gc* won't have started a cycle, so we
// have to create the forward reference here.
// This does not apply to Generational logs as they log two lines for each cycle.
if (forwardReference == null)
forwardReference = new ZGCForwardReference(getClock(), gcID, trace.gcCause(3,0), type, ZGCPhase.FULL);

((ZGCForwardReference)forwardReference).setMemorySummary(
new ZGCMemorySummary(
trace.toKBytes(3),
trace.toKBytes(6)));
trace.toKBytes(4),
trace.toKBytes(7)));
break;
case MINOR:
((ZGCMinorForwardReference)forwardReference).setMemorySummary(
new ZGCMemorySummary(
trace.toKBytes(3),
trace.toKBytes(6)));
trace.toKBytes(4),
trace.toKBytes(7)));
break;
case MAJOR:
((ZGCMajorForwardReference)forwardReference).setMemorySummary(
new ZGCMemorySummary(
trace.toKBytes(3),
trace.toKBytes(6)));
trace.toKBytes(4),
trace.toKBytes(7)));
break;
}

Expand Down
5 changes: 4 additions & 1 deletion parser/src/main/java/com/microsoft/gctoolkit/parser/unified/ZGCPatterns.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -125,11 +125,14 @@ public interface ZGCPatterns extends UnifiedPatterns {
GCParseRule END_OF_PHASE_SUMMARY_GEN = new GCParseRule("End of Phase Summary", OPT_GEN + "(Old|Young) Generation " + MEMORY_PERCENT + "->" + MEMORY_PERCENT + "\\s*" + PAUSE_TIME);


// Added GCID capture into the following regex to allow creation of forwardReference for legacy, non-detail logs
// as without details, the cycle is never initialized. This only applies to "Full" (Garbage) collection events;
// generational events log a start and end line and are properly initialized.
//[3.596s][info ][gc ] GC(3) Garbage Collection (Warmup) 894M(22%)->186M(5%)
// or
// Gen GC
//[3.596s][info][gc ] GC(7) Minor Collection (Allocation Rate) 14720M(40%)->2054M(6%) 0.689s
GCParseRule MEMORY_SUMMARY = new GCParseRule("Memory Summary", "(Garbage|Minor|Major) Collection " + GenericTokens.GC_CAUSE + MEMORY_PERCENT + "->" + MEMORY_PERCENT + "(?:\\s*" + PAUSE_TIME + ")?");
GCParseRule MEMORY_SUMMARY = new GCParseRule("Memory Summary", "GC\\(" + GenericTokens.INT + "\\) (Garbage|Minor|Major) Collection " + GenericTokens.GC_CAUSE + MEMORY_PERCENT + "->" + MEMORY_PERCENT + "(?:\\s*" + PAUSE_TIME + ")?");

/*
todo: capture and report on these log entries
Expand Down
97 changes: 87 additions & 10 deletions parser/src/test/java/com/microsoft/gctoolkit/parser/ZGCParserTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,10 @@
// Licensed under the MIT License.
package com.microsoft.gctoolkit.parser;

import com.microsoft.gctoolkit.event.GCCause;
import com.microsoft.gctoolkit.event.jvm.JVMEvent;
import com.microsoft.gctoolkit.event.zgc.FullZGCCycle;
import com.microsoft.gctoolkit.event.zgc.MajorZGCCycle;
import com.microsoft.gctoolkit.event.zgc.ZGCAllocatedSummary;
import com.microsoft.gctoolkit.event.zgc.ZGCGarbageSummary;
import com.microsoft.gctoolkit.event.zgc.ZGCLiveSummary;
Expand All @@ -13,6 +15,8 @@
import com.microsoft.gctoolkit.event.zgc.ZGCReclaimSummary;
import com.microsoft.gctoolkit.jvm.Diarizer;
import com.microsoft.gctoolkit.parser.jvm.UnifiedDiarizer;
import com.microsoft.gctoolkit.time.DateTimeStamp;

import org.junit.jupiter.api.Test;

import java.util.List;
Expand All @@ -30,6 +34,8 @@ protected GCLogParser parser() {
return new ZGCParser();
}

final long M = 1024;

@Test
public void infoLevelZGCCycle() {

Expand Down Expand Up @@ -80,18 +86,18 @@ public void infoLevelZGCCycle() {
assertEquals(zgc.getGcId(), 2L);

assertEquals(0.0710d, zgc.getDuration(),0.001d);
assertEquals(toInt(32.121d, 1000), toInt(zgc.getDateTimeStamp().getTimeStamp(), 1000));
assertEquals(toInt(32.121d, 1000), toInt(zgc.getDateTimeStamp().toSeconds(), 1000));
assertEquals("Metadata GC Threshold", zgc.getGCCause().getLabel());
// Durations
assertEquals(32.121d, zgc.getPauseMarkStartTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.122d, zgc.getConcurrentMarkTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.166d, zgc.getConcurrentMarkFreeTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.166d, zgc.getPauseMarkEndTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.167d, zgc.getConcurrentProcessNonStrongReferencesTimeStamp().getTimeStamp(), 0.002d);
assertEquals(32.172d, zgc.getConcurrentResetRelocationSetTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.172d, zgc.getConcurrentSelectRelocationSetTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.179d, zgc.getPauseRelocateStartTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.179d, zgc.getConcurrentRelocateTimeStamp().getTimeStamp(), 0.001d);
assertEquals(32.121d, zgc.getPauseMarkStartTimeStamp().toSeconds(), 0.001d);
assertEquals(32.122d, zgc.getConcurrentMarkTimeStamp().toSeconds(), 0.001d);
assertEquals(32.166d, zgc.getConcurrentMarkFreeTimeStamp().toSeconds(), 0.001d);
assertEquals(32.166d, zgc.getPauseMarkEndTimeStamp().toSeconds(), 0.001d);
assertEquals(32.167d, zgc.getConcurrentProcessNonStrongReferencesTimeStamp().toSeconds(), 0.002d);
assertEquals(32.172d, zgc.getConcurrentResetRelocationSetTimeStamp().toSeconds(), 0.001d);
assertEquals(32.172d, zgc.getConcurrentSelectRelocationSetTimeStamp().toSeconds(), 0.001d);
assertEquals(32.179d, zgc.getPauseRelocateStartTimeStamp().toSeconds(), 0.001d);
assertEquals(32.179d, zgc.getConcurrentRelocateTimeStamp().toSeconds(), 0.001d);

assertEquals(toInt(0.023d, 1000), toInt(zgc.getPauseMarkStartDuration(), 1000));
assertEquals(toInt(44.623d, 1000), toInt(zgc.getConcurrentMarkDuration(), 1000));
Expand Down Expand Up @@ -134,6 +140,70 @@ public void infoLevelZGCCycle() {
}
}

@Test
void testLegacyZGCNoDetailsLines() {
String[] lines = {
// 0 - FullZGCCycle
"[1.295s][info][gc] GC(0) Garbage Collection (Metadata GC Threshold) 90M(1%)->58M(1%)",

// 1 - FullZGCCycle
"[23.507s][info][gc] GC(3) Garbage Collection (Warmup) 826M(10%)->168M(2%)"
};

int expectedEventCount = 2;

List<JVMEvent> jvmEvents = feedParser(lines);
assertEquals(jvmEvents.size(), expectedEventCount);

// 0 - FullZGCCycle
assertTrue(jvmEvents.get(0) instanceof FullZGCCycle);
FullZGCCycle evt0 = (FullZGCCycle) jvmEvents.get(0);
assertEquals(evt0.getDateTimeStamp(), new DateTimeStamp(1.295));
assertEquals(evt0.getGCCause(), GCCause.METADATA_GENERATION_THRESHOLD);
assertZGCMemorySummary(evt0.getMemorySummary(), 90*M, 58*M);

// 1 - FullZGCCycle
assertTrue(jvmEvents.get(1) instanceof FullZGCCycle);
FullZGCCycle evt1 = (FullZGCCycle) jvmEvents.get(1);
assertEquals(evt1.getDateTimeStamp(), new DateTimeStamp(23.507));
assertEquals(evt1.getGCCause(), GCCause.WARMUP);
assertZGCMemorySummary(evt1.getMemorySummary(), 826*M, 168*M);
}

@Test
void testGenerationalZGCNoDetailsLines() {
String[] lines = {
// 0 - MajorZGCCycle
"[4.252s][info][gc] GC(2) Major Collection (Metadata GC Threshold)",
"[4.366s][info][gc] GC(2) Major Collection (Metadata GC Threshold) 384M(5%)->186M(2%) 0.114s",

// 1 - MajorZGCCycle
"[36.326s][info][gc] GC(3) Major Collection (Warmup)",
"[36.423s][info][gc] GC(3) Major Collection (Warmup) 730M(9%)->258M(3%) 0.097s"
};

int expectedEventCount = 2;

List<JVMEvent> jvmEvents = feedParser(lines);
assertEquals(jvmEvents.size(), expectedEventCount);

// 0 - MajorZGCCycle
assertTrue(jvmEvents.get(0) instanceof MajorZGCCycle);
MajorZGCCycle evt0 = (MajorZGCCycle) jvmEvents.get(0);
assertEquals(evt0.getDateTimeStamp(), new DateTimeStamp(4.252));
assertEquals(evt0.getGCCause(), GCCause.METADATA_GENERATION_THRESHOLD);
assertZGCMemorySummary(evt0.getMemorySummary(), 384*M, 186*M);
assertDoubleEquals(evt0.getDuration(), 0.114);

// 1 - MajorZGCCycle
assertTrue(jvmEvents.get(1) instanceof MajorZGCCycle);
MajorZGCCycle evt1 = (MajorZGCCycle) jvmEvents.get(1);
assertEquals(evt1.getDateTimeStamp(), new DateTimeStamp(36.326));
assertEquals(evt1.getGCCause(), GCCause.WARMUP);
assertZGCMemorySummary(evt1.getMemorySummary(), 730*M, 258*M);
assertDoubleEquals(evt1.getDuration(), 0.097);
}

private boolean checkZGCMemoryPoolSummary(ZGCMemoryPoolSummary summary, long capacity, long free, long used) {
return summary.getCapacity() == capacity && summary.getFree() == free && summary.getUsed() == used;
}
Expand Down Expand Up @@ -165,4 +235,11 @@ private boolean checkMemorySummary(ZGCMemorySummary summary, long relocateStart,
private int toInt(double value, int significantDigits) {
return (int)(value * (double)significantDigits);
}

private void assertZGCMemorySummary(ZGCMemorySummary summary, long before, long after) {
assertNotNull(summary);
assertEquals(summary.getOccupancyBefore(), before);
assertEquals(summary.getOccupancyAfter(), after);
}

}