Skip to content

Commit e8e26e9

Browse files
chewiebugchewiebug
committed
Merge branch 'feature/#198/shenandoah-non-unified-logging-format' into develop
2 parents b363505 + a62a8af commit e8e26e9

File tree

6 files changed

+176
-53
lines changed

6 files changed

+176
-53
lines changed

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

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -180,7 +180,7 @@ private boolean isNumberCharacter(char character) {
180180
|| character == ','; // some localised log files contain "," instead of "." in numbers
181181
}
182182

183-
protected void setMemory(GCEvent event, String line, ParseInformation pos) throws ParseException {
183+
protected void setMemory(AbstractGCEvent<?> event, String line, ParseInformation pos) throws ParseException {
184184
int start = skipUntilNextDigit(line, pos);
185185
int end = line.indexOf("->", pos.getIndex()) - 1;
186186
if (end != -2) for (start = end-1; start >= 0 && Character.isDigit(line.charAt(start)); start--) {}
@@ -226,7 +226,12 @@ protected double parsePause(String line, ParseInformation pos) throws ParseExcep
226226
if (end < 0) {
227227
end = line.indexOf(']', begin);
228228
}
229-
final double pause = NumberParser.parseDouble(line.substring(begin, end));
229+
double pause = NumberParser.parseDouble(line.substring(begin, end));
230+
231+
// ms...
232+
if (line.endsWith("ms]")) {
233+
pause = pause / 1000;
234+
}
230235

231236
// skip "secs]"
232237
pos.setIndex(line.indexOf(']', end) + 1);

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -164,7 +164,7 @@ else if (s.contains(" (young)") || s.contains("G1Ergonomics") || s.contains(" (m
164164
if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Sun 1.6.x G1 collector");
165165
return new DataReaderSun1_6_0G1(gcResource, in, GcLogType.SUN1_6G1);
166166
}
167-
else if (s.contains("[Times:")) {
167+
else if (s.contains("[Times:") || s.contains("[Pause Init Mark") /* Shenandoah, -XX:-PrintGCDetails */) {
168168
// all 1.6 lines end with a block like this "[Times: user=1.13 sys=0.08, real=0.95 secs]"
169169
if (getLogger().isLoggable(Level.INFO)) getLogger().info("File format: Sun 1.6.x");
170170
return new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_6);

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

Lines changed: 50 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -1,10 +1,5 @@
11
package com.tagtraum.perf.gcviewer.imp;
22

3-
import com.tagtraum.perf.gcviewer.model.*;
4-
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.*;
5-
import com.tagtraum.perf.gcviewer.util.NumberParser;
6-
import com.tagtraum.perf.gcviewer.util.ParseInformation;
7-
83
import java.io.IOException;
94
import java.io.InputStream;
105
import java.io.LineNumberReader;
@@ -17,6 +12,20 @@
1712
import java.util.regex.Matcher;
1813
import java.util.regex.Pattern;
1914

15+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
16+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.CollectionType;
17+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Concurrency;
18+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.ExtendedType;
19+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.GcPattern;
20+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
21+
import com.tagtraum.perf.gcviewer.model.ConcurrentGCEvent;
22+
import com.tagtraum.perf.gcviewer.model.GCEvent;
23+
import com.tagtraum.perf.gcviewer.model.GCModel;
24+
import com.tagtraum.perf.gcviewer.model.GCResource;
25+
import com.tagtraum.perf.gcviewer.model.VmOperationEvent;
26+
import com.tagtraum.perf.gcviewer.util.NumberParser;
27+
import com.tagtraum.perf.gcviewer.util.ParseInformation;
28+
2029
/**
2130
* Parses log output from Sun / Oracle Java 1.4 / 1.5 / 1.6. / 1.7 / 1.8.
2231
* <p>
@@ -27,6 +36,7 @@
2736
* <li>-XX:+UseParNewGC</li>
2837
* <li>-XX:+UseParallelOldGC</li>
2938
* <li>-XX:+UseConcMarkSweepGC</li>
39+
* <li>-XX:+UseShenandoahGC</li>
3040
* <li>-Xincgc (1.4 / 1.5)</li>
3141
* </ul>
3242
* <p>
@@ -102,6 +112,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
102112
EXCLUDE_STRINGS.add("PS" + ADAPTIVE_PATTERN); // -XX:PrintAdaptiveSizePolicy
103113
EXCLUDE_STRINGS.add(" avg_survived_padded_avg"); // -XX:PrintAdaptiveSizePolicy
104114
EXCLUDE_STRINGS.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs
115+
EXCLUDE_STRINGS.add("Uncommitted"); // -XX:+UseShenandoahGC
116+
EXCLUDE_STRINGS.add("Cancelling concurrent GC"); // -XX:+UseShenandoahGC
105117
}
106118

107119
private static final String EVENT_YG_OCCUPANCY = "YG occupancy";
@@ -538,7 +550,6 @@ private boolean isCmsScavengeBeforeRemark(String line) {
538550
}
539551

540552
protected AbstractGCEvent<?> parseLine(String line, ParseInformation pos) throws ParseException {
541-
AbstractGCEvent<?> ae = null;
542553
try {
543554
// parse datestamp "yyyy-MM-dd'T'hh:mm:ssZ:"
544555
// parse timestamp "double:"
@@ -548,57 +559,46 @@ protected AbstractGCEvent<?> parseLine(String line, ParseInformation pos) throws
548559
ZonedDateTime datestamp = parseDatestamp(line, pos);
549560
double timestamp = getTimestamp(line, pos, datestamp);
550561
ExtendedType type = parseType(line, pos);
551-
// special provision for CMS events
562+
AbstractGCEvent<?> ae;
552563
if (type.getConcurrency() == Concurrency.CONCURRENT) {
553564
ae = new ConcurrentGCEvent();
554-
ConcurrentGCEvent event = (ConcurrentGCEvent)ae;
555-
556-
// simple concurrent events (ending with -start) just are of type GcPattern.GC
557-
event.setDateStamp(datestamp);
558-
event.setTimestamp(timestamp);
559-
event.setExtendedType(type);
560-
if (type.getPattern() == GcPattern.GC_PAUSE_DURATION) {
561-
// the -end events contain a pause and duration as well
562-
int start = pos.getIndex();
563-
int end = line.indexOf('/', pos.getIndex());
564-
event.setPause(NumberParser.parseDouble(line.substring(start, end)));
565-
start = end + 1;
566-
end = line.indexOf(' ', start);
567-
event.setDuration(NumberParser.parseDouble(line.substring(start, end)));
568-
}
569-
// nothing more to parse...
570-
}
571-
else if (type.getCollectionType().equals(CollectionType.VM_OPERATION)) {
565+
} else if (type.getCollectionType().equals(CollectionType.VM_OPERATION)) {
572566
ae = new VmOperationEvent();
573-
VmOperationEvent vmOpEvent = (VmOperationEvent) ae;
574-
575-
vmOpEvent.setDateStamp(datestamp);
576-
vmOpEvent.setTimestamp(timestamp);
577-
vmOpEvent.setExtendedType(type);
578-
vmOpEvent.setPause(parsePause(line, pos));
579-
}
580-
else {
567+
} else {
581568
ae = new GCEvent();
582-
GCEvent event = (GCEvent) ae;
583-
584-
event.setDateStamp(datestamp);
585-
event.setTimestamp(timestamp);
586-
event.setExtendedType(type);
587-
// now add detail gcevents, should they exist
588-
parseDetailEventsIfExist(line, pos, event);
589-
if (event.getExtendedType().getPattern() == GcPattern.GC_MEMORY_PAUSE
590-
|| event.getExtendedType().getPattern() == GcPattern.GC_MEMORY) {
569+
}
591570

592-
setMemory(event, line, pos);
593-
}
594-
// then more detail events follow (perm gen is usually here)
595-
parseDetailEventsIfExist(line, pos, event);
596-
if (event.getExtendedType().getPattern() == GcPattern.GC_MEMORY_PAUSE
597-
|| event.getExtendedType().getPattern() == GcPattern.GC_PAUSE) {
571+
ae.setDateStamp(datestamp);
572+
ae.setTimestamp(timestamp);
573+
ae.setExtendedType(type);
574+
// now add detail gcevents, should they exist
575+
if (ae instanceof GCEvent) {
576+
parseDetailEventsIfExist(line, pos, (GCEvent) ae);
577+
}
578+
if (type.getPattern() == GcPattern.GC_MEMORY_PAUSE
579+
|| type.getPattern() == GcPattern.GC_MEMORY) {
598580

599-
event.setPause(parsePause(line, pos));
600-
}
581+
setMemory(ae, line, pos);
582+
}
583+
// then more detail events follow (perm gen is usually here)
584+
if (ae instanceof GCEvent) {
585+
parseDetailEventsIfExist(line, pos, (GCEvent)ae);
601586
}
587+
if (type.getPattern() == GcPattern.GC_MEMORY_PAUSE
588+
|| type.getPattern() == GcPattern.GC_PAUSE) {
589+
590+
ae.setPause(parsePause(line, pos));
591+
} else if (type.getPattern() == GcPattern.GC_PAUSE_DURATION) {
592+
// special case only occurring with concurrent collections...
593+
// the -end events contain a pause and duration as well
594+
int start = pos.getIndex();
595+
int end = line.indexOf('/', pos.getIndex());
596+
ae.setPause(NumberParser.parseDouble(line.substring(start, end)));
597+
start = end + 1;
598+
end = line.indexOf(' ', start);
599+
((ConcurrentGCEvent) ae).setDuration(NumberParser.parseDouble(line.substring(start, end)));
600+
}
601+
602602
return ae;
603603
}
604604
catch (RuntimeException rte) {

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

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -642,6 +642,7 @@ public String toString() {
642642
public static final Type UJL_SHEN_FINAL_UPDATE_REFS = new Type("Pause Final Update Refs", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE);
643643
public static final Type UJL_SHEN_CONCURRENT_CONC_MARK = new Type("Concurrent marking", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
644644
public static final Type UJL_SHEN_CONCURRENT_CONC_EVAC = new Type("Concurrent evacuation", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
645+
public static final Type UJL_SHEN_CONCURRENT_CANCEL_CONC_MARK = new Type("Cancel concurrent mark", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_PAUSE);
645646
public static final Type UJL_SHEN_CONCURRENT_CONC_RESET_BITMAPS = new Type("Concurrent reset bitmaps", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
646647
public static final Type UJL_SHEN_CONCURRENT_CONC_UPDATE_REFS = new Type("Concurrent update references", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);
647648
public static final Type UJL_SHEN_CONCURRENT_PRECLEANING = new Type("Concurrent precleaning", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC_MEMORY_PAUSE);

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

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -323,4 +323,15 @@ public void testOracleG1J8() throws Exception {
323323
assertDataReader(DataReaderSun1_6_0G1.class, dr.getClass());
324324
}
325325

326+
@Test
327+
public void testOracleShenandoahJ8Simple() throws Exception {
328+
DataReaderFactory factory = new DataReaderFactory();
329+
DataReader dr = factory.getDataReader(new GcResourceFile("byteArray"), new ByteArrayInputStream((
330+
"OpenJDK 64-Bit Server VM (25.161-b14) for linux-amd64 JRE (1.8.0_161-b14), built on Jan 9 2018 19:54:33 by \"mockbuild\" with gcc 4.8.5 20150623 (Red Hat 4.8.5-16)\n" +
331+
"Memory: 4k page, physical 8002012k(4357532k free), swap 2097148k(1656904k free)\n" +
332+
"CommandLine flags: -XX:HeapDumpPath=/work -XX:InitialHeapSize=2147483648 -XX:LogFile=/log/jvm.log -XX:+LogVMOutput -XX:+ManagementServer -XX:MaxHeapSize=2147483648 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseNUMA -XX:+UseShenandoahGC \n" +
333+
"13.976: [Pause Init Mark, 3.587 ms]\n").getBytes()));
334+
assertDataReader(DataReaderSun1_6_0.class, dr.getClass());
335+
}
336+
326337
}

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

Lines changed: 106 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,12 +6,14 @@
66
import static org.junit.Assert.assertEquals;
77
import static org.junit.Assert.assertThat;
88

9+
import java.io.ByteArrayInputStream;
910
import java.io.IOException;
1011
import java.io.InputStream;
1112
import java.util.logging.Level;
1213

1314
import com.tagtraum.perf.gcviewer.UnittestHelper;
1415
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
16+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
1517
import com.tagtraum.perf.gcviewer.model.GCModel;
1618
import com.tagtraum.perf.gcviewer.model.GCResource;
1719
import com.tagtraum.perf.gcviewer.model.GcResourceFile;
@@ -132,4 +134,108 @@ public void cmsPrintHeapBeforeFullGc() throws Exception {
132134

133135
assertEquals("number of errors", 0, handler.getCount());
134136
}
137+
138+
@Test
139+
public void shenandoahPauseMark() throws Exception {
140+
TestLogHandler handler = new TestLogHandler();
141+
handler.setLevel(Level.WARNING);
142+
GCResource gcResource = new GcResourceFile("byteArray");
143+
gcResource.getLogger().addHandler(handler);
144+
145+
ByteArrayInputStream in = new ByteArrayInputStream(
146+
("13.976: [Pause Init Mark, 3.587 ms]" +
147+
"\n13.992: [Pause Final Mark 1447M->684M(2048M), 2.279 ms]")
148+
.getBytes());
149+
150+
DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
151+
GCModel model = reader.read();
152+
153+
assertThat("gc count", model.size(), is(2));
154+
assertThat("warnings", handler.getCount(), is(0));
155+
156+
AbstractGCEvent<?> initMarkEvent = model.get(0);
157+
assertThat("Pause init mark: name", initMarkEvent.getTypeAsString(), equalTo("Pause Init Mark"));
158+
assertThat("Pause init mark: duration", initMarkEvent.getPause(), closeTo(0.003587, 0.00001));
159+
160+
AbstractGCEvent<?> finalMarkEvent = model.get(1);
161+
assertThat("Pause final mark: name", finalMarkEvent.getTypeAsString(), equalTo("Pause Final Mark"));
162+
assertThat("Pause final mark: duration", finalMarkEvent.getPause(), closeTo(0.002279, 0.00001));
163+
assertThat("Pause final mark: before", finalMarkEvent.getPreUsed(), is(1447 * 1024));
164+
}
165+
166+
@Test
167+
public void shenandoahPauseUpdateRefs() throws Exception {
168+
TestLogHandler handler = new TestLogHandler();
169+
handler.setLevel(Level.WARNING);
170+
GCResource gcResource = new GcResourceFile("byteArray");
171+
gcResource.getLogger().addHandler(handler);
172+
173+
ByteArrayInputStream in = new ByteArrayInputStream(
174+
("14.001: [Pause Init Update Refs, 0.073 ms]" +
175+
"\n14.016: [Pause Final Update Refs 726M->60M(2048M), 0.899 ms]")
176+
.getBytes());
177+
178+
DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
179+
GCModel model = reader.read();
180+
181+
assertThat("gc count", model.size(), is(2));
182+
assertThat("warnings", handler.getCount(), is(0));
183+
184+
AbstractGCEvent<?> initUpdateRefsEvent = model.get(0);
185+
assertThat("Pause init update refs: name", initUpdateRefsEvent.getTypeAsString(), equalTo("Pause Init Update Refs"));
186+
assertThat("Pause init update refs: duration", initUpdateRefsEvent.getPause(), closeTo(0.000073, 0.0000001));
187+
188+
AbstractGCEvent<?> finalUpdateRefsEvent = model.get(1);
189+
assertThat("Pause Final Update Refs: name", finalUpdateRefsEvent.getTypeAsString(), equalTo("Pause Final Update Refs"));
190+
assertThat("Pause Final Update Refs: duration", finalUpdateRefsEvent.getPause(), closeTo(0.000899, 0.00001));
191+
assertThat("Pause Final Update Refs: before", finalUpdateRefsEvent.getPreUsed(), is(726 * 1024));
192+
}
193+
194+
@Test
195+
public void shehandoahConcurrentEvents() throws Exception {
196+
TestLogHandler handler = new TestLogHandler();
197+
handler.setLevel(Level.WARNING);
198+
GCResource gcResource = new GcResourceFile("byteArray");
199+
gcResource.getLogger().addHandler(handler);
200+
201+
ByteArrayInputStream in = new ByteArrayInputStream(
202+
("13.979: [Concurrent marking 1435M->1447M(2048M), 12.576 ms]" +
203+
"\n13.994: [Concurrent evacuation 684M->712M(2048M), 6.041 ms]" +
204+
"\n14.001: [Concurrent update references 713M->726M(2048M), 14.718 ms]" +
205+
"\n14.017: [Concurrent reset bitmaps 60M->62M(2048M), 0.294 ms]" +
206+
"\n626.259: [Cancel concurrent mark, 0.056 ms]\n")
207+
.getBytes());
208+
209+
DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
210+
GCModel model = reader.read();
211+
212+
assertThat("gc count", model.size(), is(5));
213+
assertThat("warnings", handler.getCount(), is(0));
214+
215+
AbstractGCEvent<?> concurrentMarking = model.get(0);
216+
assertThat("Concurrent Marking: name", concurrentMarking.getTypeAsString(), equalTo("Concurrent marking"));
217+
assertThat("Concurrent Marking: duration", concurrentMarking.getPause(), closeTo(0.012576, 0.0000001));
218+
assertThat("Concurrent Marking: before", concurrentMarking.getPreUsed(), is(1435 * 1024));
219+
assertThat("Concurrent Marking: after", concurrentMarking.getPostUsed(), is(1447 * 1024));
220+
assertThat("Concurrent Marking: total", concurrentMarking.getTotal(), is(2048 * 1024));
221+
}
222+
223+
@Test
224+
public void shenandoahIgnoredLines() throws Exception {
225+
TestLogHandler handler = new TestLogHandler();
226+
handler.setLevel(Level.WARNING);
227+
GCResource gcResource = new GcResourceFile("byteArray");
228+
gcResource.getLogger().addHandler(handler);
229+
230+
ByteArrayInputStream in = new ByteArrayInputStream(
231+
("Uncommitted 87M. Heap: 2048M reserved, 1961M committed, 992M used" +
232+
"\nCancelling concurrent GC: Allocation Failure")
233+
.getBytes());
234+
235+
DataReader reader = new DataReaderSun1_6_0(gcResource, in, GcLogType.SUN1_8);
236+
GCModel model = reader.read();
237+
238+
assertThat("gc count", model.size(), is(0));
239+
assertThat("warnings", handler.getCount(), is(0));
240+
}
135241
}

0 commit comments

Comments
 (0)