Skip to content

Commit fb3b88e

Browse files
author
cuiweilong
committed
fix failed parsing for ZGC
1 parent d74690e commit fb3b88e

File tree

4 files changed

+130
-5
lines changed

4 files changed

+130
-5
lines changed

src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderUnifiedJvmLogging.java

Lines changed: 29 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -60,8 +60,9 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
6060
// Group 6 / tail: Pause Init Mark 1.070ms
6161
// Regex: ^(?:\[(?<time>[0-9-T:.+]*)])?(?:\[(?<uptime>[^s]*)s])?\[(?<level>[^]]+)]\[(?:(?<tags>[^] ]+)[ ]*)][ ]GC\((?<gcnumber>[0-9]+)\)[ ](?<type>([-.a-zA-Z ()]+|[a-zA-Z1 ()]+))(?:(?:[ ](?<tail>[0-9]{1}.*))|$)
6262
// note for the <type> part: easiest would have been to use [^0-9]+, but the G1 events don't fit there, because of the number in their name
63+
// add sub regex "[a-zA-Z ]+\\(.+\\)" for Allocation Stall and Relocation Stall of ZGC
6364
private static final Pattern PATTERN_DECORATORS = Pattern.compile(
64-
"^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^ms]*)(?<uptimeunit>m?s)])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](GC\\((?<gcnumber>[0-9]+)\\)[ ])?(?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+)(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
65+
"^(?:\\[(?<time>[0-9-T:.+]*)])?(?:\\[(?<uptime>[^ms]*)(?<uptimeunit>m?s)])?\\[(?<level>[^]]+)]\\[(?:(?<tags>[^] ]+)[ ]*)][ ](GC\\((?<gcnumber>[0-9]+)\\)[ ])?(?<type>(?:Phase [0-9]{1}: [a-zA-Z ]+)|[-.a-zA-Z: ()]+|[a-zA-Z1 ()]+|[a-zA-Z ]+\\(.+\\))(?:(?:[ ](?<tail>[0-9]{1}.*))|$)"
6566
);
6667
private static final String GROUP_DECORATORS_TIME = "time";
6768
private static final String GROUP_DECORATORS_UPTIME = "uptime";
@@ -176,7 +177,20 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
176177
"Cancelling GC",
177178
"CDS archive(s) mapped at", // metaspace preamble since JDK 17
178179
"Compressed class space mapped at", // metaspace preamble since JDK 17
179-
"Narrow klass base" // metaspace preamble since JDK 17
180+
"Narrow klass base", // metaspace preamble since JDK 17
181+
" Mark Start ", // heap preamble for ZGC since JDK 11
182+
"Reserve:", // heap preamble for ZGC since JDK 11
183+
"Free:", // heap preamble for ZGC since JDK 11
184+
"Used:", // heap preamble for ZGC since JDK 11
185+
"Live:", // heap preamble for ZGC since JDK 11
186+
"Allocated:", // heap preamble for ZGC since JDK 11
187+
"Garbage:", // heap preamble for ZGC since JDK 11
188+
"Reclaimed:", // heap preamble for ZGC since JDK 11
189+
"Page Cache Flushed:", // heap preamble for ZGC since JDK 11
190+
"Min Capacity:", // heap preamble for ZGC since JDK 11
191+
"Max Capacity:", // heap preamble for ZGC since JDK 11
192+
"Soft Max Capacity:", // heap preamble for ZGC since JDK 11
193+
"Uncommitted:" // heap preamble for ZGC since JDK 11
180194
);
181195
/** list of strings, that are gc log lines, but not a gc event -&gt; should be logged only */
182196
private static final List<String> LOG_ONLY_STRINGS = Arrays.asList("Using",
@@ -300,6 +314,19 @@ private AbstractGCEvent<?> handleTagGcPhasesTail(ParseContext context, AbstractG
300314

301315
private AbstractGCEvent<?> handleTagGcMetaspaceTail(ParseContext context, AbstractGCEvent<?> event, String tail) {
302316
AbstractGCEvent<?> returnEvent = event;
317+
// the event "Metaspace" in gc tag "[gc,metaspace]" for ZGC don't match the "PATTERN_MEMORY" rules; ignore it
318+
// ZGC:
319+
// [1.182s][info][gc,metaspace] GC(0) Metaspace: 19M used, 19M capacity, 19M committed, 20M reserved
320+
// [1.182s][info][gc,metaspace] GC(0) Metaspace: 11M used, 12M committed, 1088M reserved
321+
// G1:
322+
// [5.537s][info][gc,metaspace] GC(0) Metaspace: 118K(320K)->118K(320K) NonClass: 113K(192K)->113K(192K) Class: 4K(128K)->4K(128K)
323+
324+
if (returnEvent.getExtendedType().getType().equals(Type.METASPACE) && tail != null) {
325+
if (tail.contains("used,") && tail.contains("committed,")) {
326+
return null;
327+
}
328+
}
329+
303330
returnEvent = parseTail(context, returnEvent, tail);
304331
// the UJL "Old" event occurs often after the next STW events have taken place; ignore it for now
305332
// size after concurrent collection will be calculated by GCModel#add()

src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -539,7 +539,7 @@ public String toString() {
539539
// since about java 7_u45 these have a time stamp prepended
540540
public static final Type APPLICATION_STOPPED_TIME = new Type("Total time for which application threads were stopped", Generation.OTHER, Concurrency.SERIAL, GcPattern.GC_PAUSE, CollectionType.VM_OPERATION);
541541
// java 8: perm gen is moved to metaspace
542-
public static final Type Metaspace = new Type("Metaspace", Generation.PERM, Concurrency.SERIAL, GcPattern.GC_MEMORY);
542+
public static final Type METASPACE = new Type("Metaspace", Generation.PERM, Concurrency.SERIAL, GcPattern.GC_MEMORY);
543543

544544
// CMS types
545545
public static final Type CMS = new Type("CMS", Generation.TENURED);
@@ -704,13 +704,16 @@ public String toString() {
704704
public static final Type UJL_ZGC_PAUSE_MARK_END = new Type("Pause Mark End", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
705705
public static final Type UJL_ZGC_PAUSE_RELOCATE_START = new Type("Pause Relocate Start", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
706706
public static final Type UJL_ZGC_CONCURRENT_MARK = new Type("Concurrent Mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
707+
public static final Type UJL_ZGC_CONCURRENT_MARK_FREE = new Type("Concurrent Mark Free", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
707708
public static final Type UJL_ZGC_CONCURRENT_NONREF = new Type("Concurrent Process Non-Strong References", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
708709
public static final Type UJL_ZGC_CONCURRENT_RESET_RELOC_SET = new Type("Concurrent Reset Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
709710
public static final Type UJL_ZGC_CONCURRENT_DETATCHED_PAGES = new Type("Concurrent Destroy Detached Pages", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
710711
public static final Type UJL_ZGC_CONCURRENT_SELECT_RELOC_SET = new Type("Concurrent Select Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
711712
public static final Type UJL_ZGC_CONCURRENT_PREPARE_RELOC_SET = new Type("Concurrent Prepare Relocation Set", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
712713
public static final Type UJL_ZGC_CONCURRENT_RELOCATE = new Type("Concurrent Relocate", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
713714
public static final Type UJL_ZGC_HEAP_CAPACITY = new Type("Capacity", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_HEAP_MEMORY_PERCENTAGE);
715+
public static final Type UJL_ZGC_ALLOCATION_STALL = new Type("Allocation Stall", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
716+
public static final Type UJL_ZGC_RELOCATION_STALL = new Type("Relocation Stall", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE);
714717

715718
// IBM Types
716719
// TODO: are scavenge always young only??

src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLZGC.java

Lines changed: 60 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,12 +8,13 @@
88
import com.tagtraum.perf.gcviewer.UnittestHelper;
99
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
1010
import com.tagtraum.perf.gcviewer.model.GCModel;
11+
1112
import org.junit.After;
1213
import org.junit.Before;
1314
import org.junit.Test;
1415

1516
/**
16-
* Test unified java logging ZGC algorithm in OpenJDK 11
17+
* Test unified java logging ZGC algorithm
1718
*/
1819
public class TestDataReaderUJLZGC {
1920
private static final int CONCURRENT_MARK_INDEX = 0;
@@ -256,4 +257,61 @@ public void testDefaultGcSystemGc() {
256257
false);
257258
}
258259

259-
}
260+
/** Complement other gc type tests for ZGC */
261+
@Test
262+
public void testGcOther() throws Exception {
263+
GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
264+
265+
assertThat("size", model.size(), is(21));
266+
assertThat("amount of gc event types", model.getGcEventPauses().size(), is(15));
267+
assertThat("amount of gc events", model.getGCPause().getN(), is(15));
268+
assertThat("amount of full gc event types", model.getFullGcEventPauses().size(), is(0));
269+
assertThat("amount of gc phases event types", model.getGcEventPhases().size(), is(3));
270+
assertThat("amount of full gc events", model.getFullGCPause().getN(), is(0));
271+
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(6));
272+
assertThat("total heap size", model.getHeapAllocatedSizes().getMax(), is(3884 * 1024));
273+
}
274+
275+
@Test
276+
public void testAllocationStall() throws Exception {
277+
GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
278+
279+
AbstractGCEvent<?> allocationStallEvent = model.get(5);
280+
UnittestHelper.testMemoryPauseEvent(allocationStallEvent,
281+
"Allocation Stall",
282+
AbstractGCEvent.Type.UJL_ZGC_ALLOCATION_STALL,
283+
0.029092,
284+
0, 0, 0,
285+
AbstractGCEvent.Generation.TENURED,
286+
false);
287+
}
288+
289+
@Test
290+
public void testRelocationStall() throws Exception {
291+
GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
292+
293+
AbstractGCEvent<?> RelocationStallEvent = model.get(12);
294+
UnittestHelper.testMemoryPauseEvent(RelocationStallEvent,
295+
"Relocation Stall",
296+
AbstractGCEvent.Type.UJL_ZGC_RELOCATION_STALL,
297+
0.000720,
298+
0, 0, 0,
299+
AbstractGCEvent.Generation.TENURED,
300+
false);
301+
}
302+
303+
@Test
304+
public void testConcurrentMarkFree() throws Exception {
305+
GCModel model = getGCModelFromLogFile("sample-ujl-zgc-gc-other.txt");
306+
307+
AbstractGCEvent<?> RelocationStallEvent = model.get(2);
308+
UnittestHelper.testMemoryPauseEvent(RelocationStallEvent,
309+
"Concurrent Mark Free",
310+
AbstractGCEvent.Type.UJL_ZGC_CONCURRENT_MARK_FREE,
311+
0.000001,
312+
0, 0, 0,
313+
AbstractGCEvent.Generation.TENURED,
314+
false);
315+
}
316+
317+
}
Lines changed: 37 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,37 @@
1+
[200.343s][info][gc,start ] GC(25) Garbage Collection (Allocation Rate)
2+
[200.344s][info][gc,phases ] GC(25) Pause Mark Start 0.008ms
3+
[201.482s][info][gc ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.1) 0.706ms
4+
[201.507s][info][gc,phases ] GC(25) Concurrent Mark 1163.494ms
5+
[201.507s][info][gc,phases ] GC(25) Pause Mark End 0.011ms
6+
[201.507s][info][gc,phases ] GC(25) Concurrent Mark Free 0.001ms
7+
[201.510s][info][gc,phases ] GC(25) Concurrent Process Non-Strong References 3.045ms
8+
[201.510s][info][gc,phases ] GC(25) Concurrent Reset Relocation Set 0.072ms
9+
[201.511s][info][gc ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.10) 29.092ms
10+
[201.511s][info][gc ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.7) 11.429ms
11+
[201.511s][info][gc ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.2) 11.428ms
12+
[201.511s][info][gc ] Allocation Stall (Group1.Backend.CompositeBackend{Tier3}.8) 11.050ms
13+
[201.511s][info][gc ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.11) 10.880ms
14+
[201.511s][info][gc ] Allocation Stall (Group1.Backend.CompositeBackend{Tier1}.4) 10.660ms
15+
[201.519s][info][gc,phases ] GC(25) Concurrent Select Relocation Set 8.186ms
16+
[201.519s][info][gc,phases ] GC(25) Pause Relocate Start 0.006ms
17+
[201.521s][info][gc ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.3) 0.720ms
18+
[201.521s][info][gc ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.4) 0.771ms
19+
[201.521s][info][gc ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.8) 0.725ms
20+
[201.521s][info][gc ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.5) 0.672ms
21+
[201.521s][info][gc ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.10) 0.777ms
22+
[201.521s][info][gc ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.2) 0.782ms
23+
[201.521s][info][gc ] Relocation Stall (Group1.Backend.CompositeBackend{Tier1}.7) 0.799ms
24+
[201.657s][info][gc,phases ] GC(25) Concurrent Relocate 138.752ms
25+
[201.658s][info][gc,metaspace] GC(25) Metaspace: 17M used, 17M committed, 1040M reserved
26+
[201.658s][info][gc,heap ] GC(25) Min Capacity: 8M(0%)
27+
[201.658s][info][gc,heap ] GC(25) Max Capacity: 3954M(100%)
28+
[201.658s][info][gc,heap ] GC(25) Soft Max Capacity: 3954M(100%)
29+
[201.658s][info][gc,heap ] GC(25) Mark Start Mark End Relocate Start Relocate End High Low
30+
[201.658s][info][gc,heap ] GC(25) Capacity: 3884M (98%) 3954M (100%) 3954M (100%) 3954M (100%) 3954M (100%) 3884M (98%)
31+
[201.658s][info][gc,heap ] GC(25) Free: 620M (16%) 0M (0%) 56M (1%) 1724M (44%) 1724M (44%) 0M (0%)
32+
[201.658s][info][gc,heap ] GC(25) Used: 3334M (84%) 3954M (100%) 3898M (99%) 2230M (56%) 3954M (100%) 2230M (56%)
33+
[201.658s][info][gc,heap ] GC(25) Live: - 1359M (34%) 1359M (34%) 1359M (34%) - -
34+
[201.658s][info][gc,heap ] GC(25) Allocated: - 620M (16%) 628M (16%) 691M (17%) - -
35+
[201.658s][info][gc,heap ] GC(25) Garbage: - 1974M (50%) 1910M (48%) 178M (5%) - -
36+
[201.658s][info][gc,heap ] GC(25) Reclaimed: - - 64M (2%) 1795M (45%) - -
37+
[201.658s][info][gc ] GC(25) Garbage Collection (Allocation Rate) 3334M(84%)->2230M(56%)

0 commit comments

Comments
 (0)