/** Tests the combination of -XX:PrintCmsStatistics=2 and -XX:+CMSScavengeBeforeRemark */
@Test
public void testPrintCmsStatisticsScavengeBeforeRemark() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2012-10-26T18:31:09.699+0200: 15.473: [GC[YG occupancy: 8752 K (78656 K)]2012-10-26T18:31:09.699+0200: 15.473: [GC 15.473: [ParNew: 8752K->64K(78656K), 0.0052352 secs] 388874K->388870K(515584K), 0.0052868 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]"
+ "\n15.478: [Rescan (parallel) (Survivor:0chunks) Finished young gen rescan work in 1th thread: 0.000 sec"
+ "\nFinished young gen rescan work in 1th thread: 0.000 sec"
+ "\nFinished young gen rescan work in 0th thread: 0.000 sec"
+ "\nFinished remaining root rescan work in 1th thread: 0.000 sec"
+ "\nFinished remaining root rescan work in 2th thread: 0.000 sec"
+ "\nFinished remaining root rescan work in 0th thread: 0.000 sec"
+ "\nFinished dirty card rescan work in 0th thread: 0.001 sec"
+ "\nFinished dirty card rescan work in 2th thread: 0.001 sec"
+ "\nFinished dirty card rescan work in 1th thread: 0.001 sec"
+ "\nFinished young gen rescan work in 3th thread: 0.000 sec"
+ "\nFinished remaining root rescan work in 3th thread: 0.000 sec"
+ "\nFinished dirty card rescan work in 3th thread: 0.000 sec"
+ "\nFinished work stealing in 3th thread: 0.000 sec"
+ "\nFinished work stealing in 2th thread: 0.000 sec"
+ "\nFinished work stealing in 0th thread: 0.000 sec"
+ "\nFinished work stealing in 1th thread: 0.000 sec"
+ "\n, 0.0006571 secs]15.479: [weak refs processing, 0.0000041 secs]15.479: [class unloading, 0.0001106 secs]15.479: [scrub symbol table, 0.0004465 secs]15.480: [scrub string table, 0.0000168 secs] [1 CMS-remark: 388806K(436928K)] 388870K(515584K), 0.0067111 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
GCEvent parNew = (GCEvent) model.get(0);
GCEvent remarkEvent = (GCEvent) model.get(1);
assertEquals("GC pause ParNew", 0.0052868, parNew.getPause(), 0.000000001);
assertEquals("GC pause Remark", 0.0067111 - 0.0052868, remarkEvent.getPause(), 0.000000001);
}
@Test
public void testGenCon() throws Exception {
InputStream in = getInputStream("SampleJRockit1_5_12_gencon.txt");
DataReader reader = new DataReaderJRockit1_5_0(in);
GCModel model = reader.read();
assertEquals("count", 8, model.size());
GCEvent event = (GCEvent) model.get(0);
assertEquals("timestamp", 6.038, event.getTimestamp(), 0.000001);
assertEquals("name", Type.JROCKIT_GC.getName(), event.getExtendedType().getName());
assertEquals("before", 3089328, event.getPreUsed());
assertEquals("after", 352551, event.getPostUsed());
assertEquals("total", 3145728, event.getTotal());
assertEquals("pause", 0.1186, event.getPause(), 0.0000001);
}
@Test
public void testGcPrioThroughput() throws Exception {
InputStream in = getInputStream("SampleJRockit1_5_12_gcpriothroughput.txt");
DataReader reader = new DataReaderJRockit1_5_0(in);
GCModel model = reader.read();
assertEquals("count", 8, model.size());
GCEvent event = (GCEvent) model.get(0);
assertEquals("timestamp", 4.817, event.getTimestamp(), 0.000001);
assertEquals("name", Type.JROCKIT_GC.getName(), event.getExtendedType().getName());
assertEquals("before", 1641728, event.getPreUsed());
assertEquals("after", 148365, event.getPostUsed());
assertEquals("total", 3145728, event.getTotal());
assertEquals("pause", 0.039959, event.getPause(), 0.0000001);
}
@Test
public void testSimpleOpts() throws Exception {
InputStream in = getInputStream("SampleJRockit1_5_12-gcreport-simpleopts-singlecon.txt");
DataReader reader = new DataReaderJRockit1_5_0(in);
GCModel model = reader.read();
assertEquals("count", 5, model.size());
GCEvent event = (GCEvent) model.get(0);
assertEquals("timestamp", 6.771, event.getTimestamp(), 0.000001);
assertEquals("name", Type.JROCKIT_GC.getName(), event.getExtendedType().getName());
assertEquals("before", 3145728, event.getPreUsed());
assertEquals("after", 296406, event.getPostUsed());
assertEquals("total", 3145728, event.getTotal());
assertEquals("pause", 0.066, event.getPause(), 0.0000001);
}
@Test
public void testGcPrioPausetime() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
IMP_LOGGER.addHandler(handler);
DATA_READER_FACTORY_LOGGER.addHandler(handler);
InputStream in = getInputStream("SampleJRockit1_5_12_gcpriopausetime.txt");
DataReader reader = new DataReaderJRockit1_5_0(in);
GCModel model = reader.read();
assertEquals("count", 10, model.size());
GCEvent event = (GCEvent) model.get(0);
assertEquals("timestamp", 6.290, event.getTimestamp(), 0.000001);
assertEquals("name", Type.JROCKIT_GC.getName(), event.getExtendedType().getName());
assertEquals("before", 3128161, event.getPreUsed());
assertEquals("after", 296406, event.getPostUsed());
assertEquals("total", 3145728, event.getTotal());
assertEquals("pause", 0.059084, event.getPause(), 0.0000001);
assertEquals("number of warnings", 6, handler.getCount());
}
public GCModel read() throws IOException {
if (LOG.isLoggable(Level.INFO)) LOG.info("Reading IBM 1.3.0 format...");
try {
GCModel model = new GCModel(true);
model.setFormat(GCModel.Format.IBM_VERBOSE_GC);
int state = 0;
String line = null;
AbstractGCEvent<GCEvent> lastEvent = new GCEvent();
GCEvent event = null;
while ((line = in.readLine()) != null) {
String trimmedLine = line.trim();
if ((!trimmedLine.equals(""))
&& (!trimmedLine.startsWith("<GC: "))
&& (!(trimmedLine.startsWith("<") && trimmedLine.endsWith(">")))) {
if (LOG.isLoggable(Level.WARNING))
LOG.warning("Malformed line (" + in.getLineNumber() + "): " + line);
state = 0;
}
switch (state) {
case 0:
if (line.indexOf("Allocation Failure.") != -1) {
event = new GCEvent();
event.setType(AbstractGCEvent.Type.FULL_GC);
event.setTimestamp(lastEvent.getTimestamp() + parseTimeSinceLastAF(line));
state++;
break;
}
case 1:
if (line.indexOf("managing allocation failure, action=1") != -1) {
event.setPreUsed(parsePreUsed(line));
state++;
break;
}
case 2:
if (line.indexOf("freed") != -1 && line.indexOf("unloaded") == -1) {
event.setPostUsed(parsePostUsed(line));
event.setTotal(parseTotalAfterGC(line));
state++;
break;
}
case 3:
if (line.indexOf("expanded heap by ") != -1) {
event.setTotal(parseTotalAfterHeapExpansion(line));
state++;
break;
}
case 4:
if (line.indexOf("completed in ") != -1) {
event.setPause(parsePause(line));
model.add(event);
lastEvent = event;
event = null;
state = 0;
}
default:
}
}
return model;
} finally {
if (in != null)
try {
in.close();
} catch (IOException ioe) {
}
if (LOG.isLoggable(Level.INFO)) LOG.info("Reading done.");
}
}
public void endElement(
String namespaceURI,
String sName, // simple name
String qName // qualified name
) throws SAXException {
if ("af".equals(qName)) {
System.out.println("In AF endElement!");
if (currentAF != null) {
GCEvent event = new GCEvent();
if (!"tenured".equals(currentAF.type)) {
LOG.warning("Unhandled AF type: " + currentAF.type);
}
if (!"global".equals(currentAF.gcType)) {
LOG.warning("Different GC type: " + currentAF.gcType);
} else {
event.setType(AbstractGCEvent.Type.FULL_GC);
}
if (currentAF.initialTotalBytes != -1 && currentAF.initialFreeBytes != -1) {
int preUsed = currentAF.initialTotalBytes - currentAF.initialFreeBytes;
event.setPreUsed(preUsed);
}
if (currentAF.afterTotalBytes != -1 && currentAF.afterFreeBytes != -1) {
int postUsed = currentAF.afterTotalBytes - currentAF.afterFreeBytes;
event.setPostUsed(postUsed);
}
if (currentAF.afterTotalBytes != -1) {
event.setTotal(currentAF.afterTotalBytes);
}
// event.setTimestamp(currentAF.timestamp.getTime());
event.setTimestamp(currentAF.elapsedTime);
if (currentAF.totalTime != -1) {
event.setPause(currentAF.totalTime);
}
if (currentAF.afterSOATotalBytes != -1
&& currentAF.afterSOAFreeBytes != -1
&& currentAF.initialSOAFreeBytes != -1
&& currentAF.initialSOATotalBytes != -1) {
int preUsed = currentAF.initialSOATotalBytes - currentAF.initialSOAFreeBytes;
int postUsed = currentAF.afterSOATotalBytes - currentAF.afterSOAFreeBytes;
final GCEvent detailEvent = new GCEvent();
detailEvent.setTimestamp(currentAF.elapsedTime);
detailEvent.setType(AbstractGCEvent.Type.PS_YOUNG_GEN);
detailEvent.setTenuredDetail(true);
detailEvent.setPreUsed(preUsed);
detailEvent.setPostUsed(postUsed);
detailEvent.setTotal(currentAF.afterSOATotalBytes);
event.add(detailEvent);
}
if (currentAF.afterLOATotalBytes != -1
&& currentAF.afterLOAFreeBytes != -1
&& currentAF.initialLOAFreeBytes != -1
&& currentAF.initialLOATotalBytes != -1) {
int preUsed = currentAF.initialLOATotalBytes - currentAF.initialLOAFreeBytes;
int postUsed = currentAF.afterLOATotalBytes - currentAF.afterLOAFreeBytes;
final GCEvent detailEvent = new GCEvent();
detailEvent.setTimestamp(currentAF.elapsedTime);
detailEvent.setType(AbstractGCEvent.Type.PS_OLD_GEN);
detailEvent.setTenuredDetail(true);
detailEvent.setPreUsed(preUsed);
detailEvent.setPostUsed(postUsed);
detailEvent.setTotal(currentAF.afterLOATotalBytes);
event.add(detailEvent);
}
model.add(event);
currentTenured = 0;
currentAF = null;
} else {
LOG.warning("Found end <af> tag with no begin tag");
}
}
}
public GCModel read() throws IOException {
if (LOG.isLoggable(Level.INFO)) LOG.info("Reading IBM 1.3.1 format...");
try {
final GCModel model = new GCModel(true);
model.setFormat(GCModel.Format.IBM_VERBOSE_GC);
int state = 0;
String line = null;
GCEvent lastEvent = new GCEvent();
GCEvent event = null;
long basetime = 0;
cycleStartGCFormat = new SimpleDateFormat("EEE MMM dd HH:mm:ss yyyy", Locale.US);
while ((line = in.readLine()) != null) {
final String trimmedLine = line.trim();
if (!"".equals(trimmedLine)
&& !trimmedLine.startsWith("<GC: ")
&& !trimmedLine.startsWith("<")) {
System.err.println("Malformed line (" + in.getLineNumber() + "): " + line);
state = 0;
}
switch (state) {
case 0:
if (line.indexOf("Allocation Failure.") != -1) {
event = new GCEvent();
event.setType(AbstractGCEvent.Type.FULL_GC);
event.setTimestamp(lastEvent.getTimestamp() + parseTimeSinceLastAF(line));
// stay in state 0
break;
} else if (line.indexOf("GC cycle started") != -1) { // can apparently occur without AF
event = new GCEvent();
event.setType(AbstractGCEvent.Type.FULL_GC);
final long time = parseGCCycleStart(line);
if (basetime == 0) basetime = time;
event.setTimestamp((time - basetime) / 1000.0d);
state++;
break;
} else if (line.indexOf("managing allocation failure, action=3") != -1) {
event = new GCEvent();
event.setType(AbstractGCEvent.Type.FULL_GC);
event.setTimestamp(lastEvent.getTimestamp() + lastEvent.getPause());
event.setPreUsed(parsePreUsedAFAction3(line));
event.setPostUsed(event.getPreUsed());
state = 2;
break;
}
break;
case 1:
if (line.indexOf("freed") != -1 && line.indexOf("unloaded") == -1) {
event.setPreUsed(parsePreUsed(line));
event.setPostUsed(parsePostUsed(line));
event.setTotal(parseTotalAfterGC(line));
event.setPause(parsePause(line));
model.add(event);
lastEvent = event;
event = null;
state = 0;
break;
}
break;
case 2:
if (line.indexOf("expanded heap by ") != -1
|| line.indexOf("expanded heap fully by ") != -1) {
event.setTotal(parseTotalAfterHeapExpansion(line));
state++;
break;
}
break;
case 3:
if (line.indexOf("completed in ") != -1) {
event.setPause(parsePause(line) - lastEvent.getPause());
model.add(event);
lastEvent = event;
event = null;
state = 0;
}
break;
default:
}
}
// System.err.println(model);
return model;
} finally {
if (in != null)
try {
in.close();
} catch (IOException ioe) {
}
if (LOG.isLoggable(Level.INFO)) LOG.info("Done reading.");
}
}