Skip to content

Commit 18f43e8

Browse files
chewiebugchewiebug
committed
improve handling of -XX:+PrintFLSStatistics (also ignore output for "concurrent mode failures")
1 parent 29eaee7 commit 18f43e8

File tree

7 files changed

+499
-50
lines changed

7 files changed

+499
-50
lines changed

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

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
import java.io.UnsupportedEncodingException;
88
import java.text.SimpleDateFormat;
99
import java.util.Date;
10+
import java.util.LinkedList;
1011
import java.util.List;
1112
import java.util.logging.Level;
1213
import java.util.logging.Logger;
@@ -40,13 +41,27 @@ public abstract class AbstractDataReaderSun implements DataReader {
4041
public static final String DATE_STAMP_FORMAT = "yyyy-MM-dd'T'HH:mm:ss.S";
4142
private static final int LENGTH_OF_DATESTAMP = 29;
4243

43-
private static final String CMS_PRINT_PROMOTION_FAILURE = "promotion failure size";
44-
4544
private static Logger LOG = Logger.getLogger(AbstractDataReaderSun.class.getName());
45+
46+
private static final String CMS_PRINT_PROMOTION_FAILURE = "promotion failure size";
4647
private final SimpleDateFormat dateParser = new SimpleDateFormat(DATE_STAMP_FORMAT);
4748

4849
private static Pattern parenthesesPattern = Pattern.compile("\\([^()]*\\) ?");
4950

51+
// java 8 log output
52+
protected static final String LOG_INFORMATION_OPENJDK = "OpenJDK";
53+
protected static final String LOG_INFORMATION_HOTSPOT = "Java HotSpot";
54+
protected static final String LOG_INFORMATION_MEMORY = "Memory:";
55+
protected static final String LOG_INFORMATION_COMMANDLINE_FLAGS = "CommandLine flags:";
56+
protected static final List<String> LOG_INFORMATION_STRINGS = new LinkedList<String>();
57+
58+
static {
59+
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_OPENJDK);
60+
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_HOTSPOT);
61+
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_MEMORY);
62+
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_COMMANDLINE_FLAGS);
63+
}
64+
5065
/** the reader accessing the log file */
5166
protected BufferedReader in;
5267
/** the log type allowing for small differences between different versions of the gc logs */

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

Lines changed: 60 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
import java.util.logging.Logger;
1313
import java.util.regex.Matcher;
1414
import java.util.regex.Pattern;
15+
1516
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent;
1617
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.CollectionType;
1718
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Concurrency;
@@ -26,7 +27,7 @@
2627
import com.tagtraum.perf.gcviewer.util.ParseInformation;
2728

