diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java index 1d5ebddb..5d286b84 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/AbstractDataReaderSun.java @@ -10,6 +10,8 @@ import java.util.List; import java.util.logging.Level; import java.util.logging.Logger; +import java.util.regex.Matcher; +import java.util.regex.Pattern; import com.tagtraum.perf.gcviewer.model.AbstractGCEvent; import com.tagtraum.perf.gcviewer.model.GCEvent; @@ -46,6 +48,8 @@ public abstract class AbstractDataReaderSun implements DataReader { /** the log type allowing for small differences between different versions of the gc logs */ protected GcLogType gcLogType; + private static Pattern parenthesesPattern = Pattern.compile("\\([^()]*\\) ?"); + /** * Create an instance of this class passing an inputStream an the type of the logfile. * @param in inputstream to the log file @@ -213,7 +217,7 @@ protected void setMemory(GCEvent event, String line, ParsePosition pos) throws P while (isGeneration(line, pos)) { final GCEvent detailEvent = new GCEvent(); - final AbstractGCEvent.Type type = parseType(line, pos); + final AbstractGCEvent.Type type = parseNestedType(line, pos); detailEvent.setType(type); start = pos.getIndex(); end = line.indexOf("K", pos.getIndex()); @@ -323,7 +327,8 @@ protected boolean nextCharIsBracket(String line, ParsePosition pos) { return line.charAt(pos.getIndex()) == '['; } - protected GCEvent.Type parseType(String line, ParsePosition pos) throws ParseException { + + protected String parseTypeString(String line, ParsePosition pos) throws ParseException { int i = pos.getIndex(); try { // consume all leading spaces and [ @@ -334,7 +339,7 @@ protected GCEvent.Type parseType(String line, ParsePosition pos) throws ParseExc if (c != ' ' && c != '[') break; } if (i>=lineLength) throw new ParseException("Unexpected end of line.", line); - StringBuffer sb = new StringBuffer(20); + StringBuilder sb = new StringBuilder(20); // check whether the type name starts with a number // e.g. 0.406: [GC [1 CMS-initial-mark: 7664K(12288K)] 7666K(16320K), 0.0006855 secs] //final int startNumbers = i; @@ -365,18 +370,44 @@ protected GCEvent.Type parseType(String line, ParsePosition pos) throws ParseExc for (; itrue, if next "token" is a timestamp. * @@ -537,7 +568,7 @@ protected Date parseDatestamp(String line, ParsePosition pos) throws ParseExcept Date date = null; if (nextIsDatestamp(line, pos)) { try { - date = dateParser.parse(line.substring(pos.getIndex(), LENGTH_OF_DATESTAMP-1)); + date = dateParser.parse(line.substring(pos.getIndex(), pos.getIndex()+LENGTH_OF_DATESTAMP-1)); pos.setIndex(pos.getIndex() + LENGTH_OF_DATESTAMP); } catch (java.text.ParseException e) { @@ -555,11 +586,11 @@ protected Date parseDatestamp(String line, ParsePosition pos) throws ParseExcept * @param pos current parse position * @return true if in current line at current parse position we have a datestamp */ - private boolean nextIsDatestamp(String line, ParsePosition pos) { + protected boolean nextIsDatestamp(String line, ParsePosition pos) { if (line == null || line.length() < 10) { return false; } - return line.indexOf("-", pos.getIndex()) == 4 && line.indexOf("-", pos.getIndex() + 5) == 7; + return line.indexOf("-", pos.getIndex()) == pos.getIndex()+4 && line.indexOf("-", pos.getIndex() + 5) == pos.getIndex()+7; } } diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java index e67546b8..583b582c 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderFactory.java @@ -128,8 +128,10 @@ private DataReader getDataReaderBySample(String s, InputStream in) throws IOExce // this should be an IBM JDK < 1.3.0 if (LOG.isLoggable(Level.INFO)) LOG.info("File format: IBM <1.3.0"); return new DataReaderIBM1_3_0(in); - } else if (s.indexOf("pause (young)") > 0) { + } else if (s.indexOf("pause (young)") > 0 || s.indexOf("G1Ergonomics") > 0) { // G1 logger usually starts with ": [GC pause (young)...]" + // but can start with : [G1Ergonomics (Heap Sizing) expand the heap... + // with certain logging flaggs. if (LOG.isLoggable(Level.INFO)) LOG.info("File format: Sun 1.6.x G1 collector"); return new DataReaderSun1_6_0G1(in, GcLogType.SUN1_6G1); } else if (s.indexOf("[Times:") > 0) { diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java index 7a095d0e..b2db4fa8 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0.java @@ -58,7 +58,7 @@ */ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { - private static Logger LOG = Logger.getLogger(DataReaderSun1_6_0.class.getName()); + private static final Logger LOG = Logger.getLogger(DataReaderSun1_6_0.class.getName()); private static final String UNLOADING_CLASS = "[Unloading class "; private static final String APPLICATION_TIME = "Application time:"; // -XX:+PrintGCApplicationConcurrentTime @@ -140,19 +140,19 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { // AdaptiveSizeStop: collection: 1 // [PSYoungGen: 16420K->2657K(19136K)] 16420K->15919K(62848K), 0.0109211 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] // -> to parse it, the first line must be split, and the following left out until the rest of the gc information follows - private static Pattern adaptiveSizePolicyPattern = Pattern.compile("(.*GC|.*\\(System\\))Adaptive.*"); + private static final Pattern adaptiveSizePolicyPattern = Pattern.compile("(.*GC|.*\\(System\\))Adaptive.*"); private static final String ADAPTIVE_PATTERN = "AdaptiveSize"; // -XX:+PrintAdaptiveSizePolicy combined with -XX:-UseAdaptiveSizePolicy (not using the policy, just printing) // outputs the following line: // 0.222: [GCAdaptiveSizePolicy::compute_survivor_space_size_and_thresh: survived: 2720992 promoted: 13613552 overflow: true [PSYoungGen: 16420K->2657K(19136K)] 16420K->15951K(62848K), 0.0132830 secs] [Times: user=0.00 sys=0.03, real=0.02 secs] - private static Pattern printAdaptiveSizePolicyPattern = Pattern.compile("(.*GC)Adaptive.*(true|false)( \\[.*)"); + private static final Pattern printAdaptiveSizePolicyPattern = Pattern.compile("(.*GC)Adaptive.*(true|false)( \\[.*)"); private static final int PRINT_ADAPTIVE_SIZE_GROUP_BEFORE = 1; private static final int PRINT_ADAPTIVE_SIZE_GROUP_AFTER = 3; // -XX:PrintCmsStatistics=2 private static final String PRINT_CMS_STATISTICS_ITERATIONS = "iterations"; - private static Pattern printCmsStatisticsIterationsPattern = Pattern.compile("(.*)[ ][\\[][0-9]+[ ]iterations[, 0-9]+[ ]waits[, 0-9]+[ ]cards[)][\\]][ ](.*)"); + private static final Pattern printCmsStatisticsIterationsPattern = Pattern.compile("(.*)[ ][\\[][0-9]+[ ]iterations[, 0-9]+[ ]waits[, 0-9]+[ ]cards[)][\\]][ ](.*)"); private static final int PRINT_CMS_STATISTICS_ITERATIONS_GROUP_BEFORE = 1; private static final int PRINT_CMS_STATISTICS_ITERATIONS_GROUP_AFTER = 2; private static final String PRINT_CMS_STATISTICS_SURVIVOR = " (Survivor:"; @@ -163,7 +163,7 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun { // in JDK1.4 / 1.5 it looked like this: // 5.0: [GC Desired survivor size 3342336 bytes, new threshold 1 (max 32) - age 1: 6684672 bytes, 6684672 total 52471K->22991K(75776K), 1.0754938 secs] private static final String PRINT_TENURING_DISTRIBUTION = "Desired survivor size"; - private static Pattern printTenuringDistributionPattern = Pattern.compile("(.*GC)[ ]?Desired.*(?:[0-9]\\)|total)( \\[.*|[ ][0-9]*.*)"); + private static final Pattern printTenuringDistributionPattern = Pattern.compile("(.*GC)[ ]?Desired.*(?:[0-9]\\)|total)( \\[.*|[ ][0-9]*.*)"); private static final int PRINT_TENURING_DISTRIBUTION_PATTERN_GROUP_BEFORE = 1; private static final int PRINT_TENURING_DISTRIBUTION_PATTERN_GROUP_AFTER = 2; @@ -402,7 +402,7 @@ protected AbstractGCEvent parseLine(final String line, final ParsePosition po } double timestamp = getTimeStamp(line, pos, datestamp); - final GCEvent.Type type = parseType(line, pos); + final GCEvent.Type type = parseTopType(line, pos); // special provision for CMS events if (type.getConcurrency() == Concurrency.CONCURRENT) { final ConcurrentGCEvent event = new ConcurrentGCEvent(); @@ -467,7 +467,7 @@ private void parseDetailEventsIfExist(final String line, final ParsePosition pos } else { detailEvent.setTimestamp(parseTimestamp(line, pos)); } - detailEvent.setType(parseType(line, pos)); + detailEvent.setType(parseNestedType(line, pos)); setMemoryAndPauses(detailEvent, line, pos); event.add(detailEvent); } diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0G1.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0G1.java index 7098e252..22fc927d 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0G1.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0G1.java @@ -51,7 +51,7 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun { private static final String INCOMPLETE_CONCURRENT_MARK_INDICATOR = "concurrent-mark"; - private static Logger LOG = Logger.getLogger(DataReaderSun1_6_0G1.class .getName()); + private static final Logger LOG = Logger.getLogger(DataReaderSun1_6_0G1.class .getName()); private static final String TIMES = "[Times"; @@ -77,7 +77,7 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun { // the following pattern is specific for G1 with -XX:+PrintGCDetails // "[: ]0.295: [GC pause (young), 0.00594747 secs]" - private static final Pattern PATTERN_GC_PAUSE = Pattern.compile("^([0-9-T:.+]{29})?[ ]?([0-9.]+)[: \\[]{3}([A-Za-z- ().]+)[, ]+([0-9.]+)[ sec\\]]+$"); + private static final Pattern PATTERN_GC_PAUSE = Pattern.compile("^([0-9-T:.+]{29})?[ ]?([0-9.]+)[: \\[]{3}([A-Z0-9a-z- ().]+)[, ]+([0-9.]+)[ sec\\]]+$"); private static final int GC_PAUSE_GROUP_DATESTAMP = 1; private static final int GC_PAUSE_GROUP_TIMESTAMP = 2; private static final int GC_PAUSE_GROUP_TYPE = 3; @@ -94,9 +94,9 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun { // or "...Full GC..." // or "...): (initial-mark)..." (where the timestamp including ":" belongs to a concurrent event and the rest not) // or "...) (initial-mark)..." (where only the timestamp belongs to a concurrent event) - private static Pattern PATTERN_LINES_MIXED = Pattern.compile("(.*\\)|.*Full GC)([0-9.]+.*)"); + private static final Pattern PATTERN_LINES_MIXED = Pattern.compile("(.*\\)|.*Full GC)([0-9.]+.*)"); - private static Pattern PATTERN_G1_ERGONOMICS = Pattern.compile("(.*)\\W\\d+\\.\\d{3}\\W{2}\\[G1Ergonomics .+\\].*"); + private static final Pattern PATTERN_G1_ERGONOMICS = Pattern.compile("(.*)\\W\\d+\\.\\d{3}\\W{2}\\[G1Ergonomics .+\\].*"); private static final String HEAP_SIZING_START = "Heap"; @@ -218,7 +218,8 @@ else if (isPrintTenuringDistribution(line)) { // all other GC types are the same as in standard G1 mode. gcPauseMatcher.reset(line); if (gcPauseMatcher.matches()) { - AbstractGCEvent.Type type = AbstractGCEvent.Type.parse(gcPauseMatcher.group(GC_PAUSE_GROUP_TYPE)); + AbstractGCEvent.Type type = extractTypeFromParsedString(gcPauseMatcher.group(GC_PAUSE_GROUP_TYPE)); + if (type != null && type.getPattern().compareTo(GcPattern.GC_MEMORY_PAUSE) == 0) { // detailed G1 events start with GC_MEMORY pattern, but are of type GC_MEMORY_PAUSE @@ -337,7 +338,7 @@ private int parseDetails(BufferedReader in, GCEvent youngEvent = new GCEvent(); youngEvent.setDateStamp(event.getDatestamp()); youngEvent.setTimestamp(event.getTimestamp()); - youngEvent.setType(parseType(line, pos)); + youngEvent.setType(parseNestedType(line, pos)); setMemoryExtended(youngEvent, line, pos); // add survivors @@ -394,7 +395,7 @@ else if (line.indexOf(INCOMPLETE_CONCURRENT_MARK_INDICATOR) >= 0) { private void parseIncompleteConcurrentEvent(GCModel model, AbstractGCEvent previousEvent, String line, ParsePosition pos) throws ParseException { // some concurrent event is mixed in -> extract it pos.setIndex(line.indexOf("GC conc")); - Type type = parseType(line, pos); + Type type = parseNestedType(line, pos); model.add(parseConcurrentEvent(line, pos, previousEvent.getDatestamp(), previousEvent.getTimestamp(), type)); } @@ -408,7 +409,7 @@ protected AbstractGCEvent parseLine(final String line, final ParsePosition po // pre-used->post-used, total, time final Date datestamp = parseDatestamp(line, pos); final double timestamp = parseTimestamp(line, pos); - final GCEvent.Type type = parseType(line, pos); + final GCEvent.Type type = parseTopType(line, pos); // special provision for concurrent events if (type.getConcurrency() == Concurrency.CONCURRENT) { ae = parseConcurrentEvent(line, pos, datestamp, timestamp, type); @@ -419,7 +420,9 @@ protected AbstractGCEvent parseLine(final String line, final ParsePosition po event.setType(type); // Java 7 can have detailed event at this position like this // 0.197: [GC remark 0.197: [GC ref-proc, 0.0000070 secs], 0.0005297 secs] - if (nextIsTimestamp(line, pos)) { + // or when PrintDateTimeStamps is on like: + // 2013-09-09T06:45:45.825+0000: 83146.942: [GC remark 2013-09-09T06:45:45.825+0000: 83146.943: [GC ref-proc, 0.0069100 secs], 0.0290090 secs] + if (nextIsTimestamp(line, pos) || nextIsDatestamp(line,pos)) { event.add((GCEvent) parseLine(line, pos)); } diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java index 50943916..6101f48f 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java @@ -239,7 +239,7 @@ public boolean isRemark() { } public static class Type implements Serializable { - private final String type; + private String type; private final String rep; private Generation generation; private Concurrency concurrency; diff --git a/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java b/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java index 5bc02f34..4e6df7cf 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/GCModel.java @@ -82,7 +82,7 @@ public boolean equals(Object other) { } } - private static Logger LOG = Logger.getLogger(GCModel.class.getName()); + private static final Logger LOG = Logger.getLogger(GCModel.class.getName()); private List> allEvents; private List stopTheWorldEvents; diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0.java index 05cb6dcc..8eb64e08 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0.java @@ -198,7 +198,7 @@ public void testCmsRemarkTimestamp() throws Exception { final DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_6); GCModel model = reader.read(); - assertEquals("GC count", 1, model.size()); + assertEquals("GC count", 1, model.size()); assertEquals("gc pause", 1.1490033, model.getGCPause().getSum(), 0.00000001); } @@ -533,21 +533,21 @@ public void testCMSScavengeBeforeRemarkDateStamp() throws Exception { @Test public void testCMSScavengeBeforeRemarkWithPrintTenuringDistribution() throws Exception { - ByteArrayInputStream in = new ByteArrayInputStream( + ByteArrayInputStream input = 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(); + final DataReader reader = new DataReaderSun1_6_0(input, GcLogType.SUN1_6); + GCModel gcModel = 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); + assertEquals("GC count", 2, gcModel.size()); + assertEquals("1st event", "GC ParNew:", gcModel.get(0).getTypeAsString()); + assertEquals("1st event pause", 0.0006030, ((GCEvent)gcModel.get(0)).getPause(), 0.00000001); + assertEquals("2nd event", "GC CMS-remark:", gcModel.get(1).getTypeAsString()); + assertEquals("2nd event pause", 0.0013199 - 0.0006030, ((GCEvent)gcModel.get(1)).getPause(), 0.00000001); } @Test @@ -813,6 +813,22 @@ public void testCommaInTimestamp() throws Exception { assertEquals("GC pause", 0.3541657, model.getGCPause().getMax(), 0.0000001); assertEquals("GC timestamp", 12.655, model.get(0).getTimestamp(), 0.000001); } + + @Test + public void testPrintGCCause() throws Exception { + ByteArrayInputStream in = new ByteArrayInputStream( + "111.080: [GC (Allocation Failure)111.080: [ParNew: 140365K->605K(157248K), 0.0034070 secs] 190158K->50399K(506816K), 0.0035370 secs] [Times: user=0.02 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", 1, model.size()); + assertEquals("GC pause", 0.0035370, model.getGCPause().getMax(), 0.0000001); + assertEquals("GC timestamp", 111.080, model.get(0).getTimestamp(), 0.000001); + // If types get retained, this will be: + // assertEquals("GC (Allocation Failure) ParNew:", model.get(0).getTypeAsString()); + assertEquals("GC ParNew:", model.get(0).getTypeAsString()); + } /** * Often only the young generation information is explicitly present. Old generation memory diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java index 2f68a0e7..3d20e6ef 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_7_0G1.java @@ -120,6 +120,32 @@ public void printAdaptiveSizePolicy() throws Exception { assertEquals("number of errors", 0, handler.getCount()); } + + + /** + * Test parsing GC logs that have PrintAdaptiveSizePolicy turned on + */ + @Test + public void printGCCause() throws Exception { + TestLogHandler handler = new TestLogHandler(); + handler.setLevel(Level.WARNING); + IMP_LOGGER.addHandler(handler); + DATA_READER_FACTORY_LOGGER.addHandler(handler); + + final InputStream in = getInputStream("SampleSun1_7_0_40PrintGCCause.txt"); + final DataReader reader = new DataReaderSun1_6_0G1(in, GcLogType.SUN1_7G1); + GCModel model = reader.read(); + + assertEquals("gc pause", 0.077938, model.getPause().getMax(), 0.000000001); + GCEvent heap = (GCEvent) model.getEvents().next(); + assertEquals("heap", 32*1024, heap.getPreUsed()); + // test parsing of decimal values + assertEquals("heap", 7136, (double)heap.getPostUsed(), 1e2); + assertEquals("heap", 88.0*1024*1024, (double)heap.getTotal(), 1e2); + + assertEquals("number of errors", 0, handler.getCount()); + } + @Test public void testDetailedCollectionDatestampMixed1() throws Exception { @@ -244,6 +270,20 @@ public void gcRemark() throws Exception { assertEquals("count", 1, model.size()); assertEquals("gc pause", 0.0005297, model.getGCPause().getMax(), 0.000001); } + + @Test + public void gcRemarkWithDateTimeStamp() throws Exception { + final InputStream in = new ByteArrayInputStream( + ("2013-09-08T22:11:22.639+0000: 52131.385: [GC remark 2013-09-08T22:11:22.640+0000: 52131.386: [GC ref-proc, 0.0120750 secs], 0.0347170 secs]\n" + + " [Times: user=0.43 sys=0.00, real=0.03 secs] \n") + .getBytes()); + + final DataReader reader = new DataReaderSun1_6_0G1(in, GcLogType.SUN1_7G1); + GCModel model = reader.read(); + + assertEquals("count", 1, model.size()); + assertEquals("gc pause", 0.0347170, model.getGCPause().getMax(), 0.000001); + } @Test public void printApplicationTimePrintTenuringDistribution() throws Exception { diff --git a/src/test/resources/openjdk/SampleSun1_7_0_40PrintGCCause.txt b/src/test/resources/openjdk/SampleSun1_7_0_40PrintGCCause.txt new file mode 100644 index 00000000..4c1a4b0f --- /dev/null +++ b/src/test/resources/openjdk/SampleSun1_7_0_40PrintGCCause.txt @@ -0,0 +1,120 @@ + 0.199: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 94489280512 bytes, attempted expansion amount: 94489280512 bytes] +2013-05-22T20:43:54.027+0000: 4.438: [GC pause (G1 Evacuation Pause) (young) 4.438: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 5397, predicted base time: 26.19 ms, remaining time: 123.81 ms, target pause time: 150.00 ms] + 4.438: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1 regions, survivors: 0 regions, predicted young region time: 483.38 ms] + 4.438: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 509.57 ms, target pause time: 150.00 ms] +, 0.0208940 secs] + [Parallel Time: 9.2 ms, GC Workers: 8] + [GC Worker Start (ms): Min: 4438.4, Avg: 4441.5, Max: 4446.6, Diff: 8.3] + [Ext Root Scanning (ms): Min: 0.0, Avg: 2.2, Max: 8.4, Diff: 8.4, Sum: 17.3] + [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2] + [Processed Buffers: Min: 0, Avg: 2.9, Max: 16, Diff: 16, Sum: 23] + [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [Object Copy (ms): Min: 0.0, Avg: 2.8, Max: 6.7, Diff: 6.7, Sum: 22.4] + [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.8, Diff: 0.8, Sum: 4.2] + [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2] + [GC Worker Total (ms): Min: 0.3, Avg: 5.5, Max: 8.9, Diff: 8.6, Sum: 44.2] + [GC Worker End (ms): Min: 4446.9, Avg: 4447.0, Max: 4447.3, Diff: 0.5] + [Code Root Fixup: 0.2 ms] + [Clear CT: 0.3 ms] + [Other: 11.2 ms] + [Choose CSet: 0.0 ms] + [Ref Proc: 10.8 ms] + [Ref Enq: 0.2 ms] + [Free CSet: 0.0 ms] + [Eden: 32.0M(32.0M)->0.0B(32.0M) Survivors: 0.0B->32.0M Heap: 32.0M(88.0G)->7136.4K(88.0G)] + [Times: user=0.07 sys=0.02, real=0.02 secs] +2013-05-22T20:43:55.417+0000: 5.828: [GC pause (G1 Evacuation Pause) (young) 5.828: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 3113, predicted base time: 21.00 ms, remaining time: 129.00 ms, target pause time: 150.00 ms] + 5.828: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1 regions, survivors: 1 regions, predicted young region time: 279.42 ms] + 5.828: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 300.42 ms, target pause time: 150.00 ms] +, 0.0148290 secs] + [Parallel Time: 7.3 ms, GC Workers: 8] + [GC Worker Start (ms): Min: 5828.2, Avg: 5828.3, Max: 5828.5, Diff: 0.3] + [Ext Root Scanning (ms): Min: 0.8, Avg: 1.8, Max: 2.4, Diff: 1.7, Sum: 14.7] + [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] + [Processed Buffers: Min: 0, Avg: 2.1, Max: 9, Diff: 9, Sum: 17] + [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [Object Copy (ms): Min: 3.4, Avg: 4.0, Max: 5.1, Diff: 1.7, Sum: 31.9] + [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.9, Diff: 0.9, Sum: 2.1] + [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2] + [GC Worker Total (ms): Min: 5.9, Avg: 6.1, Max: 6.8, Diff: 0.9, Sum: 49.1] + [GC Worker End (ms): Min: 5834.4, Avg: 5834.5, Max: 5835.1, Diff: 0.8] + [Code Root Fixup: 0.4 ms] + [Clear CT: 0.2 ms] + [Other: 6.9 ms] + [Choose CSet: 0.0 ms] + [Ref Proc: 6.5 ms] + [Ref Enq: 0.2 ms] + [Free CSet: 0.0 ms] + [Eden: 32.0M(32.0M)->0.0B(32.0M) Survivors: 32.0M->32.0M Heap: 39.0M(88.0G)->13.9M(88.0G)] + [Times: user=0.07 sys=0.01, real=0.02 secs] +2013-05-22T20:43:56.087+0000: 6.499: [GC pause (G1 Evacuation Pause) (young) 6.499: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 2202, predicted base time: 16.30 ms, remaining time: 133.70 ms, target pause time: 150.00 ms] + 6.499: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1 regions, survivors: 1 regions, predicted young region time: 141.61 ms] + 6.499: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 157.91 ms, target pause time: 150.00 ms] +, 0.0124840 secs] + [Parallel Time: 6.7 ms, GC Workers: 8] + [GC Worker Start (ms): Min: 6498.8, Avg: 6499.0, Max: 6499.1, Diff: 0.3] + [Ext Root Scanning (ms): Min: 1.1, Avg: 1.7, Max: 2.3, Diff: 1.2, Sum: 13.8] + [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] + [Processed Buffers: Min: 0, Avg: 1.5, Max: 12, Diff: 12, Sum: 12] + [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [Object Copy (ms): Min: 3.9, Avg: 4.3, Max: 5.0, Diff: 1.1, Sum: 34.5] + [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2] + [GC Worker Total (ms): Min: 5.9, Avg: 6.1, Max: 6.2, Diff: 0.3, Sum: 48.7] + [GC Worker End (ms): Min: 6505.0, Avg: 6505.0, Max: 6505.1, Diff: 0.0] + [Code Root Fixup: 0.4 ms] + [Clear CT: 0.3 ms] + [Other: 5.1 ms] + [Choose CSet: 0.0 ms] + [Ref Proc: 4.7 ms] + [Ref Enq: 0.2 ms] + [Free CSet: 0.0 ms] + [Eden: 32.0M(32.0M)->0.0B(64.0M) Survivors: 32.0M->32.0M Heap: 45.9M(88.0G)->13.7M(88.0G)] + [Times: user=0.07 sys=0.00, real=0.02 secs] +2013-05-22T20:43:57.961+0000: 8.373: [GC pause (G1 Evacuation Pause) (young) 8.373: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 3388, predicted base time: 13.87 ms, remaining time: 136.13 ms, target pause time: 150.00 ms] + 8.373: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2 regions, survivors: 1 regions, predicted young region time: 115.29 ms] + 8.373: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 129.16 ms, target pause time: 150.00 ms] +, 0.0185740 secs] + [Parallel Time: 11.3 ms, GC Workers: 8] + [GC Worker Start (ms): Min: 8373.0, Avg: 8373.1, Max: 8373.3, Diff: 0.3] + [Ext Root Scanning (ms): Min: 1.5, Avg: 3.3, Max: 4.6, Diff: 3.1, Sum: 26.3] + [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] + [Processed Buffers: Min: 0, Avg: 1.9, Max: 15, Diff: 15, Sum: 15] + [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [Object Copy (ms): Min: 6.2, Avg: 7.4, Max: 9.1, Diff: 2.9, Sum: 59.2] + [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4] + [GC Worker Total (ms): Min: 10.6, Avg: 10.8, Max: 10.9, Diff: 0.3, Sum: 86.0] + [GC Worker End (ms): Min: 8383.8, Avg: 8383.9, Max: 8383.9, Diff: 0.0] + [Code Root Fixup: 0.8 ms] + [Clear CT: 0.2 ms] + [Other: 6.3 ms] + [Choose CSet: 0.0 ms] + [Ref Proc: 5.9 ms] + [Ref Enq: 0.2 ms] + [Free CSet: 0.0 ms] + [Eden: 64.0M(64.0M)->0.0B(256.0M) Survivors: 32.0M->32.0M Heap: 77.7M(88.0G)->27.5M(88.0G)] + [Times: user=0.10 sys=0.02, real=0.02 secs] +2013-05-22T20:44:01.030+0000: 11.442: [GC pause (G1 Evacuation Pause) (young) 11.442: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 3923, predicted base time: 13.49 ms, remaining time: 136.51 ms, target pause time: 150.00 ms] + 11.442: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 8 regions, survivors: 1 regions, predicted young region time: 134.17 ms] + 11.442: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 8 regions, survivors: 1 regions, old: 0 regions, predicted pause time: 147.66 ms, target pause time: 150.00 ms] +, 0.0779380 secs] + [Parallel Time: 59.6 ms, GC Workers: 8] + [GC Worker Start (ms): Min: 11441.9, Avg: 11442.1, Max: 11442.2, Diff: 0.3] + [Ext Root Scanning (ms): Min: 3.6, Avg: 5.6, Max: 7.4, Diff: 3.7, Sum: 45.1] + [Update RS (ms): Min: 0.0, Avg: 1.2, Max: 9.6, Diff: 9.6, Sum: 9.6] + [Processed Buffers: Min: 0, Avg: 3.6, Max: 24, Diff: 24, Sum: 29] + [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] + [Object Copy (ms): Min: 45.0, Avg: 50.6, Max: 52.8, Diff: 7.8, Sum: 405.1] + [Termination (ms): Min: 0.8, Avg: 1.7, Max: 2.2, Diff: 1.4, Sum: 13.7] + [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2] + [GC Worker Total (ms): Min: 59.0, Avg: 59.2, Max: 59.4, Diff: 0.4, Sum: 473.7] + [GC Worker End (ms): Min: 11501.2, Avg: 11501.3, Max: 11501.3, Diff: 0.1] + [Code Root Fixup: 1.5 ms] + [Clear CT: 0.6 ms] + [Other: 16.2 ms] + [Choose CSet: 0.0 ms] + [Ref Proc: 15.4 ms] + [Ref Enq: 0.4 ms] + [Free CSet: 0.1 ms] + [Eden: 256.0M(256.0M)->0.0B(128.0M) Survivors: 32.0M->64.0M Heap: 283.5M(88.0G)->65.9M(88.0G)] diff --git a/src/test/resources/openjdk/SampleSun1_7_0_40PrintGCCause2.txt b/src/test/resources/openjdk/SampleSun1_7_0_40PrintGCCause2.txt new file mode 100644 index 00000000..3c462b56 --- /dev/null +++ b/src/test/resources/openjdk/SampleSun1_7_0_40PrintGCCause2.txt @@ -0,0 +1,2 @@ +2013-09-08T22:11:22.639+0000: 52131.385: [GC remark 2013-09-08T22:11:22.640+0000: 52131.386: [GC ref-proc, 0.0120750 secs], 0.0347170 secs] + [Times: user=0.43 sys=0.00, real=0.03 secs] diff --git a/src/test/resources/openjdk/SampleSun1_7_40CMS_PrintGCCause.txt b/src/test/resources/openjdk/SampleSun1_7_40CMS_PrintGCCause.txt new file mode 100644 index 00000000..e056f84a --- /dev/null +++ b/src/test/resources/openjdk/SampleSun1_7_40CMS_PrintGCCause.txt @@ -0,0 +1,127 @@ +2.167: [GC (Allocation Failure)2.167: [ParNew: 139776K->17471K(157248K), 0.0143520 secs] 139776K->19817K(506816K), 0.0144450 secs] [Times: user=0.05 sys=0.01, real=0.01 secs] +9.362: [GC (Allocation Failure)9.362: [ParNew: 157247K->15133K(157248K), 0.0291490 secs] 159593K->26585K(506816K), 0.0292370 secs] [Times: user=0.11 sys=0.02, real=0.03 secs] +9.899: [GC (Allocation Failure)9.899: [ParNew: 154909K->9268K(157248K), 0.0137570 secs] 166361K->27966K(506816K), 0.0139820 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] +11.087: [GC (Allocation Failure)11.087: [ParNew: 149044K->15025K(157248K), 0.0088430 secs] 167742K->33724K(506816K), 0.0090370 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] +11.633: [GC (Allocation Failure)11.633: [ParNew: 154801K->9027K(157248K), 0.0176650 secs] 173500K->36525K(506816K), 0.0178420 secs] [Times: user=0.07 sys=0.02, real=0.02 secs] +11.969: [GC (Allocation Failure)11.969: [ParNew: 148799K->5226K(157248K), 0.0053210 secs] 176297K->32724K(506816K), 0.0054840 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] +13.173: [GC (Allocation Failure)13.173: [ParNew: 145002K->12094K(157248K), 0.0053880 secs] 172500K->39592K(506816K), 0.0055900 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] +14.085: [GC (Allocation Failure)14.085: [ParNew: 151870K->15643K(157248K), 0.0089330 secs] 179368K->45449K(506816K), 0.0091180 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] +14.761: [GC (Allocation Failure)14.761: [ParNew: 155419K->13518K(157248K), 0.0108460 secs] 185225K->50783K(506816K), 0.0110870 secs] [Times: user=0.05 sys=0.01, real=0.01 secs] +15.406: [GC (Allocation Failure)15.406: [ParNew: 153294K->12828K(157248K), 0.0043750 secs] 190559K->50094K(506816K), 0.0045210 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] +16.029: [GC (Allocation Failure)16.029: [ParNew: 152604K->12020K(157248K), 0.0079940 secs] 189870K->53088K(506816K), 0.0081630 secs] [Times: user=0.04 sys=0.01, real=0.00 secs] +16.698: [GC (Allocation Failure)16.698: [ParNew: 151796K->11680K(157248K), 0.0083420 secs] 192864K->52748K(506816K), 0.0085100 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] +17.243: [GC (Allocation Failure)17.243: [ParNew: 151456K->15343K(157248K), 0.0036040 secs] 192524K->56411K(506816K), 0.0037780 secs] [Times: user=0.03 sys=0.01, real=0.00 secs] +17.829: [GC (Allocation Failure)17.829: [ParNew: 155119K->11016K(157248K), 0.0122690 secs] 196187K->52084K(506816K), 0.0124790 secs] [Times: user=0.07 sys=0.00, real=0.01 secs] +18.334: [GC (Allocation Failure)18.334: [ParNew: 150792K->9797K(157248K), 0.0058100 secs] 191860K->53432K(506816K), 0.0059820 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] +18.893: [GC (Allocation Failure)18.893: [ParNew: 149573K->8249K(157248K), 0.0043860 secs] 193208K->54177K(506816K), 0.0045650 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] +19.435: [GC (Allocation Failure)19.435: [ParNew: 148025K->3668K(157248K), 0.0043380 secs] 193953K->51651K(506816K), 0.0045140 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] +20.003: [GC (Allocation Failure)20.003: [ParNew: 143444K->1566K(157248K), 0.0044040 secs] 191427K->51337K(506816K), 0.0045680 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] +20.597: [GC (Allocation Failure)20.597: [ParNew: 141342K->437K(157248K), 0.0014030 secs] 191113K->50208K(506816K), 0.0015420 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +21.054: [GC (Allocation Failure)21.054: [ParNew: 140213K->216K(157248K), 0.0021170 secs] 189984K->49988K(506816K), 0.0022520 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +21.617: [GC (Allocation Failure)21.617: [ParNew: 139992K->147K(157248K), 0.0014460 secs] 189764K->49920K(506816K), 0.0015680 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +22.324: [GC (Allocation Failure)22.324: [ParNew: 139923K->152K(157248K), 0.0014280 secs] 189696K->49925K(506816K), 0.0015550 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +22.816: [GC (Allocation Failure)22.816: [ParNew: 139928K->219K(157248K), 0.0053890 secs] 189701K->49993K(506816K), 0.0055200 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] +23.134: [GC (Allocation Failure)23.134: [ParNew: 139995K->155K(157248K), 0.0029890 secs] 189769K->49931K(506816K), 0.0031530 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] +23.659: [GC (Allocation Failure)23.659: [ParNew: 139931K->508K(157248K), 0.0015830 secs] 189707K->50285K(506816K), 0.0017260 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +23.961: [GC (Allocation Failure)23.961: [ParNew: 140284K->510K(157248K), 0.0017060 secs] 190061K->50288K(506816K), 0.0018530 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +24.490: [GC (Allocation Failure)24.490: [ParNew: 140286K->312K(157248K), 0.0062070 secs] 190064K->50091K(506816K), 0.0063730 secs] [Times: user=0.04 sys=0.00, real=0.00 secs] +25.048: [GC (Allocation Failure)25.048: [ParNew: 140088K->244K(157248K), 0.0012700 secs] 189867K->50023K(506816K), 0.0013950 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +25.719: [GC (Allocation Failure)25.719: [ParNew: 140020K->163K(157248K), 0.0016970 secs] 189799K->49941K(506816K), 0.0018720 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +26.247: [GC (Allocation Failure)26.247: [ParNew: 139939K->142K(157248K), 0.0012390 secs] 189717K->49921K(506816K), 0.0013580 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +26.884: [GC (Allocation Failure)26.884: [ParNew: 139918K->162K(157248K), 0.0014230 secs] 189697K->49941K(506816K), 0.0015520 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +27.258: [GC (Allocation Failure)27.258: [ParNew: 139938K->156K(157248K), 0.0015480 secs] 189717K->49935K(506816K), 0.0016820 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +27.749: [GC (Allocation Failure)27.749: [ParNew: 139932K->133K(157248K), 0.0015110 secs] 189711K->49913K(506816K), 0.0016250 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +28.255: [GC (Allocation Failure)28.256: [ParNew: 139909K->108K(157248K), 0.0064770 secs] 189689K->49888K(506816K), 0.0065950 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] +28.629: [GC (Allocation Failure)28.629: [ParNew: 139884K->337K(157248K), 0.0019820 secs] 189664K->50117K(506816K), 0.0021210 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +29.224: [GC (Allocation Failure)29.224: [ParNew: 140113K->421K(157248K), 0.0017030 secs] 189893K->50201K(506816K), 0.0018300 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +29.571: [GC (Allocation Failure)29.571: [ParNew: 140197K->226K(157248K), 0.0030320 secs] 189977K->50006K(506816K), 0.0031800 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +30.031: [GC (Allocation Failure)30.031: [ParNew: 140002K->147K(157248K), 0.0013820 secs] 189782K->49927K(506816K), 0.0015070 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] +30.482: [GC (Allocation Failure)30.482: [ParNew: 139923K->160K(157248K), 0.0054030 secs] 189703K->49940K(506816K), 0.0055620 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] +30.883: [GC (Allocation Failure)30.883: [ParNew: 139936K->111K(157248K), 0.0014990 secs] 189716K->49891K(506816K), 0.0016300 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +31.470: [GC (Allocation Failure)31.470: [ParNew: 139887K->128K(157248K), 0.0016690 secs] 189667K->49909K(506816K), 0.0018190 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +31.955: [GC (Allocation Failure)31.955: [ParNew: 139904K->144K(157248K), 0.0018120 secs] 189685K->49924K(506816K), 0.0019570 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +32.557: [GC (Allocation Failure)32.557: [ParNew: 139920K->83K(157248K), 0.0013670 secs] 189700K->49864K(506816K), 0.0015000 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +32.907: [GC (Allocation Failure)32.907: [ParNew: 139859K->368K(157248K), 0.0019350 secs] 189640K->50149K(506816K), 0.0020780 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +33.468: [GC (Allocation Failure)33.468: [ParNew: 140144K->317K(157248K), 0.0015370 secs] 189925K->50097K(506816K), 0.0016580 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] +34.052: [GC (Allocation Failure)34.052: [ParNew: 140093K->351K(157248K), 0.0015430 secs] 189873K->50131K(506816K), 0.0016670 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +34.489: [GC (Allocation Failure)34.489: [ParNew: 140127K->258K(157248K), 0.0037640 secs] 189907K->50039K(506816K), 0.0039430 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] +34.985: [GC (Allocation Failure)34.985: [ParNew: 140034K->110K(157248K), 0.0059390 secs] 189815K->49892K(506816K), 0.0060990 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] +35.559: [GC (Allocation Failure)35.559: [ParNew: 139886K->172K(157248K), 0.0016250 secs] 189668K->49954K(506816K), 0.0017520 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +35.998: [GC (Allocation Failure)35.998: [ParNew: 139948K->143K(157248K), 0.0013060 secs] 189730K->49925K(506816K), 0.0014200 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] +36.495: [GC (Allocation Failure)36.495: [ParNew: 139919K->245K(157248K), 0.0012790 secs] 189701K->50027K(506816K), 0.0013950 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +37.185: [GC (Allocation Failure)37.185: [ParNew: 140021K->190K(157248K), 0.0060900 secs] 189803K->49972K(506816K), 0.0062240 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] +37.687: [GC (Allocation Failure)37.687: [ParNew: 139966K->239K(157248K), 0.0015010 secs] 189748K->50021K(506816K), 0.0016290 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +38.150: [GC (Allocation Failure)38.150: [ParNew: 140015K->356K(157248K), 0.0019500 secs] 189797K->50138K(506816K), 0.0021190 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +38.577: [GC (Allocation Failure)38.578: [ParNew: 140132K->351K(157248K), 0.0017270 secs] 189914K->50133K(506816K), 0.0018600 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +39.149: [GC (Allocation Failure)39.149: [ParNew: 140127K->345K(157248K), 0.0013260 secs] 189909K->50127K(506816K), 0.0014440 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +39.475: [GC (Allocation Failure)39.475: [ParNew: 140121K->257K(157248K), 0.0015350 secs] 189903K->50040K(506816K), 0.0016620 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +39.976: [GC (Allocation Failure)39.976: [ParNew: 140033K->145K(157248K), 0.0015310 secs] 189816K->49928K(506816K), 0.0016550 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +40.408: [GC (Allocation Failure)40.408: [ParNew: 139921K->563K(157248K), 0.0018160 secs] 189704K->50347K(506816K), 0.0019670 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +41.053: [GC (Allocation Failure)41.053: [ParNew: 140339K->337K(157248K), 0.0014220 secs] 190123K->50121K(506816K), 0.0015520 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +41.526: [GC (Allocation Failure)41.526: [ParNew: 140113K->206K(157248K), 0.0040640 secs] 189897K->49991K(506816K), 0.0042170 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] +41.872: [GC (Allocation Failure)41.872: [ParNew: 139982K->116K(157248K), 0.0013370 secs] 189767K->49901K(506816K), 0.0014930 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +42.237: [GC (Allocation Failure)42.237: [ParNew: 139892K->338K(157248K), 0.0020160 secs] 189677K->50123K(506816K), 0.0022250 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +42.675: [GC (Allocation Failure)42.676: [ParNew: 140114K->341K(157248K), 0.0016750 secs] 189899K->50126K(506816K), 0.0018000 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +43.099: [GC (Allocation Failure)43.099: [ParNew: 140117K->384K(157248K), 0.0014080 secs] 189902K->50170K(506816K), 0.0015290 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +43.540: [GC (Allocation Failure)43.541: [ParNew: 140160K->260K(157248K), 0.0015100 secs] 189946K->50045K(506816K), 0.0016510 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +47.248: [GC (Allocation Failure)47.248: [ParNew: 140036K->155K(157248K), 0.0017360 secs] 189821K->49946K(506816K), 0.0018540 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +48.061: [GC (Allocation Failure)48.061: [ParNew: 139931K->177K(157248K), 0.0019980 secs] 189722K->49967K(506816K), 0.0021390 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +48.657: [GC (Allocation Failure)48.657: [ParNew: 139953K->213K(157248K), 0.0013470 secs] 189743K->50003K(506816K), 0.0014770 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +49.162: [GC (Allocation Failure)49.163: [ParNew: 139989K->166K(157248K), 0.0045560 secs] 189779K->49957K(506816K), 0.0047910 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] +49.885: [GC (Allocation Failure)49.885: [ParNew: 139942K->148K(157248K), 0.0020630 secs] 189733K->49939K(506816K), 0.0021890 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] +50.277: [GC (Allocation Failure)50.277: [ParNew: 139924K->436K(157248K), 0.0016090 secs] 189715K->50226K(506816K), 0.0017630 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] +50.825: [GC (Allocation Failure)50.825: [ParNew: 140212K->387K(157248K), 0.0014330 secs] 190002K->50178K(506816K), 0.0015590 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +51.402: [GC (Allocation Failure)51.403: [ParNew: 140163K->366K(157248K), 0.0012350 secs] 189954K->50157K(506816K), 0.0013710 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] +51.833: [GC (Allocation Failure)51.833: [ParNew: 140142K->178K(157248K), 0.0013340 secs] 189933K->49969K(506816K), 0.0014560 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +52.322: [GC (Allocation Failure)52.323: [ParNew: 139954K->108K(157248K), 0.0014210 secs] 189745K->49899K(506816K), 0.0015660 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +52.704: [GC (Allocation Failure)52.704: [ParNew: 139884K->132K(157248K), 0.0105530 secs] 189675K->49924K(506816K), 0.0107020 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] +53.301: [GC (Allocation Failure)53.301: [ParNew: 139908K->126K(157248K), 0.0017520 secs] 189700K->49917K(506816K), 0.0018840 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +53.855: [GC (Allocation Failure)53.855: [ParNew: 139902K->218K(157248K), 0.0014700 secs] 189693K->50010K(506816K), 0.0016030 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +54.245: [GC (Allocation Failure)54.245: [ParNew: 139994K->163K(157248K), 0.0029460 secs] 189786K->49956K(506816K), 0.0030850 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] +54.617: [GC (Allocation Failure)54.617: [ParNew: 139939K->523K(157248K), 0.0015510 secs] 189732K->50315K(506816K), 0.0016730 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +55.090: [GC (Allocation Failure)55.090: [ParNew: 140299K->394K(157248K), 0.0041680 secs] 190091K->50187K(506816K), 0.0043020 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] +55.454: [GC (Allocation Failure)55.454: [ParNew: 140170K->293K(157248K), 0.0014730 secs] 189963K->50085K(506816K), 0.0016050 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +56.033: [GC (Allocation Failure)56.033: [ParNew: 140069K->254K(157248K), 0.0014490 secs] 189861K->50048K(506816K), 0.0015800 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +56.519: [GC (Allocation Failure)56.519: [ParNew: 140030K->204K(157248K), 0.0015490 secs] 189824K->49997K(506816K), 0.0016790 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +107.254: [GC (Allocation Failure)107.254: [ParNew: 139980K->222K(157248K), 0.0016200 secs] 189773K->50015K(506816K), 0.0017890 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +109.659: [GC (Allocation Failure)109.659: [ParNew: 139998K->215K(157248K), 0.0012880 secs] 189791K->50008K(506816K), 0.0014140 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +110.399: [GC (Allocation Failure)110.399: [ParNew: 139991K->589K(157248K), 0.0016960 secs] 189784K->50382K(506816K), 0.0018300 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +111.080: [GC (Allocation Failure)111.080: [ParNew: 140365K->605K(157248K), 0.0034070 secs] 190158K->50399K(506816K), 0.0035370 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] +111.580: [GC (Allocation Failure)111.580: [ParNew: 140381K->421K(157248K), 0.0015590 secs] 190175K->50214K(506816K), 0.0016930 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +112.149: [GC (Allocation Failure)112.149: [ParNew: 140197K->440K(157248K), 0.0014650 secs] 189990K->50233K(506816K), 0.0016120 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +112.777: [GC (Allocation Failure)112.777: [ParNew: 140216K->332K(157248K), 0.0088580 secs] 190009K->50196K(506816K), 0.0090210 secs] [Times: user=0.06 sys=0.00, real=0.00 secs] +113.246: [GC (Allocation Failure)113.246: [ParNew: 140108K->277K(157248K), 0.0106000 secs] 189972K->50141K(506816K), 0.0107690 secs] [Times: user=0.07 sys=0.01, real=0.01 secs] +113.618: [GC (Allocation Failure)113.618: [ParNew: 140053K->148K(157248K), 0.0019570 secs] 189917K->50012K(506816K), 0.0021030 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +115.911: [GC (Allocation Failure)115.911: [ParNew: 139924K->326K(157248K), 0.0013340 secs] 189788K->50216K(506816K), 0.0014590 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +118.357: [GC (Allocation Failure)118.357: [ParNew: 140102K->202K(157248K), 0.0013390 secs] 189992K->50091K(506816K), 0.0014560 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +119.348: [GC (Allocation Failure)119.348: [ParNew: 139978K->514K(157248K), 0.0020710 secs] 189867K->50403K(506816K), 0.0022210 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +119.928: [GC (Allocation Failure)119.929: [ParNew: 140290K->598K(157248K), 0.0015870 secs] 190179K->50488K(506816K), 0.0017170 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +120.554: [GC (Allocation Failure)120.554: [ParNew: 140374K->410K(157248K), 0.0015650 secs] 190264K->50300K(506816K), 0.0017040 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +121.069: [GC (Allocation Failure)121.069: [ParNew: 140186K->225K(157248K), 0.0051570 secs] 190076K->50115K(506816K), 0.0052940 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] +121.719: [GC (Allocation Failure)121.719: [ParNew: 140001K->186K(157248K), 0.0020860 secs] 189891K->50076K(506816K), 0.0022480 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +122.214: [GC (Allocation Failure)122.214: [ParNew: 139962K->154K(157248K), 0.0013880 secs] 189852K->50044K(506816K), 0.0015210 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +714.338: [GC (Allocation Failure)714.338: [ParNew: 139930K->667K(157248K), 0.0017070 secs] 189820K->50557K(506816K), 0.0018400 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +714.879: [GC (Allocation Failure)714.879: [ParNew: 140443K->645K(157248K), 0.0015070 secs] 190333K->50536K(506816K), 0.0016430 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +715.296: [GC (Allocation Failure)715.297: [ParNew: 140421K->601K(157248K), 0.0019890 secs] 190312K->50491K(506816K), 0.0021540 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] +715.620: [GC (Allocation Failure)715.620: [ParNew: 140377K->855K(157248K), 0.0025910 secs] 190267K->50746K(506816K), 0.0027660 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +716.129: [GC (Allocation Failure)716.129: [ParNew: 140631K->841K(157248K), 0.0015850 secs] 190522K->50732K(506816K), 0.0017330 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +716.466: [GC (Allocation Failure)716.466: [ParNew: 140617K->753K(157248K), 0.0016950 secs] 190508K->50643K(506816K), 0.0018180 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +716.940: [GC (Allocation Failure)716.941: [ParNew: 140529K->220K(157248K), 0.0028860 secs] 190419K->50569K(506816K), 0.0030260 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] +717.521: [GC (Allocation Failure)717.521: [ParNew: 139996K->119K(157248K), 0.0013230 secs] 190345K->50468K(506816K), 0.0014390 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] +718.010: [GC (Allocation Failure)718.010: [ParNew: 139895K->146K(157248K), 0.0016710 secs] 190244K->50495K(506816K), 0.0018180 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +718.421: [GC (Allocation Failure)718.421: [ParNew: 139922K->114K(157248K), 0.0014510 secs] 190271K->50464K(506816K), 0.0015760 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +718.908: [GC (Allocation Failure)718.908: [ParNew: 139890K->170K(157248K), 0.0018070 secs] 190240K->50519K(506816K), 0.0019340 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +719.314: [GC (Allocation Failure)719.314: [ParNew: 139946K->155K(157248K), 0.0017010 secs] 190295K->50504K(506816K), 0.0018340 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +719.636: [GC (Allocation Failure)719.636: [ParNew: 139931K->549K(157248K), 0.0015080 secs] 190280K->50898K(506816K), 0.0016300 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +720.054: [GC (Allocation Failure)720.054: [ParNew: 140325K->471K(157248K), 0.0016300 secs] 190674K->50820K(506816K), 0.0017560 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +720.531: [GC (Allocation Failure)720.531: [ParNew: 140247K->304K(157248K), 0.0013960 secs] 190596K->50653K(506816K), 0.0015150 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] +721.019: [GC (Allocation Failure)721.019: [ParNew: 140080K->213K(157248K), 0.0015080 secs] 190429K->50562K(506816K), 0.0016440 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +729.934: [GC (Allocation Failure)729.935: [ParNew: 139989K->287K(157248K), 0.0017780 secs] 190338K->50636K(506816K), 0.0019360 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +730.658: [GC (Allocation Failure)730.658: [ParNew: 140063K->341K(157248K), 0.0014070 secs] 190412K->50691K(506816K), 0.0015220 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] +731.444: [GC (Allocation Failure)731.444: [ParNew: 140117K->213K(157248K), 0.0075830 secs] 190467K->50563K(506816K), 0.0077460 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] +732.164: [GC (Allocation Failure)732.164: [ParNew: 139989K->148K(157248K), 0.0035640 secs] 190339K->50498K(506816K), 0.0037120 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] +732.937: [GC (Allocation Failure)732.937: [ParNew: 139924K->226K(157248K), 0.0032410 secs] 190274K->50576K(506816K), 0.0033770 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +733.787: [GC (Allocation Failure)733.787: [ParNew: 140002K->211K(157248K), 0.0013960 secs] 190352K->50561K(506816K), 0.0015190 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] +734.332: [GC (Allocation Failure)734.332: [ParNew: 139987K->114K(157248K), 0.0042860 secs] 190337K->50468K(506816K), 0.0044590 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] +734.941: [GC (Allocation Failure)734.941: [ParNew: 139890K->143K(157248K), 0.0014340 secs] 190244K->50497K(506816K), 0.0015680 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] +735.695: [GC (Allocation Failure)735.695: [ParNew: 139919K->99K(157248K), 0.0065500 secs] 190273K->50454K(506816K), 0.0067500 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] \ No newline at end of file