Skip to content

Commit

Permalink
reduce number of WARNING messages when parsing introduction of a deta…
Browse files Browse the repository at this point in the history 
…iled G1 message fails (#128)

filter detail lines, that are not recognised as being part of a G1 detailed event information
e.g.
   [Parallel Time: 22.1 ms, GC Workers: 10]
      [GC Worker Start (ms): Min: 5147.0, Avg: 5147.4, Max: 5147.8, Diff: 0.8]
      [Ext Root Scanning (ms): Min: 3.8, Avg: 4.5, Max: 5.2, Diff: 1.4, Sum: 44.7]
  • Loading branch information
@chewiebug
chewiebug committed May 13, 2015
1 parent 42712b6 commit 72f0c8a
Show file tree
Hide file tree
Showing 3 changed files with 80 additions and 19 deletions.
20 changes: 20 additions & 0 deletions src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderSun1_6_0G1.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -77,6 +77,26 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun {
EXCLUDE_STRINGS.add(SURVIVOR_AGE);
EXCLUDE_STRINGS.add(MARK_STACK_IS_FULL);
EXCLUDE_STRINGS.add(SETTING_ABORT_IN);
EXCLUDE_STRINGS.add(" [Root Region"); // all the details of a G1 event -> filter away, if parsing of introduction was not possible
EXCLUDE_STRINGS.add(" [Parallel Time");
EXCLUDE_STRINGS.add(" [GC Worker Start");
EXCLUDE_STRINGS.add(" [Ext Root Scanning");
EXCLUDE_STRINGS.add(" [SATB Filtering");
EXCLUDE_STRINGS.add(" [Update RS");
EXCLUDE_STRINGS.add(" [Processed Buffers");
EXCLUDE_STRINGS.add(" [Scan RS");
EXCLUDE_STRINGS.add(" [Code Root Scanning");
EXCLUDE_STRINGS.add(" [Object Copy");
EXCLUDE_STRINGS.add(" [Termination");
EXCLUDE_STRINGS.add(" [GC Worker");
EXCLUDE_STRINGS.add(" [Code Root");
EXCLUDE_STRINGS.add(" [Clear");
EXCLUDE_STRINGS.add(" [Other:");
EXCLUDE_STRINGS.add(" [Choose CSet");
EXCLUDE_STRINGS.add(" [Ref ");
EXCLUDE_STRINGS.add(" [Redirty Cards");
EXCLUDE_STRINGS.add(" [Humongous Reclaim");
EXCLUDE_STRINGS.add(" [Free CSet");
}

// the following pattern is specific for G1 with -XX:+PrintGCDetails
Expand Down
50 changes: 31 additions & 19 deletions src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,8 @@
import com.tagtraum.perf.gcviewer.model.GCModel;

/**
* Test logs generated specifically by JDK 1.8 G1 algorithm.
*
* Test logs generated specifically by JDK 1.8 G1 algorithm.
*
* @author <a href="mailto:[email protected]">Joerg Wuethrich</a>
* <p>created on: 22.07.2014</p>
*/
Expand All @@ -41,17 +41,17 @@ public void fullConcurrentCycle() throws Exception {

DataReader reader = getDataReader("SampleSun1_8_0G1_ConcurrentCycle.txt");
GCModel model = reader.read();

assertThat("size", model.size(), is(10));

assertThat("tenured size after concurrent cycle", model.getPostConcurrentCycleTenuredUsedSizes().getMax(), is(31949 - 10*1024 - 3072));
assertThat("heap size after concurrent cycle", model.getPostConcurrentCycleHeapUsedSizes().getMax(), is(31949));

assertThat("initiatingOccupancyFraction", model.getCmsInitiatingOccupancyFraction().getMax(), closeTo(0.69, 0.001));

assertThat("number of errors", handler.getCount(), is(0));
}

/**
* In java 8, suddenly the full gc events in G1 got detailed information about the generation
* sizes again. Test, that they are parsed correctly.
Expand All @@ -68,7 +68,7 @@ public void fullGcWithDetailedSizes() throws Exception {
+ "\n [Eden: 4096.0K(532.0M)->0.0B(612.0M) Survivors: 80.0M->0.0B Heap: 5811.9M(12.0G)->3097.8M(12.0G)], [Metaspace: 95902K->95450K(1140736K)]"
+ "\n [Times: user=12.34 sys=0.22, real=8.99 secs]")
.getBytes());

DataReader reader = new DataReaderSun1_6_0G1(in, GcLogType.SUN1_8);
GCModel model = reader.read();

Expand All @@ -77,9 +77,9 @@ public void fullGcWithDetailedSizes() throws Exception {
assertThat("yound before", event.getYoung().getPreUsed(), is(4096 + 80*1024));
assertThat("tenured", event.getTenured().getTotal(), is(12*1024*1024 - 612*1024));
assertThat("metaspace", event.getPerm().getTotal(), is(1140736));

assertThat("perm", model.getPermAllocatedSizes().getN(), is(1));

assertThat("warning count", handler.getCount(), is(0));
}

Expand All @@ -89,29 +89,41 @@ public void printGCCauseTenuringDistribution() throws Exception {
handler.setLevel(Level.WARNING);
IMP_LOGGER.addHandler(handler);
DATA_READER_FACTORY_LOGGER.addHandler(handler);

DataReader reader = getDataReader("SampleSun1_8_0G1PrintGCCausePrintTenuringDistribution.txt");
GCModel model = reader.read();

assertEquals("gc pause sum", 16.7578613, model.getPause().getSum(), 0.000000001);

assertEquals("number of errors", 0, handler.getCount());
}

@Test
public void printHeapAtGC() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
IMP_LOGGER.addHandler(handler);
DATA_READER_FACTORY_LOGGER.addHandler(handler);

DataReader reader = getDataReader("SampleSun1_8_0G1PrintHeapAtGc.txt");
GCModel model = reader.read();

assertEquals("gc pause sum", 0.0055924, model.getPause().getSum(), 0.000000001);

assertEquals("number of errors", 0, handler.getCount());
}



@Test
public void humongousMixed() throws Exception {
TestLogHandler handler = new TestLogHandler();
handler.setLevel(Level.WARNING);
IMP_LOGGER.addHandler(handler);
DATA_READER_FACTORY_LOGGER.addHandler(handler);

DataReader reader = getDataReader("SampleSun1_8_0G1HumongousMixed.txt");
GCModel model = reader.read();

assertThat("number of events", model.size(), is(1));
assertThat("number of errors", handler.getCount(), is(2));
}
}
29 changes: 29 additions & 0 deletions src/test/resources/openjdk/SampleSun1_8_0G1HumongousMixed.txt
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,29 @@
2015-05-01T11:26:29.687+0200: 160770.873: [GC pause (G1 Humongous Allocation) (young)2015-05-01T11:26:29.701+0200: 160770.887: [GC concurrent-root-region-scan-end, 0.0157002 secs]
2015-05-01T11:26:29.701+0200: 160770.887: [GC concurrent-mark-start]
, 0.0470136 secs]
[Root Region Scan Waiting: 14.6 ms]
[Parallel Time: 23.4 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 160770887.8, Avg: 160770887.9, Max: 160770888.0, Diff: 0.2]
[Ext Root Scanning (ms): Min: 0.2, Avg: 0.4, Max: 0.9, Diff: 0.7, Sum: 3.8]
[SATB Filtering (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): Min: 8.5, Avg: 12.3, Max: 13.9, Diff: 5.4, Sum: 122.8]
[Processed Buffers: Min: 3, Avg: 15.8, Max: 25, Diff: 22, Sum: 158]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 7.1, Avg: 8.9, Max: 12.6, Diff: 5.5, Sum: 89.2]
[Termination (ms): Min: 0.0, Avg: 1.0, Max: 1.1, Diff: 1.1, Sum: 10.0]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 22.6, Avg: 22.6, Max: 22.8, Diff: 0.2, Sum: 226.4]
[GC Worker End (ms): Min: 160770910.5, Avg: 160770910.5, Max: 160770910.5, Diff: 0.0]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.7 ms]
[Other: 8.1 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 6.7 ms]
[Ref Enq: 0.5 ms]
[Redirty Cards: 0.5 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 16.0M(1552.0M)->0.0B(1536.0M) Survivors: 80.0M->96.0M Heap: 29.9G(32.0G)->29.9G(32.0G)]
[Times: user=0.26 sys=0.00, real=0.05 secs]

0 comments on commit 72f0c8a

Please sign in to comment.