2829
/**
29-
* <p>Parses log output from Sun / Oracle Java 1.4 / 1.5 / 1.6. / 1.7
30+
* <p>Parses log output from Sun / Oracle Java 1.4 / 1.5 / 1.6. / 1.7 / 1.8
3031
* <br>Supports the following gc algorithms:
3132
* <ul>
3233
* <li>-XX:+UseSerialGC</li>
@@ -70,6 +71,8 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
7071
private static final String APPLICATION_TIME = "Application time:";
7172
private static final String BEFORE_GC = "Before GC:"; // -XX:+PrintFLSStatistics=1
7273
private static final String AFTER_GC = "After GC:"; // -XX:+PrintFLSStatistics=1
74+
private static final String CMS_LARGE_BLOCK = "CMS: Large "; // -XX:+PrintFLSStatistics=1
75+
private static final String SIZE = "size["; // -XX:+PrintFLSStatistics=1
7376

7477
private static final List<String> EXCLUDE_STRINGS = new LinkedList<String>();
7578

@@ -100,9 +103,9 @@ public class DataReaderSun1_6_0 extends AbstractDataReaderSun {
100103
EXCLUDE_STRINGS.add("Tree Height:"); // -XX:+PrintFLSStatistics=1
101104
EXCLUDE_STRINGS.add(BEFORE_GC); // -XX:+PrintFLSStatistics=1
102105
EXCLUDE_STRINGS.add(AFTER_GC); // -XX:+PrintFLSStatistics=1
103-
EXCLUDE_STRINGS.add("CMS: Large "); // -XX:+PrintFLSStatistics=1
106+
EXCLUDE_STRINGS.add(CMS_LARGE_BLOCK); // -XX:+PrintFLSStatistics=1
104107
EXCLUDE_STRINGS.add(" free"); // -XX:+PrintFLSStatistics=2
105-
EXCLUDE_STRINGS.add("size["); // -XX:+PrintFLSStatistics=2
108+
EXCLUDE_STRINGS.add(SIZE); // -XX:+PrintFLSStatistics=2
106109
EXCLUDE_STRINGS.add("demand"); // -XX:+PrintFLSStatistics=2
107110
}
108111

@@ -207,10 +210,10 @@ public DataReaderSun1_6_0(InputStream in, GcLogType gcLogType) throws Unsupporte
207210
}
208211

209212
public GCModel read() throws IOException {
210-
if (LOG.isLoggable(Level.INFO)) LOG.info("Reading Sun / Oracle 1.4.x / 1.5.x / 1.6.x / 1.7.x format...");
213+
if (LOG.isLoggable(Level.INFO)) LOG.info("Reading Sun / Oracle 1.4.x / 1.5.x / 1.6.x / 1.7.x / 1.8.x format...");
211214

212215
try (BufferedReader in = this.in) {
213-
final GCModel model = new GCModel();
216+
GCModel model = new GCModel();
214217
model.setFormat(GCModel.Format.SUN_X_LOG_GC);
215218
Matcher mixedLineMatcher = linesMixedPattern.matcher("");
216219
Matcher adaptiveSizePolicyMatcher = adaptiveSizePolicyPattern.matcher("");
@@ -224,7 +227,7 @@ public GCModel read() throws IOException {
224227
boolean lastLineWasScavengeBeforeRemark = false;
225228
boolean lineSkippedForScavengeBeforeRemark = false;
226229
boolean printTenuringDistributionOn = false;
227-
final ParseInformation parsePosition = new ParseInformation(0);
230+
ParseInformation parsePosition = new ParseInformation(0);
228231

229232
while ((line = in.readLine()) != null) {
230233
++lineNumber;
@@ -243,6 +246,11 @@ else if (line.indexOf(APPLICATION_TIME) > 0) {
243246
// when it occurs including timestamp (since about jdk1.7.0_50) it should still be ignored
244247
continue;
245248
}
249+
else if (startsWith(line, LOG_INFORMATION_STRINGS, false)) {
250+
LOG.info(line);
251+
continue;
252+
}
253+
246254
if (line.indexOf(CMS_ABORT_PRECLEAN) >= 0) {
247255
// line contains like " CMS: abort preclean due to time "
248256
// -> remove the text
@@ -285,13 +293,8 @@ else if (line.indexOf(APPLICATION_TIME) > 0) {
285293
if (line.indexOf(PRINT_REFERENCE_GC_INDICATOR) > 0) {
286294
line = filterAwayReferenceGc(line);
287295
}
288-
if (line.endsWith(BEFORE_GC)) {
289-
beginningOfLine.addFirst(line.substring(0, line.indexOf(BEFORE_GC)));
290-
continue;
291-
}
292-
else if (line.endsWith(AFTER_GC)) {
293-
String beginning = beginningOfLine.removeFirst();
294-
beginningOfLine.addFirst(beginning + line.substring(0, line.indexOf(AFTER_GC)));
296+
if (lineHasPrintFlsStatistics(line)) {
297+
handlePrintFlsStatistics(line, beginningOfLine);
295298
continue;
296299
}
297300

@@ -317,7 +320,7 @@ else if (line.endsWith(AFTER_GC)) {
317320
lastLineWasScavengeBeforeRemark = true;
318321
continue;
319322
}
320-
final int unloadingClassIndex = line.indexOf(UNLOADING_CLASS);
323+
int unloadingClassIndex = line.indexOf(UNLOADING_CLASS);
321324
if (unloadingClassIndex > 0) {
322325
beginningOfLine.addFirst(line.substring(0, unloadingClassIndex));
323326
continue;
@@ -328,19 +331,6 @@ else if (isPrintTenuringDistribution(line)) {
328331
beginningOfLine.addFirst(line);
329332
continue;
330333
}
331-
else if (isMixedLine(line, mixedLineMatcher)) {
332-
// if PrintTenuringDistribution is used and a line is mixed,
333-
// beginningOfLine may already contain a value, which must be preserved
334-
String firstPartOfBeginningOfLine = beginningOfLine.pollFirst();
335-
if (firstPartOfBeginningOfLine == null) {
336-
firstPartOfBeginningOfLine = "";
337-
}
338-
beginningOfLine.addFirst(firstPartOfBeginningOfLine + mixedLineMatcher.group(LINES_MIXED_STARTOFLINE_GROUP));
339-
340-
model.add(parseLine(mixedLineMatcher.group(LINES_MIXED_ENDOFLINE_GROUP), parsePosition));
341-
parsePosition.setIndex(0);
342-
continue;
343-
}
344334
else if (line.indexOf(ADAPTIVE_PATTERN) >= 0) {
345335
if (line.indexOf("Times") > 0) {
346336
// -XX:+PrintAdaptiveSizePolicy -XX:-UseAdaptiveSizePolicy
@@ -394,9 +384,23 @@ else if (line.indexOf(HEAP_SIZING_START) >= 0) {
394384
continue;
395385
}
396386

387+
if (isMixedLine(line, mixedLineMatcher)) {
388+
// if PrintTenuringDistribution is used and a line is mixed,
389+
// beginningOfLine may already contain a value, which must be preserved
390+
String firstPartOfBeginningOfLine = beginningOfLine.pollFirst();
391+
if (firstPartOfBeginningOfLine == null) {
392+
firstPartOfBeginningOfLine = "";
393+
}
394+
beginningOfLine.addFirst(firstPartOfBeginningOfLine + mixedLineMatcher.group(LINES_MIXED_STARTOFLINE_GROUP));
395+
396+
model.add(parseLine(mixedLineMatcher.group(LINES_MIXED_ENDOFLINE_GROUP), parsePosition));
397+
parsePosition.setIndex(0);
398+
continue;
399+
}
400+
397401
AbstractGCEvent<?> gcEvent = parseLine(line, parsePosition);
398402

399-
if (lastLineWasScavengeBeforeRemark && !printTenuringDistributionOn) {
403+
if (lastLineWasScavengeBeforeRemark && !printTenuringDistributionOn) {
400404
// according to http://mail.openjdk.java.net/pipermail/hotspot-gc-use/2012-August/001297.html
401405
// the pause time reported for cms-remark includes the scavenge-before-remark time
402406
// so it has to be corrected to show only the time spent in remark event
@@ -424,6 +428,34 @@ else if (line.indexOf(HEAP_SIZING_START) >= 0) {
424428
}
425429
}
426430

431+
private boolean lineHasPrintFlsStatistics(String line) {
432+
return line.endsWith(BEFORE_GC)
433+
|| line.endsWith(AFTER_GC)
434+
|| line.indexOf(CMS_LARGE_BLOCK) > 0
435+
|| line.indexOf(SIZE) > 0;
436+
}
437+
438+
private void handlePrintFlsStatistics(String line, Deque<String> beginningOfLine) {
439+
if (line.endsWith(BEFORE_GC)) {
440+
beginningOfLine.addFirst(line.substring(0, line.indexOf(BEFORE_GC)));
441+
}
442+
else if (line.endsWith(AFTER_GC)) {
443+
String beginning = beginningOfLine.removeFirst();
444+
beginningOfLine.addFirst(beginning + line.substring(0, line.indexOf(AFTER_GC)));
445+
}
446+
else if (line.indexOf(CMS_LARGE_BLOCK) > 0) {
447+
String beginning = beginningOfLine.removeFirst();
448+
beginningOfLine.addFirst(beginning + line.substring(0, line.indexOf(CMS_LARGE_BLOCK)));
449+
}
450+
else if (line.indexOf(SIZE) > 0) {
451+
String beginning = beginningOfLine.removeFirst();
452+
beginningOfLine.addFirst(beginning + line.substring(0, line.indexOf(SIZE)));
453+
}
454+
else {
455+
LOG.warning("line should contain some known PrintFLSStatistics output, which it doesn't (" + line + ")");
456+
}
457+
}
458+
427459
private String filterAwayReferenceGc(String line) {
428460
int lastIndexOfReference = line.lastIndexOf(PRINT_REFERENCE_GC_INDICATOR);
429461
int endOfLastReference = line.indexOf("]", lastIndexOfReference) + 1;

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

Lines changed: 0 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -94,21 +94,6 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun {
9494
private static final String INITIAL_MARK = "(initial-mark)";
9595
private static final String TO_SPACE_OVERFLOW = "(to-space overflow)";
9696

97-
// JDK 8 leading log entries
98-
private static final String LOG_INFORMATION_OPENJDK = "OpenJDK";
99-
private static final String LOG_INFORMATION_HOTSPOT = "Java HotSpot";
100-
private static final String LOG_INFORMATION_MEMORY = "Memory:";
101-
private static final String LOG_INFORMATION_COMMANDLINE_FLAGS = "CommandLine flags:";
102-
103-
private static final List<String> LOG_INFORMATION_STRINGS = new LinkedList<String>();
104-
105-
static {
106-
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_OPENJDK);
107-
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_HOTSPOT);
108-
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_MEMORY);
109-
LOG_INFORMATION_STRINGS.add(LOG_INFORMATION_COMMANDLINE_FLAGS);
110-
}
111-
11297
// G1 log output in 1.6.0_u25 sometimes starts a new line somewhere in line being written
11398
// the pattern is "...)<timestamp>..."
11499
// or "...Full GC<timestamp>..."

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

Lines changed: 13 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -384,8 +384,11 @@ public void cmsPrintFlsStatistics1() throws Exception {
384384
DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_7);
385385
GCModel model = reader.read();
386386

387-
assertThat("GC count", model.size(), is(1));
388-
assertThat("pause", model.get(0).getPause(), closeTo(0.0030039, 0.00000001));
387+
assertThat("GC count", model.size(), is(3));
388+
assertThat("event 1 pause", model.get(0).getPause(), closeTo(0.0030039, 0.00000001));
389+
assertThat("event 2", model.get(1).isConcurrent(), is(true));
390+
assertThat("event 3", model.get(2).isFull(), is(true));
391+
assertThat("event 3 pause", model.get(2).getPause(), closeTo(0.0339164, 0.00000001));
389392
assertThat("number of parse problems", handler.getCount(), is(0));
390393

391394
}
@@ -401,8 +404,14 @@ public void cmsPrintFlsStatistics2() throws Exception {
401404
DataReader reader = new DataReaderSun1_6_0(in, GcLogType.SUN1_7);
402405
GCModel model = reader.read();
403406

404-
assertThat("GC count", model.size(), is(1));
405-
assertThat("pause", model.get(0).getPause(), closeTo(0.0054252, 0.00000001));
407+
assertThat("GC count", model.size(), is(5));
408+
assertThat("event 1 pause", model.get(0).getPause(), closeTo(0.0054252, 0.00000001));
409+
assertThat("event 2", model.get(1).isConcurrent(), is(true));
410+
assertThat("event 3", model.get(2).isFull(), is(true));
411+
assertThat("event 3 pause", model.get(2).getPause(), closeTo(0.0356364, 0.00000001));
412+
assertThat("event 4", model.get(3).isConcurrent(), is(true));
413+
assertThat("event 5", model.get(4).isFull(), is(true));
414+
assertThat("event 5 pause", model.get(4).getPause(), closeTo(0.0264843, 0.00000001));
406415
assertThat("number of parse problems", handler.getCount(), is(0));
407416

408417
}

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

Lines changed: 34 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,4 +28,37 @@ Total Free Space: 0
2828
Max Chunk Size: 0
2929
Number of Blocks: 0
3030
Tree Height: 0
31-
, 0.0030039 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
31+
, 0.0030039 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
32+
2014-10-21T20:58:53.838+0200: 0.545: [GCBefore GC:
33+
Statistics for BinaryTreeDictionary:
34+
------------------------------------
35+
Total Free Space: 22278
36+
Max Chunk Size: 22278
37+
Number of Blocks: 1
38+
Av. Block Size: 22278
39+
Tree Height: 1
40+
Before GC:
41+
Statistics for BinaryTreeDictionary:
42+
------------------------------------
43+
Total Free Space: 0
44+
Max Chunk Size: 0
45+
Number of Blocks: 0
46+
Tree Height: 0
47+
2014-10-21T20:58:53.838+0200: 0.545: [ParNew: 19586K->19586K(19648K), 0.0000205 secs]2014-10-21T20:58:53.838+0200: 0.545: [CMS2014-10-21T20:58:53.838+0200: 0.545: [CMS-concurrent-abortable-preclean: 0.005/0.111 secs] [Times: user=0.23 sys=0.08, real=0.11 secs]
48+
(concurrent mode failure)CMS: Large block 0x00000000f8648448
49+
: 83511K->54817K(84032K), 0.0336464 secs] 103097K->54817K(103680K), [CMS Perm : 2472K->2471K(21248K)]After GC:
50+
Statistics for BinaryTreeDictionary:
51+
------------------------------------
52+
Total Free Space: 5205879
53+
Max Chunk Size: 5205879
54+
Number of Blocks: 1
55+
Av. Block Size: 5205879
56+
Tree Height: 1
57+
After GC:
58+
Statistics for BinaryTreeDictionary:
59+
------------------------------------
60+
Total Free Space: 0
61+
Max Chunk Size: 0
62+
Number of Blocks: 0
63+
Tree Height: 0
64+
, 0.0339164 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]

0 commit comments

Comments
 (0)