@Test
public void testCmsConcurrentMarkStart() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2011-10-24T08:12:24.375+0200: 3388.929: [CMS-concurrent-mark-start]").getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 1, model.size());
assertEquals("full gc pause", 0.0, model.getFullGCPause().getSum(), 0.01);
}
@Test
public void testCMSPromotionFailed() throws Exception {
final ByteArrayInputStream in =
new ByteArrayInputStream(
("2011-10-05T16:05:55.964+0200: 41985.374: [GC 41985.375: [ParNew (promotion failed): 104960K->100764K(104960K), 0.3379238 secs]41985.713: [CMS: 1239589K->897516K(1398144K), 38.3189415 secs] 1336713K->897516K(1503104K), [CMS Perm : 55043K->53511K(91736K)], 38.6583674 secs] [Times: user=39.22 sys=0.06, real=38.66 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("gc pause", 38.6583674, model.getFullGCPause().getSum(), 0.000001);
}
@Test
public void testFullGcIncrementalDatestamp2() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2011-10-05T04:23:39.427+0200: 44189.823: [Full GC 44189.824: [CMS: 274825K->223922K(892264K), 8.0594203 secs] 327565K->223922K(992616K), [CMS Perm : 524287K->158591K(524288K)] icms_dc=0 , 8.0600619 secs] [Times: user=4.51 sys=0.05, real=8.06 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 1, model.size());
assertEquals("full gc pause", 8.0600619, model.getFullGCPause().getSum(), 0.00000001);
}
@Test
public void testCMSConcurrentModeFailureDate() throws Exception {
final ByteArrayInputStream in =
new ByteArrayInputStream(
("2011-10-05T15:53:24.119+0200: 41403.025: [GC 41403.025: [ParNew (promotion failed): 104960K->101572K(104960K), 0.3275017 secs]41403.353: [CMS2011-10-05T15:53:24.629+0200: 41403.534: [CMS-concurrent-abortable-preclean: 1.992/2.650 secs] [Times: user=4.40 sys=0.06, real=2.65 secs]"
+ "\n (concurrent mode failure): 1295417K->906090K(1398144K), 32.4123146 secs] 1395643K->906090K(1503104K), [CMS Perm : 54986K->53517K(91576K)], 32.7410609 secs] [Times: user=33.10 sys=0.05, real=32.74 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
assertEquals("gc pause", 32.7410609, model.getFullGCPause().getMax(), 0.000001);
}
@Test
public void testCMSWithoutPrintTimeStampConcurrentModeFailure() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2012-04-03T20:36:35.284+0200: [GC [ParNew: 19081K->19081K(19136K), 0.0000205 secs][CMS2012-04-03T20:36:35.285+0200: [CMS-concurrent-abortable-preclean: 0.005/0.150 secs] [Times: user=0.14 sys=0.14, real=0.15 secs]"
+ "\n (concurrent mode failure): 98182K->3832K(98624K), 0.0195864 secs] 117264K->3832K(117760K), [CMS Perm : 2614K->2613K(21248K)], 0.0199322 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
assertEquals("heap", 117760, model.getHeapAllocatedSizes().getMax());
assertEquals("pause", 0.0199322, model.getFullGCPause().getMax(), 0.00000001);
}
@Test
public void testFullGcSystem() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("164.078: [Full GC (System) 164.078: [Tenured: 107024K->86010K(349568K), 0.7964528 secs] 143983K->86010K(506816K), [Perm : 85883K->85855K(86016K)], 0.7965714 secs] [Times: user=0.84 sys=0.00, real=0.80 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 1, model.size());
assertEquals("full gc pause", 0.7965714, model.getFullGCPause().getSum(), 0.00000001);
}
@Test
public void testFullGcIncrementalDatestamp() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2011-10-05T04:23:39.427+0200: 42927.215: [Full GC 42927.215: [CMS2011-10-05T04:23:39.427+0200: 42927.255: [CMS-concurrent-sweep: 0.416/6.288 secs] [Times: user=17.38 sys=0.44, real=6.29 secs]"
+ "\n (concurrent mode failure): 262166K->215967K(785256K), 7.8308614 secs] 273998K->215967K(800040K), [CMS Perm : 523009K->155678K(524288K)] icms_dc=8 , 7.8320634 secs] [Times: user=4.59 sys=0.04, real=7.83 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
assertEquals("full gc pause", 7.8320634, model.getFullGCPause().getSum(), 0.00000001);
}
@Test
public void testCMSFullGcCmsInterrupted() throws Exception {
// TODO CMS (concurrent mode interrupted) not recognised (ignored)
ByteArrayInputStream in =
new ByteArrayInputStream(
"78.579: [Full GC (System) 78.579: [CMS (concurrent mode interrupted): 64171K->1538K(107776K), 0.0088356 secs] 75362K->1538K(126912K), [CMS Perm : 2554K->2554K(21248K)], 0.0089351 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]"
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("count", 1, model.getPause().getN());
assertEquals("full gc pause", 0.0089351, model.getFullGCPause().getSum(), 0.00000001);
}
@Test
public void testCMSConcurrentModeFailure() throws Exception {
final ByteArrayInputStream in =
new ByteArrayInputStream(
("25866.053: [GC 25866.054: [ParNew (promotion failed): 458123K->468193K(471872K), 0.9151441 secs]25866.969: [CMS25870.038: [CMS-concurrent-mark: 3.120/4.102 secs] [Times: user=26.00 sys=0.12, real=4.10 secs]"
+ "\n (concurrent mode failure): 1143630K->1154547K(1572864K), 40.1744087 secs] 1590086K->1154547K(2044736K), [CMS Perm : 65802K->63368K(109784K)], 41.0904457 secs] [Times: user=60.57 sys=0.07, real=41.09 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
assertEquals("gc pause", 41.0904457, model.getFullGCPause().getMax(), 0.000001);
}
@Test
public void testAdaptiveSizePolicyFullSystemGc() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2012-03-21T20:49:09.624+0100: 9.993: [Full GC (System)AdaptiveSizeStart: 10.000 collection: 61"
+ "\nAdaptiveSizeStop: collection: 61"
+ "\n[PSYoungGen: 480K->0K(270976K)] [PSOldGen: 89711K->671K(145536K)] 90191K->671K(416512K) [PSPermGen: 2614K->2614K(21248K)], 0.0070749 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", 1, model.size());
assertEquals("Full GC pause", 0.0070749, model.getFullGCPause().getMax(), 0.00000001);
}
@Test
public void testCMSConcurrentModeFailureCmsAbortPreclean() throws Exception {
final ByteArrayInputStream in =
new ByteArrayInputStream(
("39323.400: [GC 39323.400: [ParNew (promotion failed): 471871K->457831K(471872K), 10.5045897 secs]39333.905: [CMS CMS: abort preclean due to time 39334.591: [CMS-concurrent-abortable-preclean: 4.924/15.546 secs] [Times: user=24.45 sys=9.40, real=15.55 secs]"
+ "\n (concurrent mode failure): 1301661K->1299268K(1572864K), 43.3433234 secs] 1757009K->1299268K(2044736K), [CMS Perm : 64534K->63216K(110680K)], 53.8487115 secs] [Times: user=54.83 sys=9.22, real=53.85 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
assertEquals("gc pause", 53.8487115, model.getFullGCPause().getMax(), 0.000001);
}
@Test
public void testCMSAdaptiveSizePolicy() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
IMP_LOGGER.addHandler(handler);
DATA_READER_FACTORY_LOGGER.addHandler(handler);
final InputStream in =
getClass().getResourceAsStream("SampleSun1_6_0CMSAdaptiveSizePolicy.txt");
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("event count", 24, model.size());
assertEquals("young gc count", 11, model.getGCPause().getN());
assertEquals("full gc count", 1, model.getFullGCPause().getN());
assertEquals("number of errors", 0, handler.getCount());
}
@Test
public void testPrintTenuringDistributionPromotionFailedConcurrentModeFailure() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2011-04-18T12:01:14.683+0200: 27401.763: [GC 27401.763: [ParNew (promotion failed)"
+ "\nDesired survivor size 557056 bytes, new threshold 1 (max 4)"
+ "\n- age 1: 906712 bytes, 906712 total"
+ "\n: 9768K->9877K(10240K), 0.0453585 secs]27401.808: [CMS2011-04-18T12:01:20.261+0200: 27407.340: [CMS-concurrent-sweep: 5.738/5.787 secs] [Times: user=6.40 sys=0.02, real=5.79 secs]"
+ "\n (concurrent mode failure): 858756K->670276K(932096K), 31.5781426 secs] 868036K->670276K(942336K), [CMS Perm : 54962K->51858K(91608K)], 31.6248756 secs] [Times: user=31.85 sys=0.03, real=31.63 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
assertEquals("event pause", 31.6248756, model.getFullGCPause().getMax(), 0.0000001);
}
@Test
public void testPrintTenuringDistributionPromotionFailed() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2011-02-14T13:14:36.298+0100: 31533.871: [GC 31533.871: [ParNew (promotion failed)"
+ "\nDesired survivor size 524288 bytes, new threshold 1 (max 4)"
+ "\n- age 1: 703560 bytes, 703560 total"
+ "\n- age 2: 342056 bytes, 1045616 total"
+ "\n : 9321K->9398K(9792K), 0.0563031 secs]31533.928: [CMS: 724470K->317478K(931248K), 13.5375713 secs] 733688K->317478K(941040K), [CMS Perm : 51870K->50724K(86384K)], 13.5959700 secs] [Times: user=14.03 sys=0.03, real=13.60 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 1, model.size());
assertEquals("event pause", 13.5959700, model.getFullGCPause().getMax(), 0.0000001);
}
@Test
public void testPrintCmsStatisticsConcurrentModeFailure() throws Exception {
ByteArrayInputStream in =
new ByteArrayInputStream(
("2012-10-20T18:04:58.147+0200: 1.621: [GC 1.621: [ParNew: 78631K->78631K(78656K), 0.0000164 secs]1.621: [CMS [9 iterations, 5 waits, 5367 cards)] 2012-10-20T18:04:58.147+0200: 1.621: [CMS-concurrent-abortable-preclean: 0.020/0.292 secs] (CMS-concurrent-abortable-preclean yielded 0 times)"
+ "\n [Times: user=0.30 sys=0.23, real=0.30 secs]"
+ "\n (concurrent mode failure): 402265K->61915K(436928K), 0.0394420 secs] 480896K->61915K(515584K), [CMS Perm : 2626K->2625K(65536K)], 0.0395686 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]")
.getBytes());
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 2, model.size());
assertEquals("failure pause", 0.0395686, model.getFullGCPause().getMax(), 0.0000001);
assertEquals(
"concurrent time",
0.02,
model.getConcurrentEventPauses().values().iterator().next().getMin(),
0.000000001);
}
@Test
public void testAdaptiveSizePolicy() throws Exception {
// 0.175: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 2721008
// promoted: 13580768 overflow: trueAdaptiveSizeStart: 0.186 collection: 1
// PSAdaptiveSizePolicy::compute_generation_free_space: costs minor_time: 0.059538 major_cost:
// 0.000000 mutator_cost: 0.940462 throughput_goal: 0.990000 live_space: 273821824 free_space:
// 33685504 old_promo_size: 16842752 old_eden_size: 16842752 desired_promo_size: 16842752
// desired_eden_size: 33685504
// AdaptiveSizePolicy::survivor space sizes: collection: 1 (2752512, 2752512) -> (2752512,
// 2752512)
// AdaptiveSizeStop: collection: 1
// [PSYoungGen: 16420K->2657K(19136K)] 16420K->15919K(62848K), 0.0109211 secs] [Times:
// user=0.00 sys=0.00, real=0.01 secs]
final InputStream in = getClass().getResourceAsStream("SampleSun1_6_0AdaptiveSizePolicy.txt");
final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6);
GCModel model = reader.read();
assertEquals("GC count", 10, model.size());
assertEquals("GC pause", 0.0224480, model.getGCPause().getMax(), 0.00000001);
assertEquals("Full GC pause", 0.0204436, model.getFullGCPause().getMax(), 0.00000001);
}