Skip to content

Commit 9cf6058

Browse files
chewiebugchewiebug
committed
improve a few things in G1 parser
1 parent 082919c commit 9cf6058

File tree

4 files changed

+192
-9
lines changed

4 files changed

+192
-9
lines changed

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

Lines changed: 85 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -55,7 +55,7 @@
5555
*/
5656
public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun {
5757

58-
private static final String INCOMPLETE_CONCURRENT_MARK_INDICATOR = "concurrent-mark";
58+
private static final String INCOMPLETE_CONCURRENT_EVENT_INDICATOR = "concurrent-";
5959

6060
private static final Logger LOG = Logger.getLogger(DataReaderSun1_6_0G1.class .getName());
6161

@@ -115,8 +115,12 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun {
115115
HEAP_STRINGS.add("Metaspace"); // java 8
116116
HEAP_STRINGS.add("class space"); // java 8
117117
HEAP_STRINGS.add("}");
118+
HEAP_STRINGS.add("[0x"); // special case of line following one containing a concurrent event mixed with heap information
118119
}
119120

121+
/** is true, if "[Times ..." information is present in the gc log */
122+
private boolean hasTimes = false;
123+
120124
public DataReaderSun1_6_0G1(InputStream in, GcLogType gcLogType) throws UnsupportedEncodingException {
121125
super(in, gcLogType);
122126
}
@@ -288,10 +292,10 @@ else if (line.indexOf(Type.FULL_GC.getName()) > 0) {
288292
}
289293
else if (line.indexOf(HEAP_SIZING_START) >= 0) {
290294
// the next few lines will be the sizing of the heap
291-
lineNumber = skipLines(in, parsePosition, lineNumber, HEAP_STRINGS);
295+
lineNumber = skipLinesRespectingConcurrentEvents(in, model, parsePosition, lineNumber, HEAP_STRINGS);
292296
continue;
293297
}
294-
else if (line.indexOf(INCOMPLETE_CONCURRENT_MARK_INDICATOR) >= 0) {
298+
else if (hasIncompleteConcurrentEvent(line, parsePosition)) {
295299
parseIncompleteConcurrentEvent(model, model.getLastEventAdded(), line, parsePosition);
296300
}
297301
else {
@@ -313,6 +317,12 @@ else if (line.indexOf(INCOMPLETE_CONCURRENT_MARK_INDICATOR) >= 0) {
313317
}
314318
}
315319

320+
private boolean hasIncompleteConcurrentEvent(String line, ParseInformation paresPosition) {
321+
return !nextIsTimestamp(line, paresPosition)
322+
&& !nextIsDatestamp(line, paresPosition)
323+
&& line.indexOf(INCOMPLETE_CONCURRENT_EVENT_INDICATOR) >= 0;
324+
}
325+
316326
/**
317327
* Returns true, if <code>line</code> ends with one of the detailed event types.
318328
*
@@ -357,7 +367,11 @@ private int parseDetails(BufferedReader in,
357367
++lineNumber;
358368
pos.setLineNumber(lineNumber);
359369
pos.setIndex(0);
360-
370+
371+
if (line.length() == 0) {
372+
continue;
373+
}
374+
361375
// we might have had a mixed line before; then we just parsed the second part of the mixed line
362376
if (beginningOfLine != null) {
363377
line = beginningOfLine + line;
@@ -371,7 +385,13 @@ private int parseDetails(BufferedReader in,
371385
if (line.indexOf("Eden") >= 0) {
372386
parseMemoryDetails(event, line, pos);
373387
}
374-
else if (line.indexOf(INCOMPLETE_CONCURRENT_MARK_INDICATOR) >= 0) {
388+
else if (line.charAt(0) != ' ' && !hasTimes && (nextIsDatestamp(line, pos) || nextIsTimestamp(line, pos))) {
389+
// special case for simple logs (marked by missing "[Times..." in the log)
390+
// since the line starts with a time / datestamp, the detailed event seems to be finished (unexpectedly)
391+
model.add(parseLine(line, pos));
392+
isInDetailedEvent = false;
393+
}
394+
else if (line.indexOf(INCOMPLETE_CONCURRENT_EVENT_INDICATOR) >= 0) {
375395
parseIncompleteConcurrentEvent(model, event, line, pos);
376396
}
377397
else {
@@ -387,6 +407,7 @@ else if (line.indexOf(INCOMPLETE_CONCURRENT_MARK_INDICATOR) >= 0) {
387407
if (line.indexOf(TIMES) >= 0) {
388408
// detailed gc description ends with " [Times: user=...]" -> stop reading lines
389409
isInDetailedEvent = false;
410+
hasTimes = true;
390411
}
391412
}
392413

@@ -462,7 +483,11 @@ private void parseIncompleteConcurrentEvent(GCModel model, AbstractGCEvent<?> pr
462483
// some concurrent event is mixed in -> extract it
463484
pos.setIndex(line.indexOf("GC conc"));
464485
ExtendedType type = parseType(line, pos);
465-
model.add(parseConcurrentEvent(line, pos, previousEvent.getDatestamp(), previousEvent.getTimestamp(), type));
486+
model.add(parseConcurrentEvent(line,
487+
pos,
488+
previousEvent != null ? previousEvent.getDatestamp() : null,
489+
previousEvent != null ? previousEvent.getTimestamp() : 0,
490+
type));
466491
}
467492

468493
@Override
@@ -544,4 +569,58 @@ private AbstractGCEvent<?> parseConcurrentEvent(String line,
544569
return event;
545570
}
546571

572+
/**
573+
* Skips a block of lines containing information like they are generated by
574+
* -XX:+PrintHeapAtGC or -XX:+PrintAdaptiveSizePolicy.
575+
*
576+
* @param in inputStream of the current log to be read
577+
* @param lineNumber current line number
578+
* @param lineStartStrings lines starting with these strings should be ignored
579+
* @return line number including lines read in this method
580+
* @throws IOException problem with reading from the file
581+
*/
582+
private int skipLinesRespectingConcurrentEvents(BufferedReader in, GCModel model, ParseInformation pos, int lineNumber, List<String> lineStartStrings) throws IOException {
583+
String line = "";
584+
585+
if (!in.markSupported()) {
586+
LOG.warning("input stream does not support marking!");
587+
}
588+
else {
589+
in.mark(200);
590+
}
591+
592+
boolean startsWithString = true;
593+
while (startsWithString && (line = in.readLine()) != null) {
594+
++lineNumber;
595+
pos.setLineNumber(lineNumber);
596+
597+
if (line.indexOf(INCOMPLETE_CONCURRENT_EVENT_INDICATOR) >= 0) {
598+
parseIncompleteConcurrentEvent(model, model.getLastEventAdded(), line, pos);
599+
}
600+
else {
601+
// for now just skip those lines
602+
startsWithString = startsWith(line, lineStartStrings, true);
603+
if (startsWithString) {
604+
// don't mark any more if line didn't match -> it is the first line that
605+
// is of interest after the skipped block
606+
if (in.markSupported()) {
607+
in.mark(200);
608+
}
609+
}
610+
}
611+
}
612+
613+
// push last read line back into stream - it is the next event to be parsed
614+
if (in.markSupported()) {
615+
try {
616+
in.reset();
617+
}
618+
catch (IOException e) {
619+
throw new ParseException("problem resetting stream (" + e.toString() + ")", line, pos);
620+
}
621+
}
622+
623+
return --lineNumber;
624+
}
625+
547626
}

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

Lines changed: 58 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717

1818
import com.tagtraum.perf.gcviewer.math.DoubleData;
1919
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
20+
import com.tagtraum.perf.gcviewer.model.ConcurrentGCEvent;
2021
import com.tagtraum.perf.gcviewer.model.GCEvent;
2122
import com.tagtraum.perf.gcviewer.model.GCModel;
2223

@@ -192,14 +193,20 @@ public void testDetailedCollectionDatestampMixed2() throws Exception {
192193
// 371.856: [Parallel Time: 268.0 ms]
193194
// [GC concurrent-mark-start]
194195

196+
TestLogHandler handler = new TestLogHandler();
197+
handler.setLevel(Level.WARNING);
198+
IMP_LOGGER.addHandler(handler);
199+
DATA_READER_FACTORY_LOGGER.addHandler(handler);
200+
195201
final InputStream in = getInputStream("SampleSun1_7_0G1_DateStamp_Detailed-mixedLine2.txt");
196202
final DataReader reader = new DataReaderSun1_6_0G1(in, GcLogType.SUN1_7G1);
197203
GCModel model = reader.read();
198204

199-
assertEquals("nummber of events", 2, model.size());
205+
assertEquals("number of events", 3, model.size());
206+
assertEquals("number of warnings", 0, handler.getCount());
200207
assertEquals("concurrent event type", Type.G1_CONCURRENT_MARK_START.toString(), model.getConcurrentGCEvents().next().getTypeAsString());
201-
assertEquals("number of pauses", 1, model.getPause().getN());
202-
assertEquals("gc pause sum", 0.28031200, model.getPause().getSum(), 0.000000001);
208+
assertEquals("number of pauses", 2, model.getPause().getN());
209+
assertEquals("gc pause max", 0.28031200, model.getPause().getMax(), 0.000000001);
203210
assertEquals("gc memory", 20701*1024 - 20017*1024, model.getFreedMemoryByGC().getMax());
204211
}
205212

@@ -362,6 +369,54 @@ public void printApplicationTimePrintTenuringDistribution() throws Exception {
362369

363370
assertEquals("number of errors", 0, handler.getCount());
364371
}
372+
373+
/**
374+
* Usually "cleanup" events have memory information; if it doesn't the parser should just continue
375+
*/
376+
@Test
377+
public void simpleLogCleanUpNoMemory() throws Exception {
378+
final InputStream in = new ByteArrayInputStream(
379+
("2013-06-22T18:58:45.955+0200: 1.433: [Full GC 128M->63M(128M), 0.0385026 secs]"
380+
+ "\n2013-06-22T18:58:45.986+0200: 1.472: [GC cleanup, 0.0000004 secs]"
381+
+ "\n2013-06-22T18:58:45.986+0200: 1.472: [GC concurrent-mark-abort]"
382+
+ "\n2013-06-22T18:58:46.002+0200: 1.483: [GC pause (young) 91M->90M(128M), 0.0128787 secs]")
383+
.getBytes());
384+
385+
final DataReader reader = new DataReaderSun1_6_0G1(in, GcLogType.SUN1_7G1);
386+
GCModel model = reader.read();
387+
388+
assertEquals("count", 4, model.size());
389+
390+
// the order of the events is in fact wrong; but for the sake of simplicity in the parser I accept it
391+
assertEquals("cleanup event", "GC cleanup", model.get(2).getTypeAsString());
392+
assertEquals("concurrent-mark-abort event", "GC concurrent-mark-abort", model.get(1).getTypeAsString());
393+
}
394+
395+
@Test
396+
public void printHeapAtGcWithConcurrentEvents() throws Exception {
397+
TestLogHandler handler = new TestLogHandler();
398+
handler.setLevel(Level.WARNING);
399+
IMP_LOGGER.addHandler(handler);
400+
DATA_READER_FACTORY_LOGGER.addHandler(handler);
401+
402+
final InputStream in = getInputStream("SampleSun1_7_0G1_PrintHeapAtGC_withConcurrent.txt");
403+
final DataReader reader = new DataReaderSun1_6_0G1(in, GcLogType.SUN1_7G1);
404+
GCModel model = reader.read();
405+
406+
assertEquals("number of events", 3, model.size());
407+
assertEquals("number of concurrent events", 2, model.getConcurrentEventPauses().size());
408+
409+
ConcurrentGCEvent concurrentEvent = (ConcurrentGCEvent) model.get(0);
410+
assertEquals("GC concurrent-root-region-scan-end expected", "GC concurrent-root-region-scan-end", concurrentEvent.getTypeAsString());
411+
412+
concurrentEvent = (ConcurrentGCEvent) model.get(1);
413+
assertEquals("GC concurrent-mark-start expected", "GC concurrent-mark-start", concurrentEvent.getTypeAsString());
414+
415+
GCEvent fullGcEvent = (GCEvent) model.get(2);
416+
assertEquals("full gc", "Full GC", fullGcEvent.getTypeAsString());
417+
418+
assertEquals("number of errors", 0, handler.getCount());
419+
}
365420

366421
@Test
367422
public void printPrintHeapAtGC() throws Exception {

‎src/test/resources/openjdk/SampleSun1_7_0G1_DateStamp_Detailed-mixedLine2.txt‎

Lines changed: 32 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,35 @@
1+
2012-02-24T03:50:08.274-0800: 370.576: [GC pause (young), 0.08031200 secs]
2+
[Parallel Time: 268.0 ms]
3+
[GC Worker Start Time (ms): 371577.0 371577.0 371577.0 371577.1 371577.1 371577.1 371584.2 371584.3 371584.3 371584.4 371584.4 371584.4 371584.4 371584.4 371584.4
4+
Avg: 371581.4, Min: 371577.0, Max: 371584.4, Diff: 7.5]
5+
[Update RS (ms): 111.9 107.4 111.7 116.9 107.2 111.5 102.3 130.1 101.9 102.9 102.6 101.7 102.8 104.3 111.1
6+
Avg: 108.4, Min: 101.7, Max: 130.1, Diff: 28.4]
7+
[Processed Buffers : 136 115 74 93 116 76 79 97 100 126 70 75 69 67 75
8+
Sum: 1368, Avg: 91, Min: 67, Max: 136, Diff: 69]
9+
[Ext Root Scanning (ms): 1.8 1.6 1.6 1.6 1.7 1.6 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
10+
Avg: 0.7, Min: 0.0, Max: 1.8, Diff: 1.8]
11+
[Mark Stack Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
12+
Avg: 0.0, Min: 0.0, Max: 0.0, Diff: 0.0]
13+
[Scan RS (ms): 0.1 2.2 0.1 0.1 2.2 0.1 1.9 0.2 2.1 1.0 1.4 2.2 1.1 0.1 0.2
14+
Avg: 1.0, Min: 0.1, Max: 2.2, Diff: 2.2]
15+
[Object Copy (ms): 145.7 149.1 146.2 140.9 148.5 146.2 148.2 129.9 148.2 148.2 148.2 154.8 148.2 147.7 143.7
16+
Avg: 146.2, Min: 129.9, Max: 154.8, Diff: 24.9]
17+
[Termination (ms): 7.9 7.3 7.9 7.9 7.8 8.0 8.0 0.0 8.0 7.9 7.9 1.4 8.0 7.9 5.0
18+
Avg: 6.7, Min: 0.0, Max: 8.0, Diff: 8.0]
19+
[Termination Attempts : 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1
20+
Sum: 15, Avg: 1, Min: 1, Max: 1, Diff: 0]
21+
[GC Worker End Time (ms): 371844.6 371844.6 371844.5 371844.6 371844.6 371844.6 371844.5 371844.5 371844.6 371844.7 371844.7 371844.5 371844.6 371844.6 371844.6
22+
Avg: 371844.6, Min: 371844.5, Max: 371844.7, Diff: 0.2]
23+
[GC Worker Times (ms): 267.6 267.7 267.5 267.5 267.5 267.5 260.4 260.3 260.3 260.3 260.3 260.1 260.2 260.2 260.2
24+
Avg: 263.2, Min: 260.1, Max: 267.7, Diff: 7.5]
25+
[Parallel Other: 5.0 ms]
26+
[Clear CT: 0.7 ms]
27+
[Other: 11.6 ms]
28+
[Choose CSet: 0.0 ms]
29+
[Ref Proc: 0.9 ms]
30+
[Ref Enq: 0.0 ms]
31+
[Eden: 960M(960M)->0B(896M) Survivors: 64M->128M Heap: 20701M(25936M)->20017M(25936M)]
32+
[Times: user=2.50 sys=0.13, real=0.29 secs]
133
2012-02-24T03:50:08.274-0800: 371.576: [GC pause (young)2012-02-24T03:50:08.554-0800: (initial-mark), 0.28031200 secs]
234
371.856: [Parallel Time: 268.0 ms]
335
[GC concurrent-mark-start]

‎src/test/resources/openjdk/SampleSun1_7_0G1_PrintHeapAtGC_withConcurrent.txt‎

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,17 @@
1+
2.385: {Heap before GC invocations=166 (full 32):
2+
[GC concurrent-root-region-scan-end, 0.0000684]
3+
garbage-first heap 2.385: total 131072K, used 131072K[GC concurrent-mark-start]
4+
[0x04800000, 0x0c800000, 0x0c800000)
5+
region size 8192K, 1 young (8192K), 1 survivors (8192K)
6+
compacting perm gen total 8192K, used 1626K [0x0c800000, 0x0d000000, 0x10800000)
7+
the space 8192K, 19% used [0x0c800000, 0x0c996bd0, 0x0c996c00, 0x0d000000)
8+
No shared spaces configured.
9+
2.385: [Full GC 128M->57M(128M), 0.0326402 secs]
10+
[Times: user=0.05 sys=0.00, real=0.05 secs]
11+
Heap after GC invocations=167 (full 33):
12+
garbage-first heap total 131072K, used 59219K [0x04800000, 0x0c800000, 0x0c800000)
13+
region size 8192K, 0 young (0K), 0 survivors (0K)
14+
compacting perm gen total 8192K, used 1626K [0x0c800000, 0x0d000000, 0x10800000)
15+
the space 8192K, 19% used [0x0c800000, 0x0c996bd0, 0x0c996c00, 0x0d000000)
16+
No shared spaces configured.
17+
}

0 commit comments

Comments
 (0)