Skip to content

Commit 44c761e

Browse files
chewiebugchewiebug
committed
support "Total time for which application threads were stopped" in DataReaderUnifiedJvmLogging
1 parent 4a09773 commit 44c761e

File tree

8 files changed

+94
-45
lines changed

8 files changed

+94
-45
lines changed

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

Lines changed: 25 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -14,13 +14,15 @@
1414

1515
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
1616
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Concurrency;
17+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType;
1718
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.GcPattern;
1819
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
1920
import com.tagtraum.perf.gcviewer.model.ConcurrentGCEvent;
2021
import com.tagtraum.perf.gcviewer.model.GCEvent;
2122
import com.tagtraum.perf.gcviewer.model.GCEventUJL;
2223
import com.tagtraum.perf.gcviewer.model.GCModel;
2324
import com.tagtraum.perf.gcviewer.model.GCResource;
25+
import com.tagtraum.perf.gcviewer.model.VmOperationEvent;
2426
import com.tagtraum.perf.gcviewer.util.DateHelper;
2527
import com.tagtraum.perf.gcviewer.util.NumberParser;
2628

@@ -157,9 +159,10 @@ public class DataReaderUnifiedJvmLogging extends AbstractDataReader {
157159
private static final String TAG_GC_HEAP = "gc,heap";
158160
private static final String TAG_GC_METASPACE = "gc,metaspace";
159161
private static final String TAG_GC_PHASES = "gc,phases";
162+
private static final String TAG_SAFEPOINT = "safepoint";
160163

161164
/** list of strings, that must be part of the gc log line to be considered for parsing */
162-
private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE, "[" + TAG_GC_PHASES);
165+
private static final List<String> INCLUDE_STRINGS = Arrays.asList("[gc ", "[gc]", "[" + TAG_GC_START, "[" + TAG_GC_HEAP, "[" + TAG_GC_METASPACE, "[" + TAG_GC_PHASES, Type.APPLICATION_STOPPED_TIME.getName());
163166
/** list of strings, that target gc log lines, that - although part of INCLUDE_STRINGS - are not considered a gc event */
164167
private static final List<String> EXCLUDE_STRINGS = Arrays.asList("Cancelling concurrent GC",
165168
"[debug",
@@ -228,6 +231,9 @@ private ParseContext parseEvent(ParseContext context) {
228231
private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> event, String tags, String tail) {
229232
AbstractGCEvent<?> returnEvent = event;
230233
switch (tags) {
234+
case TAG_SAFEPOINT:
235+
returnEvent = handleTagSafepoint(context, event, tail);
236+
break;
231237
case TAG_GC_START:
232238
returnEvent = handleTagGcStartTail(context, event);
233239
break;
@@ -254,6 +260,11 @@ private AbstractGCEvent<?> handleTail(ParseContext context, AbstractGCEvent<?> e
254260
return returnEvent;
255261
}
256262

263+
private AbstractGCEvent<?> handleTagSafepoint(ParseContext context, AbstractGCEvent<?> event, String tail) {
264+
event.setPause(NumberParser.parseDouble(tail.split(" ")[0]));
265+
return event;
266+
}
267+
257268
private AbstractGCEvent<?> handleTagGcStartTail(ParseContext context, AbstractGCEvent<?> event) {
258269
// here, the gc type is known, and the partial events will need to be added later
259270
context.getPartialEventsMap().put(event.getNumber() + "", event);
@@ -459,7 +470,7 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decorator
459470
if (decoratorsMatcher.find()) {
460471
AbstractGCEvent.ExtendedType type = getDataReaderTools().parseType(decoratorsMatcher.group(GROUP_DECORATORS_GC_TYPE));
461472

462-
AbstractGCEvent<?> event = type.getConcurrency().equals(Concurrency.CONCURRENT) ? new ConcurrentGCEvent() : new GCEventUJL();
473+
AbstractGCEvent<?> event = createGcEvent(type);
463474
event.setExtendedType(type);
464475
if (decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER) != null) {
465476
event.setNumber(Integer.parseInt(decoratorsMatcher.group(GROUP_DECORATORS_GC_NUMBER)));
@@ -473,6 +484,18 @@ private AbstractGCEvent<?> createGcEventWithStandardDecorators(Matcher decorator
473484
}
474485
}
475486

487+
private AbstractGCEvent<?> createGcEvent(ExtendedType type) {
488+
AbstractGCEvent<?> event;
489+
if (type.getConcurrency().equals(Concurrency.CONCURRENT)) {
490+
event = new ConcurrentGCEvent();
491+
} else if (type.getType().equals(Type.APPLICATION_STOPPED_TIME)) {
492+
event = new VmOperationEvent();
493+
} else {
494+
event = new GCEventUJL();
495+
}
496+
return event;
497+
}
498+
476499
private void setPause(AbstractGCEvent event, String pauseAsString) {
477500
// TODO remove code duplication with AbstractDataReaderSun -> move to DataReaderTools
478501
if (pauseAsString != null && pauseAsString.length() > 0) {

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -667,7 +667,7 @@ public String toString() {
667667
public static final Type UJL_G1_EDEN = new Type("Eden regions", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_REGION);
668668
public static final Type UJL_G1_SURVIVOR = new Type("Survivor regions", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_REGION);
669669
public static final Type UJL_G1_OLD = new Type("Old regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
670-
public static final Type UJL_G1_HUMongous = new Type("Humongous regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
670+
public static final Type UJL_G1_HUMONGOUS = new Type("Humongous regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
671671
public static final Type UJL_G1_ARCHIVE = new Type("Archive regions", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_REGION);
672672

673673
public static final Type UJL_G1_PHASE_PRE_EVACUATE_COLLECTION_SET = new Type("Pre Evacuate Collection Set", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_PAUSE);

‎src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLCMS.java‎

Lines changed: 8 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -91,12 +91,13 @@ public void parseGcDefaults() throws Exception {
9191
@Test
9292
public void parseGcAllSafepointOsCpu() throws Exception {
9393
GCModel model = getGCModelFromLogFile("sample-ujl-cms-gc-all,safepoint,os+cpu.txt");
94-
assertThat("size", model.size(), is(26));
94+
assertThat("size", model.size(), is(37));
9595
assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(3));
96+
assertThat("amount of VM operation pause types", model.getVmOperationPause().getN(), is(11));
9697
assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1));
9798
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(4));
9899

99-
AbstractGCEvent<?> event1 = model.get(0);
100+
AbstractGCEvent<?> event1 = model.get(1);
100101
UnittestHelper.testMemoryPauseEvent(event1,
101102
"young",
102103
Type.UJL_PAUSE_YOUNG,
@@ -106,7 +107,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
106107
false);
107108

108109
// GC(3) Pause Initial Mark
109-
AbstractGCEvent<?> event2 = model.get(3);
110+
AbstractGCEvent<?> event2 = model.get(7);
110111
UnittestHelper.testMemoryPauseEvent(event2,
111112
"initial mark",
112113
Type.UJL_PAUSE_INITIAL_MARK,
@@ -117,7 +118,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
117118
assertThat("isInitialMark", event2.isInitialMark(), is(true));
118119

119120
// GC(3) Pause Remark
120-
AbstractGCEvent<?> remarkEvent = model.get(10);
121+
AbstractGCEvent<?> remarkEvent = model.get(15);
121122
UnittestHelper.testMemoryPauseEvent(remarkEvent,
122123
"remark",
123124
Type.UJL_PAUSE_REMARK,
@@ -128,7 +129,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
128129
assertThat("isRemark", remarkEvent.isRemark(), is(true));
129130

130131
// GC(5) Pause Full
131-
AbstractGCEvent<?> fullGcEvent = model.get(13);
132+
AbstractGCEvent<?> fullGcEvent = model.get(19);
132133
UnittestHelper.testMemoryPauseEvent(fullGcEvent,
133134
"full gc ",
134135
Type.UJL_PAUSE_FULL,
@@ -137,10 +138,10 @@ public void parseGcAllSafepointOsCpu() throws Exception {
137138
Generation.ALL,
138139
true);
139140

140-
AbstractGCEvent<?> concurrentMarkBeginEvent = model.get(4);
141+
AbstractGCEvent<?> concurrentMarkBeginEvent = model.get(9);
141142
assertThat("event is not start of concurrent collection", concurrentMarkBeginEvent.isConcurrentCollectionStart(), is(false));
142143

143-
AbstractGCEvent<?> concurrentMarkWithPauseEvent = model.get(5);
144+
AbstractGCEvent<?> concurrentMarkWithPauseEvent = model.get(10);
144145
assertThat("event is start of concurrent collection", concurrentMarkWithPauseEvent.isConcurrentCollectionStart(), is(true));
145146
}
146147

‎src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1.java‎

Lines changed: 13 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -108,14 +108,15 @@ public void parseGcDefaults() throws Exception {
108108
@Test
109109
public void parseGcAllSafepointOsCpu() throws Exception {
110110
GCModel model = getGCModelFromLogFile("sample-ujl-g1-gc-all,safepoint,os+cpu.txt");
111-
assertThat("size", model.size(), is(15));
111+
assertThat("size", model.size(), is(29));
112112
assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(4));
113113
assertThat("amount of STW GC pauses", model.getGCPause().getN(), is(13));
114+
assertThat("amount of VM operation pauses", model.getVmOperationPause().getN(), is(14));
114115
assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(0));
115116
assertThat("amount of STW Full GC pauses", model.getFullGCPause().getN(), is(0));
116117
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(1));
117118

118-
AbstractGCEvent<?> event1 = model.get(0);
119+
AbstractGCEvent<?> event1 = model.get(1);
119120
UnittestHelper.testMemoryPauseEvent(event1,
120121
"young",
121122
Type.UJL_PAUSE_YOUNG,
@@ -125,8 +126,8 @@ public void parseGcAllSafepointOsCpu() throws Exception {
125126
false);
126127
assertThat("young heap before", event1.details().next().getPreUsed(), is(1024 * 14));
127128

128-
// GC(3) Pause Initial Mark
129-
AbstractGCEvent<?> event2 = model.get(5);
129+
// GC(6) Pause Initial Mark
130+
AbstractGCEvent<?> event2 = model.get(11);
130131
UnittestHelper.testMemoryPauseEvent(event2,
131132
"initial mark",
132133
Type.UJL_PAUSE_INITIAL_MARK,
@@ -136,8 +137,8 @@ public void parseGcAllSafepointOsCpu() throws Exception {
136137
false);
137138
assertThat("isInitialMark", event2.isInitialMark(), is(true));
138139

139-
// GC(3) Pause Remark
140-
AbstractGCEvent<?> remarkEvent = model.get(10);
140+
// GC(6) Pause Remark
141+
AbstractGCEvent<?> remarkEvent = model.get(20);
141142
UnittestHelper.testMemoryPauseEvent(remarkEvent,
142143
"remark",
143144
Type.UJL_PAUSE_REMARK,
@@ -147,7 +148,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
147148
false);
148149
assertThat("isRemark", remarkEvent.isRemark(), is(true));
149150

150-
AbstractGCEvent<?> cleanupEvent = model.get(13);
151+
AbstractGCEvent<?> cleanupEvent = model.get(26);
151152
UnittestHelper.testMemoryPauseEvent(cleanupEvent,
152153
"cleanup",
153154
Type.UJL_G1_PAUSE_CLEANUP,
@@ -156,12 +157,14 @@ public void parseGcAllSafepointOsCpu() throws Exception {
156157
Generation.TENURED,
157158
false);
158159

159-
AbstractGCEvent<?> concurrentCycleBeginEvent = model.get(6);
160+
AbstractGCEvent<?> concurrentCycleBeginEvent = model.get(13);
161+
assertThat("concurrent cycle", concurrentCycleBeginEvent.getTypeAsString(), is(Type.UJL_G1_CONCURRENT_CYCLE.getName()));
160162
assertThat("event is start of concurrent collection",
161163
concurrentCycleBeginEvent.isConcurrentCollectionStart(),
162164
is(true));
163165

164-
AbstractGCEvent<?> concurrentCycleEndEvent = model.get(14);
166+
AbstractGCEvent<?> concurrentCycleEndEvent = model.get(28);
167+
assertThat("concurrent cycle", concurrentCycleEndEvent.getTypeAsString(), is(Type.UJL_G1_CONCURRENT_CYCLE.getName()));
165168
assertThat("event is end of concurrent collection",
166169
concurrentCycleEndEvent.isConcurrentCollectionEnd(),
167170
is(true));
@@ -170,7 +173,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
170173
@Test
171174
public void parseGcAllSafepointOsCpuWithToSpaceExhausted() throws Exception {
172175
GCModel model = getGCModelFromLogFile("sample-ujl-g1-gc-all,safepoint,os+cpu-to-space-exhausted.txt");
173-
assertThat("size", model.size(), is(1));
176+
assertThat("size", model.size(), is(2));
174177
AbstractGCEvent<?> youngEvent = model.get(0);
175178
UnittestHelper.testMemoryPauseEvent(youngEvent,
176179
"young",

‎src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLG1JDK11.java‎

Lines changed: 20 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -146,7 +146,7 @@ public void testFullGcWithPhases() throws Exception {
146146
GCModel model = reader.read();
147147

148148
assertThat("number of warnings", handler.getCount(), is(0));
149-
assertThat("number of events", model.size(), is(1));
149+
assertThat("number of events", model.size(), is(2));
150150
assertThat("total heap", model.get(0).getTotal(), is(128 * 1024));
151151
}
152152

@@ -180,4 +180,23 @@ public void testPauseYoungConcurrentStartMetadataGcThreshold() throws Exception
180180
assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.UJL_PAUSE_YOUNG));
181181
assertThat("total heap", model.get(0).getTotal(), is(256 * 1024));
182182
}
183+
184+
@Test
185+
public void testTotalTimeForWhichApplicationThreadsWereStopped() throws IOException {
186+
TestLogHandler handler = new TestLogHandler();
187+
handler.setLevel(Level.WARNING);
188+
GCResource gcResource = new GcResourceFile("byteArray");
189+
gcResource.getLogger().addHandler(handler);
190+
InputStream in = new ByteArrayInputStream(
191+
("[2019-09-17T20:20:29.824+0000][19.163s][info ][safepoint ] Total time for which application threads were stopped: 0.0047914 seconds, Stopping threads took: 0.0000103 seconds\n\n")
192+
.getBytes());
193+
194+
DataReader reader = new DataReaderUnifiedJvmLogging(gcResource, in);
195+
GCModel model = reader.read();
196+
197+
assertThat("number of warnings", handler.getCount(), is(0));
198+
assertThat("number of events", model.size(), is(1));
199+
assertThat("event type", model.get(0).getExtendedType().getType(), is(Type.APPLICATION_STOPPED_TIME));
200+
assertThat("total heap", model.get(0).getPause(), closeTo(0.0047914, 0.0000001));
201+
}
183202
}

‎src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLParallel.java‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -59,7 +59,7 @@ public void parseGcDefaults() throws Exception {
5959
@Test
6060
public void parseGcAllSafepointOsCpu() throws Exception {
6161
GCModel model = getGCModelFromLogFile("sample-ujl-parallel-gc-all,safepoint,os+cpu.txt");
62-
assertThat("size", model.size(), is(8));
62+
assertThat("size", model.size(), is(14));
6363
assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(1));
6464
assertThat("amount of gc events", model.getGCPause().getN(), is(4));
6565
assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1));
@@ -68,7 +68,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
6868
assertThat("amount of events for phase 1 types", model.getGcEventPhases().get(Type.UJL_PARALLEL_PHASE_MARKING.getName()).getN(), is(4));
6969
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));
7070

71-
AbstractGCEvent<?> event1 = model.get(0);
71+
AbstractGCEvent<?> event1 = model.get(1);
7272
UnittestHelper.testMemoryPauseEvent(event1,
7373
"pause young",
7474
Type.UJL_PAUSE_YOUNG,
@@ -78,7 +78,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
7878
false);
7979

8080
// GC(6) Pause Full (Ergonomics)
81-
AbstractGCEvent<?> event2 = model.get(6);
81+
AbstractGCEvent<?> event2 = model.get(11);
8282
UnittestHelper.testMemoryPauseEvent(event2,
8383
"pause full",
8484
Type.UJL_PAUSE_FULL,
@@ -88,7 +88,7 @@ public void parseGcAllSafepointOsCpu() throws Exception {
8888
true);
8989

9090
// GC(7) Pause Young (Allocation Failure)
91-
AbstractGCEvent<?> event3 = model.get(7);
91+
AbstractGCEvent<?> event3 = model.get(13);
9292
UnittestHelper.testMemoryPauseEvent(event3,
9393
"pause young 2",
9494
Type.UJL_PAUSE_YOUNG,

‎src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLSerial.java‎

Lines changed: 11 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -65,14 +65,15 @@ public void parseGcDefaults() throws Exception {
6565
@Test
6666
public void parseGcAllSafepointOsCpu() throws Exception {
6767
GCModel model = getGCModelFromLogFile("sample-ujl-serial-gc-all,safepoint,os+cpu.txt");
68-
assertThat("size", model.size(), is(4));
68+
assertThat("size", model.size(), is(8));
6969
assertThat("amount of STW GC pause types", model.getGcEventPauses().size(), is(1));
7070
assertThat("amount of STW GC pauses", model.getGCPause().getN(), is(3));
7171
assertThat("amount of STW Full GC pause types", model.getFullGcEventPauses().size(), is(1));
7272
assertThat("amount of STW Full GC pauses", model.getFullGCPause().getN(), is(1));
73+
assertThat("amount of vm operation events", model.getVmOperationPause().getN(), is(4));
7374
assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0));
7475

75-
AbstractGCEvent<?> event1 = model.get(0);
76+
AbstractGCEvent<?> event1 = model.get(1);
7677
assertThat("event1 type", event1.getTypeAsString(), startsWith(Type.UJL_PAUSE_YOUNG.getName()));
7778
assertThat("event1 pause", event1.getPause(), closeTo(0.009814, 0.00001));
7879
assertThat("event1 heap before", event1.getPreUsed(), is(1024 * 25));
@@ -81,16 +82,16 @@ public void parseGcAllSafepointOsCpu() throws Exception {
8182

8283
// TODO fix timestamps or renderers (seeing the ujl logs, I realise, that the timestamps usually are the end of the event, not the beginning, as I kept thinking)
8384
// GC(3) Pause Full (Allocation Failure)
84-
AbstractGCEvent<?> event2 = model.get(2);
85-
assertThat("event2 type", event2.getTypeAsString(), startsWith(Type.UJL_PAUSE_FULL.getName()));
86-
assertThat("event2 pause", event2.getPause(), closeTo(0.006987, 0.00001));
87-
assertThat("event2 time", event2.getTimestamp(), closeTo(0.290, 0.0001));
85+
AbstractGCEvent<?> event5 = model.get(5);
86+
assertThat("event5 type", event5.getTypeAsString(), startsWith(Type.UJL_PAUSE_FULL.getName()));
87+
assertThat("event5 pause", event5.getPause(), closeTo(0.006987, 0.00001));
88+
assertThat("event5 time", event5.getTimestamp(), closeTo(0.290, 0.0001));
8889

8990
// GC(2) Pause Young (Allocation Failure)
90-
AbstractGCEvent<?> event3 = model.get(3);
91-
assertThat("event3 type", event3.getTypeAsString(), startsWith(Type.UJL_PAUSE_YOUNG.getName()));
92-
assertThat("event3 pause", event3.getPause(), closeTo(0.007118, 0.00001));
93-
assertThat("event3 time", event3.getTimestamp(), closeTo(0.290, 0.0001));
91+
AbstractGCEvent<?> event6 = model.get(6);
92+
assertThat("event6 type", event6.getTypeAsString(), startsWith(Type.UJL_PAUSE_YOUNG.getName()));
93+
assertThat("event6 pause", event6.getPause(), closeTo(0.007118, 0.00001));
94+
assertThat("event6 time", event6.getTimestamp(), closeTo(0.290, 0.0001));
9495
}
9596

9697
@Test

0 commit comments

Comments
 (0)