/** 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 testPrintTenuringDistributionOpenJdk6() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
"3.141: [GCDesired survivor size 134217728 bytes, new threshold 7 (max 2) [PSYoungGen: 188744K->13345K(917504K)] 188744K->13345K(4063232K), 0.0285820 secs] [Times: user=0.06 sys=0.01, real=0.03 secs]"
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("count", 1, model.size());
assertEquals("main type", "GC", model.get(0).getType().getType());
assertEquals("detail type", "PSYoungGen", model.get(0).details().next().getType().getType());
}
@Test
public void testCMSScavengeBeforeRemarkDateStamp() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2012-03-07T22:19:49.110+0100: 2.479: [GC[YG occupancy: 227872 K (235968 K)]2012-03-07T22:19:49.110+0100: 2.479: [GC 2.479: [ParNew: 227872K->30K(235968K), 0.0005432 secs] 296104K->68322K(395712K), 0.0005809 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]"
+ "\n2.480: [Rescan (parallel) , 0.0001934 secs]2.480: [weak refs processing, 0.0000061 secs]2.480: [class unloading, 0.0001131 secs]2.480: [scrub symbol & string tables, 0.0003175 secs] [1 CMS-remark: 68292K(159744K)] 68322K(395712K), 0.0013506 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());
assertEquals("1st event", "GC ParNew:", model.get(0).getTypeAsString());
assertEquals("2nd event", "GC CMS-remark:", model.get(1).getTypeAsString());
assertEquals("1st event pause", 0.0005809, ((GCEvent) model.get(0)).getPause(), 0.00000001);
assertEquals(
"2nd event pause", 0.0013506 - 0.0005809, ((GCEvent) model.get(1)).getPause(), 0.00000001);
}
@Test
public void testCMSScavengeBeforeRemarkTimeStamp() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2.036: [GC[YG occupancy: 235954 K (235968 K)]2.036: [GC 2.036: [ParNew: 235954K->30K(235968K), 0.0004961 secs] 317153K->81260K(395712K), 0.0005481 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]"
+ "\n2.037: [Rescan (parallel) , 0.0002425 secs]2.037: [weak refs processing, 0.0000041 secs]2.037: [class unloading, 0.0000938 secs]2.037: [scrub symbol & string tables, 0.0003138 secs] [1 CMS-remark: 81230K(159744K)] 81260K(395712K), 0.0013653 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());
assertEquals("1st event", "GC ParNew:", model.get(0).getTypeAsString());
assertEquals("2nd event", "GC CMS-remark:", model.get(1).getTypeAsString());
assertEquals("1st event pause", 0.0005481, ((GCEvent) model.get(0)).getPause(), 0.00000001);
assertEquals(
"2nd event pause", 0.0013653 - 0.0005481, ((GCEvent) model.get(1)).getPause(), 0.00000001);
}
@Test
public void testPSWithoutPrintTimeStamp() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2012-04-03T20:35:40.033+0200: [GC [PSYoungGen: 16420K->2657K(19136K)] 16420K->15887K(62848K), 0.0143603 secs] [Times: user=0.02 sys=0.02, real=0.01 secs]"
+ "\n2012-04-03T20:35:40.056+0200: [GC [PSYoungGen: 19084K->2657K(35584K)] 32314K->32279K(79296K), 0.0236295 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]"
+ "\n2012-04-03T20:35:40.079+0200: [Full GC [PSYoungGen: 2657K->0K(35584K)] [PSOldGen: 29622K->32262K(67392K)] 32279K->32262K(102976K) [PSPermGen: 2603K->2603K(21248K)], 0.0095147 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 3, model.size());
assertEquals("heap", 102976, model.getHeapAllocatedSizes().getMax());
assertEquals("pause", 0.0236295, model.getGCPause().getMax(), 0.00000001);
assertEquals(
"2nd pause, timeStamp", 0.056 - 0.033, ((GCEvent) model.get(1)).getTimestamp(), 0.00001);
assertEquals(
"3nd pause, timeStamp", 0.079 - 0.033, ((GCEvent) model.get(2)).getTimestamp(), 0.00001);
}
@Test
public void testCMSScavengeBeforeRemarkWithPrintTenuringDistribution() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2012-03-07T22:19:48.736+0100: 2.104: [GC[YG occupancy: 235952 K (235968 K)]2012-03-07T22:19:48.736+0100: 2.104: [GC 2.104: [ParNew"
+ "\nDesired survivor size 13402112 bytes, new threshold 4 (max 4)"
+ "\n- age 1: 24816 bytes, 24816 total"
+ "\n: 235952K->30K(235968K), 0.0005641 secs] 317151K->81260K(395712K), 0.0006030 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]"
+ "\n2.105: [Rescan (parallel) , 0.0002003 secs]2.105: [weak refs processing, 0.0000041 secs]2.105: [class unloading, 0.0000946 secs]2.105: [scrub symbol & string tables, 0.0003146 secs] [1 CMS-remark: 81230K(159744K)] 81260K(395712K), 0.0013199 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());
assertEquals("1st event", "GC ParNew:", model.get(0).getTypeAsString());
assertEquals("1st event pause", 0.0006030, ((GCEvent) model.get(0)).getPause(), 0.00000001);
assertEquals("2nd event", "GC CMS-remark:", model.get(1).getTypeAsString());
assertEquals(
"2nd event pause", 0.0013199 - 0.0006030, ((GCEvent) model.get(1)).getPause(), 0.00000001);
}
@Test
public void testCommaInTimestamp() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
"12,655: [GC [PSYoungGen: 262656K->28075K(306432K)] 262656K->28075K(1006848K), 0,3541657 secs] [Times: user=0,22 sys=0,48, real=0,35 secs]"
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 1, model.size());
assertEquals("GC pause", 0.3541657, model.getGCPause().getMax(), 0.0000001);
assertEquals("GC timestamp", 12.655, model.get(0).getTimestamp(), 0.000001);
}
@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());
}
