Skip to content

Commit 89bf7bf

Browse files
chewiebugchewiebug
committed
support sys + af global collections (/#175)
1 parent e8ed84c commit 89bf7bf

File tree

7 files changed

+226
-40
lines changed

7 files changed

+226
-40
lines changed

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

Lines changed: 82 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@
1919
import javax.xml.stream.events.StartElement;
2020
import javax.xml.stream.events.XMLEvent;
2121

22+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
2223
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
2324
import com.tagtraum.perf.gcviewer.model.GCEvent;
2425
import com.tagtraum.perf.gcviewer.model.GCModel;
@@ -34,6 +35,9 @@ public class DataReaderIBM_J9_R28 extends AbstractDataReader {
3435
private static final String VERBOSEGC = "verbosegc";
3536
private static final String INITIALIZED = "initialized";
3637
private static final String EXCLUSIVE_START = "exclusive-start";
38+
private static final String SYS_START = "sys-start";
39+
private static final String AF_START = "af-start";
40+
private static final String CONCURRENT_COLLECTION_START = "concurrent-collection-start";
3741
private static final String GC_START = "gc-start";
3842
private static final String GC_END = "gc-end";
3943
private static final String EXCLUSIVE_END = "exclusive-end";
@@ -54,44 +58,70 @@ public GCModel read() throws IOException {
5458
XMLInputFactory factory = XMLInputFactory.newInstance();
5559
XMLEventReader eventReader = factory.createXMLEventReader(in);
5660
GCEvent currentGcEvent = null;
61+
String eventNameStart = null;
5762
while (eventReader.hasNext()) {
58-
XMLEvent event = eventReader.nextEvent();
59-
if (event.isStartElement()) {
60-
StartElement startElement = event.asStartElement();
61-
switch (startElement.getName().getLocalPart()) {
62-
case VERBOSEGC:
63-
handleVerboseGC(startElement);
64-
break;
65-
case INITIALIZED:
66-
handleInitialized(eventReader);
67-
break;
68-
case EXCLUSIVE_START:
69-
currentGcEvent = handleExclusiveStart(startElement);
70-
break;
71-
case GC_START:
72-
handleGcStart(eventReader, startElement, currentGcEvent);
73-
break;
74-
case GC_END:
75-
handleGcEnd(eventReader, currentGcEvent);
76-
break;
77-
case EXCLUSIVE_END:
78-
handleExclusiveEnd(startElement, currentGcEvent);
79-
if (currentGcEvent.getExtendedType() == null) {
80-
if (getLogger().isLoggable(Level.FINE)) getLogger().fine("event at " + in.getLineNumber() + " doesn't contain any information, the parser can handle");
81-
} else {
82-
model.add(currentGcEvent);
83-
}
84-
currentGcEvent = null;
85-
break;
63+
try {
64+
XMLEvent event = eventReader.nextEvent();
65+
if (event.isStartElement()) {
66+
StartElement startElement = event.asStartElement();
67+
switch (startElement.getName().getLocalPart()) {
68+
case VERBOSEGC:
69+
handleVerboseGC(startElement);
70+
break;
71+
case INITIALIZED:
72+
handleInitialized(eventReader);
73+
break;
74+
case EXCLUSIVE_START:
75+
currentGcEvent = handleExclusiveStart(startElement);
76+
break;
77+
case SYS_START:
78+
assert eventNameStart == null : "eventNameStart was expected to be null, but was " + eventNameStart;
79+
eventNameStart = handleSysStart(eventReader, startElement);
80+
break;
81+
case AF_START:
82+
assert eventNameStart == null : "eventNameStart was expected to be null, but was " + eventNameStart;
83+
eventNameStart = handleAfStart(eventReader, startElement);
84+
break;
85+
case GC_START:
86+
handleGcStart(eventReader, startElement, currentGcEvent, eventNameStart);
87+
break;
88+
case GC_END:
89+
if (currentGcEvent.getTypeAsString() != null) {
90+
handleGcEnd(eventReader, currentGcEvent);
91+
}
92+
break;
93+
case EXCLUSIVE_END:
94+
handleExclusiveEnd(startElement, currentGcEvent);
95+
if (currentGcEvent.getExtendedType() == null) {
96+
if (getLogger().isLoggable(Level.FINE))
97+
getLogger().fine("event at " + in.getLineNumber() + " doesn't contain any information, the parser can handle");
98+
}
99+
else {
100+
model.add(currentGcEvent);
101+
}
102+
currentGcEvent = null;
103+
eventNameStart = null;
104+
break;
105+
}
86106
}
87-
}
88107

108+
}
109+
catch (Exception e) {
110+
if (e instanceof XMLStreamException) {
111+
throw e;
112+
}
113+
if (getLogger().isLoggable(Level.WARNING)) getLogger().warning("line " + in.getLineNumber() + ": " + e.toString());
114+
if (getLogger().isLoggable(Level.FINE)) getLogger().log(Level.FINE, "line " + in.getLineNumber() + ": " + e.getMessage(), e);
115+
}
89116
}
90117
}
91118
catch (XMLStreamException e) {
92119
if (getLogger().isLoggable(Level.WARNING)) getLogger().warning("line " + in.getLineNumber() + ": " + e.toString());
93120
if (getLogger().isLoggable(Level.FINE)) getLogger().log(Level.FINE, "line " + in.getLineNumber() + ": " + e.getMessage(), e);
94121
}
122+
finally {
123+
if (getLogger().isLoggable(Level.INFO)) getLogger().info("Done reading.");
124+
}
95125

96126
return model;
97127
}
@@ -132,21 +162,37 @@ private GCEvent handleExclusiveStart(StartElement startElement) {
132162
if (getLogger().isLoggable(Level.WARNING)) getLogger().warning("line " + in.getLineNumber() + ": " + e.toString());
133163
if (getLogger().isLoggable(Level.FINE)) getLogger().log(Level.FINE, "line " + in.getLineNumber() + ": " + e.getMessage(), e);
134164
}
135-
165+
136166
return event;
137167
}
138168

139169
private void handleExclusiveEnd(StartElement startElement, GCEvent event) {
140170
event.setPause(NumberParser.parseDouble(getAttributeValue(startElement, "durationms")) / 1000);
141171
}
142172

143-
private void handleGcStart(XMLEventReader eventReader, StartElement startElement, GCEvent event) throws XMLStreamException {
144-
event.setType(Type.lookup(getAttributeValue(startElement, "type")));
145-
if (event.getExtendedType() == null) {
146-
getLogger().warning("could not determine type of event " + startElement.toString());
147-
return;
173+
private String handleSysStart(XMLEventReader eventReader, StartElement startElement) throws XMLStreamException {
174+
String reason = getAttributeValue(startElement, "reason");
175+
return "sys " + (reason != null ? reason + " " : "");
176+
}
177+
178+
private String handleAfStart(XMLEventReader eventReader, StartElement startElement) throws XMLStreamException {
179+
return "af ";
180+
}
181+
182+
private void handleConcurrentCollectionStart(XMLEventReader eventReader, StartElement startElement) {
183+
}
184+
185+
private void handleGcStart(XMLEventReader eventReader, StartElement startElement, GCEvent event, String eventNameStart) throws
186+
XMLStreamException,
187+
UnknownGcTypeException {
188+
189+
String typeName = eventNameStart + getAttributeValue(startElement, "type");
190+
AbstractGCEvent.Type type = Type.lookup(typeName);
191+
if (type == null) {
192+
throw new UnknownGcTypeException(typeName, startElement.toString());
148193
}
149-
194+
event.setType(type);
195+
150196
String currentElementName = "";
151197
while (eventReader.hasNext() && !currentElementName.equals(GC_START)) {
152198

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

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -513,10 +513,19 @@ public String toString() {
513513

514514
// IBM Types
515515
// TODO: are scavenge always young only??
516+
public static final Type IBM_AF = new Type("af", Generation.YOUNG);
517+
public static final Type IBM_SYS = new Type("sys explicit", Generation.ALL);
518+
public static final Type IBM_AF_SCAVENGE = new Type("af scavenge", Generation.YOUNG);
519+
public static final Type IBM_AF_GLOBAL = new Type("af global", Generation.TENURED);
520+
public static final Type IBM_SYS_GLOBAL = new Type("sys global", Generation.ALL);
521+
public static final Type IBM_SYS_EXPLICIT_GLOBAL = new Type("sys explicit global", Generation.ALL);
516522
public static final Type IBM_SCAVENGE = new Type("scavenge", Generation.YOUNG, Concurrency.SERIAL);
517523
public static final Type IBM_GLOBAL = new Type("global", Generation.ALL, Concurrency.SERIAL);
518524
public static final Type IBM_NURSERY = new Type("nursery", Generation.YOUNG);
519525
public static final Type IBM_TENURE = new Type("tenure", Generation.TENURED);
526+
527+
public static final Type IBM_CONCURRENT_COLLECTION_START = new Type("concurrent-collection-start", Generation.ALL, Concurrency.CONCURRENT);
528+
520529
}
521530

522531
public static enum GcPattern {

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

Lines changed: 43 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
package com.tagtraum.perf.gcviewer.imp;
22

33
import static com.tagtraum.perf.gcviewer.UnittestHelper.toKiloBytes;
4+
import static org.hamcrest.Matchers.equalTo;
45
import static org.hamcrest.Matchers.is;
56
import static org.hamcrest.number.IsCloseTo.closeTo;
67
import static org.junit.Assert.assertThat;
@@ -13,6 +14,7 @@
1314
import com.tagtraum.perf.gcviewer.model.GCEvent;
1415
import com.tagtraum.perf.gcviewer.model.GCModel;
1516
import com.tagtraum.perf.gcviewer.model.GCResource;
17+
import org.junit.Ignore;
1618
import org.junit.Test;
1719

1820
/**
@@ -30,10 +32,10 @@ private DataReader getDataReader(GCResource gcResource) throws IOException {
3032
}
3133

3234
@Test
33-
public void testFullHeaderWithAfGcs() throws Exception {
35+
public void testAfScavenge() throws Exception {
3436
TestLogHandler handler = new TestLogHandler();
3537
handler.setLevel(Level.WARNING);
36-
GCResource gcResource = new GCResource("SampleIBMJ9_R28_full_header.txt");
38+
GCResource gcResource = new GCResource("SampleIBMJ9_R28_af_scavenge_full_header.txt");
3739
gcResource.getLogger().addHandler(handler);
3840

3941
DataReader reader = getDataReader(gcResource);
@@ -59,14 +61,35 @@ public void testFullHeaderWithAfGcs() throws Exception {
5961
assertThat("timestamp 1", event.getTimestamp(), closeTo(0.0, 0.0001));
6062
assertThat("timestamp 2", model.get(1).getTimestamp(), closeTo(1.272, 0.0001));
6163

64+
assertThat("type", event.getTypeAsString(), equalTo("af scavenge; nursery; tenure"));
65+
6266
assertThat("number of errors", handler.getCount(), is(0));
6367
}
6468

6569
@Test
66-
public void testSystemGc() throws Exception {
70+
public void testAfGlobal() throws Exception {
6771
TestLogHandler handler = new TestLogHandler();
6872
handler.setLevel(Level.WARNING);
69-
GCResource gcResource = new GCResource("SampleIBMJ9_R28_global.txt");
73+
GCResource gcResource = new GCResource("SampleIBMJ9_R28_af_global.txt");
74+
gcResource.getLogger().addHandler(handler);
75+
76+
DataReader reader = getDataReader(gcResource);
77+
GCModel model = reader.read();
78+
79+
assertThat("model size", model.size(), is(1));
80+
81+
GCEvent event = (GCEvent) model.get(0);
82+
assertThat("pause", event.getPause(), closeTo(1.255648, 0.0000001));
83+
assertThat("type", event.getTypeAsString(), equalTo("af global; tenure"));
84+
85+
assertThat("number of errors", handler.getCount(), is(0));
86+
}
87+
88+
@Test
89+
public void testSysGlobal() throws Exception {
90+
TestLogHandler handler = new TestLogHandler();
91+
handler.setLevel(Level.WARNING);
92+
GCResource gcResource = new GCResource("SampleIBMJ9_R28_sys_global.txt");
7093
gcResource.getLogger().addHandler(handler);
7194

7295
DataReader reader = getDataReader(gcResource);
@@ -76,6 +99,7 @@ public void testSystemGc() throws Exception {
7699

77100
GCEvent event = (GCEvent) model.get(0);
78101
assertThat("pause", event.getPause(), closeTo(0.097756, 0.0000001));
102+
assertThat("type", event.getTypeAsString(), equalTo("sys explicit global; nursery; tenure"));
79103

80104
assertThat("number of errors", handler.getCount(), is(0));
81105
}
@@ -95,4 +119,19 @@ public void testConcurrentMinimal() throws Exception {
95119
assertThat("number of errors", handler.getCount(), is(0));
96120
}
97121

122+
@Test @Ignore
123+
public void testConcurrentCollection() throws Exception {
124+
TestLogHandler handler = new TestLogHandler();
125+
handler.setLevel(Level.WARNING);
126+
GCResource gcResource = new GCResource("SampleIBMJ9_R28_concurrent_collection.txt");
127+
gcResource.getLogger().addHandler(handler);
128+
129+
DataReader reader = getDataReader(gcResource);
130+
GCModel model = reader.read();
131+
132+
assertThat("model size", model.size(), is(1));
133+
assertThat("duration", model.get(0).getPause(), closeTo(1.182375, 0.00000001));
134+
assertThat("number of errors", handler.getCount(), is(0));
135+
}
136+
98137
}

‎src/test/resources/ibm/SampleIBMJ9_R28_af_global.txt‎

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,44 @@
1+
<verbosegc xmlns="http://www.ibm.com/j9/verbosegc" version="R28_Java8_GA_20150116_2030_B231420_CMPRSS">
2+
3+
<exclusive-start id="9871" timestamp="2016-08-09T14:58:58.343" intervalms="14425.085">
4+
<response-info timems="1.109" idlems="0.826" threads="7" lastid="0000000033719C00" lastname="HTTP Handler 10.172.46.44" />
5+
</exclusive-start>
6+
<af-start id="9872" totalBytesRequested="40" timestamp="2016-08-09T14:58:58.346" intervalms="453274064.112" />
7+
<cycle-start id="9873" type="global" contextid="0" timestamp="2016-08-09T14:58:58.346" intervalms="14426.710" />
8+
<gc-start id="9874" type="global" contextid="9873" timestamp="2016-08-09T14:58:58.347">
9+
<mem-info id="9875" free="322121728" total="6442450944" percent="4">
10+
<mem type="tenure" free="322121728" total="6442450944" percent="4">
11+
<mem type="soa" free="0" total="6120329216" percent="0" />
12+
<mem type="loa" free="322121728" total="322121728" percent="100" />
13+
</mem>
14+
</mem-info>
15+
</gc-start>
16+
<allocation-stats totalBytes="4674836712" >
17+
<allocated-bytes non-tlh="103021496" tlh="4571815216" />
18+
<largest-consumer threadName="HTTP Handler 10.172.46.44" threadId="00000000349A0100" bytes="180588648" />
19+
</allocation-stats>
20+
<gc-op id="9876" type="mark" timems="1229.959" contextid="9873" timestamp="2016-08-09T14:58:59.577">
21+
<trace-info objectcount="34811076" scancount="27617833" scanbytes="990253856" />
22+
<finalization candidates="7738" enqueued="4005" />
23+
<ownableSynchronizers candidates="339246" cleared="73" />
24+
<references type="soft" candidates="18886" cleared="0" enqueued="0" dynamicThreshold="24" maxThreshold="32" />
25+
<references type="weak" candidates="37919" cleared="16" enqueued="16" />
26+
<references type="phantom" candidates="115" cleared="0" enqueued="0" />
27+
<stringconstants candidates="73321" cleared="28" />
28+
</gc-op>
29+
<gc-op id="9877" type="sweep" timems="7.808" contextid="9873" timestamp="2016-08-09T14:58:59.585" />
30+
<gc-end id="9878" type="global" contextid="9873" durationms="1239.395" usertimems="2046.100" systemtimems="2.290" timestamp="2016-08-09T14:58:59.586">
31+
<mem-info id="9879" free="4911161608" total="6442450944" percent="76">
32+
<mem type="tenure" free="4911161608" total="6442450944" percent="76">
33+
<mem type="soa" free="4653463848" total="6184753152" percent="75" />
34+
<mem type="loa" free="257697760" total="257697792" percent="99" />
35+
</mem>
36+
<pending-finalizers system="217" default="3788" reference="16" classloader="0" />
37+
</mem-info>
38+
</gc-end>
39+
<cycle-end id="9880" type="global" contextid="9873" timestamp="2016-08-09T14:58:59.598" />
40+
<allocation-satisfied id="9881" threadId="0000000034272200" bytesRequested="40" />
41+
<af-end id="9882" timestamp="2016-08-09T14:58:59.598" />
42+
<exclusive-end id="9883" timestamp="2016-08-09T14:58:59.598" durationms="1255.648" />
43+
44+
</verbosegc>

‎src/test/resources/ibm/SampleIBMJ9_R28_full_header.txt‎ renamed to ‎src/test/resources/ibm/SampleIBMJ9_R28_af_scavenge_full_header.txt‎

File renamed without changes.

‎src/test/resources/ibm/SampleIBMJ9_R28_concurrent_collection.txt‎

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,48 @@
1+
<verbosegc xmlns="http://www.ibm.com/j9/verbosegc" version="R28_Java8_GA_20150116_2030_B231420_CMPRSS">
2+
3+
<exclusive-start id="11420" timestamp="2016-08-09T15:14:56.110" intervalms="76.020">
4+
<response-info timems="3.943" idlems="2.966" threads="27" lastid="0000000034775300" lastname="HTTP Handler 10.172.46.44" />
5+
</exclusive-start>
6+
<concurrent-collection-start id="11421" timestamp="2016-08-09T15:14:56.114" intervalms="454231830.812" />
7+
<gc-start id="11422" type="global" contextid="11388" timestamp="2016-08-09T15:14:56.115">
8+
<mem-info id="11423" free="12883968" total="6442450944" percent="0">
9+
<mem type="tenure" free="12883968" total="6442450944" percent="0">
10+
<mem type="soa" free="0" total="6429566976" percent="0" />
11+
<mem type="loa" free="12883968" total="12883968" percent="100" />
12+
</mem>
13+
</mem-info>
14+
</gc-start>
15+
<allocation-stats totalBytes="5091236872" >
16+
<allocated-bytes non-tlh="82774752" tlh="5008462120" />
17+
<largest-consumer threadName="IS &lt;octopus#OCT_SRV_Demande_V3_0.utils.threads:actConsulterDemande&gt;" threadId="0000000034B25900" bytes="100498456" />
18+
</allocation-stats>
19+
<gc-op id="11424" type="card-cleaning" timems="35.676" contextid="11388" timestamp="2016-08-09T15:14:56.151">
20+
<card-cleaning cardsCleaned="4845" bytesTraced="7868432" workStackOverflowCount="0" />
21+
</gc-op>
22+
<gc-op id="11425" type="mark" timems="1133.811" contextid="11388" timestamp="2016-08-09T15:14:57.286">
23+
<trace-info objectcount="25717326" scancount="20845868" scanbytes="741280452" />
24+
<finalization candidates="8383" enqueued="4354" />
25+
<ownableSynchronizers candidates="339217" cleared="45" />
26+
<references type="soft" candidates="19261" cleared="0" enqueued="0" dynamicThreshold="25" maxThreshold="32" />
27+
<references type="weak" candidates="52578" cleared="12" enqueued="12" />
28+
<references type="phantom" candidates="115" cleared="0" enqueued="0" />
29+
<stringconstants candidates="73384" cleared="10" />
30+
</gc-op>
31+
<gc-op id="11426" type="classunload" timems="0.275" contextid="11388" timestamp="2016-08-09T15:14:57.286">
32+
<classunload-info classloadercandidates="932" classloadersunloaded="0" classesunloaded="0" anonymousclassesunloaded="0" quiescems="0.000" setupms="0.274" scanms="0.000" postms="0.000" />
33+
</gc-op>
34+
<gc-op id="11427" type="sweep" timems="2.542" contextid="11388" timestamp="2016-08-09T15:14:57.289" />
35+
<gc-end id="11428" type="global" contextid="11388" durationms="1175.175" usertimems="1772.853" systemtimems="2.967" timestamp="2016-08-09T15:14:57.290">
36+
<mem-info id="11429" free="5069413376" total="6442450944" percent="78">
37+
<mem type="tenure" free="5069413376" total="6442450944" percent="78">
38+
<mem type="soa" free="5062971392" total="6436008960" percent="78" />
39+
<mem type="loa" free="6441984" total="6441984" percent="100" />
40+
</mem>
41+
<pending-finalizers system="225" default="4129" reference="12" classloader="0" />
42+
</mem-info>
43+
</gc-end>
44+
<cycle-end id="11430" type="global" contextid="11388" timestamp="2016-08-09T15:14:57.292" />
45+
<concurrent-collection-end id="11431" timestamp="2016-08-09T15:14:57.292" />
46+
<exclusive-end id="11432" timestamp="2016-08-09T15:14:57.292" durationms="1182.375" />
47+
48+
</verbosegc>

‎src/test/resources/ibm/SampleIBMJ9_R28_global.txt‎ renamed to ‎src/test/resources/ibm/SampleIBMJ9_R28_sys_global.txt‎

File renamed without changes.

0 commit comments

Comments
 (0)