Skip to content

Commit ee15cd3

Browse files
chewiebugchewiebug
committed
ignore output of -XX:+PrintStringDeduplicationStatistics for G1 (jdk8)
1 parent eb89b1f commit ee15cd3

File tree

3 files changed

+115
-1
lines changed

3 files changed

+115
-1
lines changed

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

Lines changed: 34 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,7 @@
4747
* <li>-XX:+PrintGCApplicationConcurrentTime (output ignored)</li>
4848
* <li>-XX:+PrintAdaptiveSizePolicy (output ignored)</li>
4949
* <li>-XX:+PrintReferenceGC (output ignored)</li>
50+
* <li>-XX:+PrintStringDeduplicationStatistics (output ignored)</li>
5051
* </ul>
5152
*
5253
* @author <a href="mailto:[email protected]">Joerg Wuethrich</a>
@@ -66,6 +67,7 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun {
6667
private static final String SETTING_ABORT_IN = "Setting abort in CSMarkOopClosure";
6768
private static final String G1_ERGONOMICS = "G1Ergonomics";
6869
private static final String SOFT_REFERENCE = "SoftReference";
70+
private static final String GC_CONCURRENT_STRING_DEDUPLICATION = "GC concurrent-string-deduplication";
6971
private static final List<String> EXCLUDE_STRINGS = new LinkedList<>();
7072

7173
static {
@@ -97,6 +99,34 @@ public class DataReaderSun1_6_0G1 extends AbstractDataReaderSun {
9799
EXCLUDE_STRINGS.add(" [Humongous");
98100
EXCLUDE_STRINGS.add(" [Free CSet");
99101
EXCLUDE_STRINGS.add("/proc/meminfo"); // apple vms seem to print this out in the beginning of the logs
102+
EXCLUDE_STRINGS.add(" [Last Exec:"); // -XX:+PrintStringDeduplicationStatistics ...
103+
EXCLUDE_STRINGS.add(" [Inspected");
104+
EXCLUDE_STRINGS.add(" [Skipped");
105+
EXCLUDE_STRINGS.add(" [Hashed");
106+
EXCLUDE_STRINGS.add(" [Known");
107+
EXCLUDE_STRINGS.add(" [New");
108+
EXCLUDE_STRINGS.add(" [Deduplicated");
109+
EXCLUDE_STRINGS.add(" [Young");
110+
EXCLUDE_STRINGS.add(" [Old");
111+
EXCLUDE_STRINGS.add(" [Total Exec");
112+
EXCLUDE_STRINGS.add(" [Inspected");
113+
EXCLUDE_STRINGS.add(" [Skipped");
114+
EXCLUDE_STRINGS.add(" [Hashed");
115+
EXCLUDE_STRINGS.add(" [Known");
116+
EXCLUDE_STRINGS.add(" [New");
117+
EXCLUDE_STRINGS.add(" [Deduplicated");
118+
EXCLUDE_STRINGS.add(" [Young");
119+
EXCLUDE_STRINGS.add(" [Old");
120+
EXCLUDE_STRINGS.add(" [Table]");
121+
EXCLUDE_STRINGS.add(" [Memory Usage");
122+
EXCLUDE_STRINGS.add(" [Size");
123+
EXCLUDE_STRINGS.add(" [Entries");
124+
EXCLUDE_STRINGS.add(" [Resize Count");
125+
EXCLUDE_STRINGS.add(" [Rehash Count");
126+
EXCLUDE_STRINGS.add(" [Age Threshold");
127+
EXCLUDE_STRINGS.add(" [Queue]");
128+
EXCLUDE_STRINGS.add(" [Dropped"); // ... -XX:+PrintStringDeduplicationStatistics
129+
100130
}
101131

102132
// the following pattern is specific for G1 with -XX:+PrintGCDetails
@@ -147,7 +177,7 @@ public DataReaderSun1_6_0G1(GCResource gcResource, InputStream in, GcLogType gcL
147177

148178
@Override
149179
public GCModel read() throws IOException {
150-
if (getLogger().isLoggable(Level.INFO)) getLogger().info("Reading Sun 1.6.x / 1.7.x G1 format...");
180+
if (getLogger().isLoggable(Level.INFO)) getLogger().info("Reading Sun 1.6.x .. 1.8.x G1 format...");
151181

152182
try (LineNumberReader in = this.in) {
153183
GCModel model = new GCModel();
@@ -172,6 +202,9 @@ public GCModel read() throws IOException {
172202
if (startsWith(line, EXCLUDE_STRINGS, false)) {
173203
continue;
174204
}
205+
else if (line.contains(GC_CONCURRENT_STRING_DEDUPLICATION)) {
206+
continue;
207+
}
175208
else if (line.indexOf(APPLICATION_TIME) > 0) {
176209
continue;
177210
}

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

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@
1414

1515
import com.tagtraum.perf.gcviewer.UnittestHelper;
1616
import com.tagtraum.perf.gcviewer.UnittestHelper.FOLDER;
17+
import com.tagtraum.perf.gcviewer.model.AbstractGCEvent.Type;
1718
import com.tagtraum.perf.gcviewer.model.GCEvent;
1819
import com.tagtraum.perf.gcviewer.model.GCModel;
1920
import com.tagtraum.perf.gcviewer.model.GCResource;
@@ -195,6 +196,20 @@ public void doubleTimeStamp() throws Exception {
195196
assertThat("warnings", handler.getCount(), is(1));
196197
assertThat("log message contains line number", handler.getLogRecords().get(0).getMessage(), containsString("Line"));
197198
assertThat("log message contains log line", handler.getLogRecords().get(0).getMessage(), containsString("176020.306: 176020.306"));
199+
}
200+
201+
@Test
202+
public void ignorePrintStringDeduplicationStatistics() throws Exception {
203+
TestLogHandler handler = new TestLogHandler();
204+
handler.setLevel(Level.WARNING);
205+
GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1StringDeduplication.txt");
206+
gcResource.getLogger().addHandler(handler);
207+
208+
DataReader reader = getDataReader(gcResource);
209+
GCModel model = reader.read();
198210

211+
assertThat("warnings", handler.getCount(), is(0));
212+
assertThat("size", model.size(), is(1));
213+
assertThat("type", model.get(0).getExtendedType().getType(), is(Type.G1_YOUNG));
199214
}
200215
}

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

Lines changed: 66 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,66 @@
1+
2019-07-08 14:47:32 GC log file created /opt/eap/standalone/log/gc.log.1
2+
Java HotSpot(TM) 64-Bit Server VM (25.212-b10) for linux-amd64 JRE (1.8.0_212-b10), built on Apr 1 2019 21:31:50 by "java_re" with gcc 7.3.0
3+
Memory: 4k page, physical 10485760k(9200k free), swap 0k(0k free)
4+
CommandLine flags: -XX:AdaptiveSizePolicyWeight=90 -XX:CICompilerCount=2 -XX:CompressedClassSpaceSize=528482304 -XX:ConcGCThreads=2 -XX:+DisableExplicitGC -XX:+ExitOnOutOfMemoryError -XX:G1HeapRegionSize=4194304 -XX:G1ReservePercent=20 -XX:GCLogFileSize=3145728 -XX:GCTimeRatio=4 -XX:InitialHeapSize=7516192768 -XX:InitiatingHeapOccupancyPercent=50 -XX:MarkStackSize=4194304 -XX:MaxGCPauseMillis=100 -XX:MaxHeapFreeRatio=40 -XX:MaxHeapSize=7516192768 -XX:MaxMetaspaceSize=536870912 -XX:MaxNewSize=4508876800 -XX:MetaspaceSize=100663296 -XX:MinHeapDeltaBytes=4194304 -XX:MinHeapFreeRatio=20 -XX:NativeMemoryTracking=summary -XX:NumberOfGCLogFiles=5 -XX:ParallelGCThreads=6 -XX:+PrintAdaptiveSizePolicy -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintReferenceGC -XX:+PrintStringDeduplicationStatistics -XX:-TraceClassUnloading -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC -XX:+UseGCLogFileRotation -XX:-UseParallelGC -XX:+UseStringDeduplication
5+
2019-07-08T14:47:32.753+0200: 1069.416: [GC concurrent-string-deduplication, 31.4K->7128.0B(24.5K), avg 67.3%, 0.0009256 secs]
6+
[Last Exec: 0.0009256 secs, Idle: 0.7833251 secs, Blocked: 1/0.0043273 secs]
7+
[Inspected: 619]
8+
[Skipped: 0( 0.0%)]
9+
[Hashed: 318( 51.4%)]
10+
[Known: 2( 0.3%)]
11+
[New: 617( 99.7%) 31.4K]
12+
[Deduplicated: 574( 93.0%) 24.5K( 77.8%)]
13+
[Young: 574(100.0%) 24.5K(100.0%)]
14+
[Old: 0( 0.0%) 0.0B( 0.0%)]
15+
[Total Exec: 703/20.1500520 secs, Idle: 703/1045.6280060 secs, Blocked: 446/2.1353791 secs]
16+
[Inspected: 21201416]
17+
[Skipped: 0( 0.0%)]
18+
[Hashed: 11819450( 55.7%)]
19+
[Known: 785625( 3.7%)]
20+
[New: 20415791( 96.3%) 1524.2M]
21+
[Deduplicated: 17196568( 84.2%) 1026.4M( 67.3%)]
22+
[Young: 8732059( 50.8%) 520.9M( 50.7%)]
23+
[Old: 8464509( 49.2%) 505.5M( 49.3%)]
24+
[Table]
25+
[Memory Usage: 68.9M]
26+
[Size: 2097152, Min: 1024, Max: 16777216]
27+
[Entries: 2295576, Load: 109.5%, Cached: 13897, Added: 3402145, Removed: 1106569]
28+
[Resize Count: 11, Shrink Threshold: 1398101(66.7%), Grow Threshold: 4194304(200.0%)]
29+
[Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0x0]
30+
[Age Threshold: 3]
31+
[Queue]
32+
[Dropped: 0]
33+
[GC concurrent-string-deduplication, deleted 0 entries, 0.0000006 secs]
34+
2019-07-08T14:47:33.392+0200: 1070.055: [GC pause (G1 Evacuation Pause) (young) 1070.055: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 20869, predicted base time: 81.84 ms, remaining time: 18.16 ms, target pause time: 100.00 ms]
35+
1070.056: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 84 regions, survivors: 5 regions, predicted young region time: 23.89 ms]
36+
1070.056: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 84 regions, survivors: 5 regions, old: 0 regions, predicted pause time: 105.73 ms, target pause time: 100.00 ms]
37+
2019-07-08T14:47:33.427+0200: 1070.091: [SoftReference, 0 refs, 0.0000813 secs]2019-07-08T14:47:33.427+0200: 1070.091: [WeakReference, 41 refs, 0.0000208 secs]2019-07-08T14:47:33.427+0200: 1070.091: [FinalReference, 319 refs, 0.0010788 secs]2019-07-08T14:47:33.428+0200: 1070.092: [PhantomReference, 0 refs, 6 refs, 0.0000123 secs]2019-07-08T14:47:33.428+0200: 1070.092: [JNI Weak Reference, 0.0239112 secs], 0.1060907 secs]
38+
[Parallel Time: 33.7 ms, GC Workers: 6]
39+
[GC Worker Start (ms): Min: 1070056.4, Avg: 1070056.6, Max: 1070056.7, Diff: 0.3]
40+
[Ext Root Scanning (ms): Min: 8.4, Avg: 10.3, Max: 14.4, Diff: 6.0, Sum: 61.8]
41+
[Update RS (ms): Min: 10.8, Avg: 14.0, Max: 15.3, Diff: 4.4, Sum: 84.0]
42+
[Processed Buffers: Min: 15, Avg: 34.5, Max: 45, Diff: 30, Sum: 207]
43+
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
44+
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
45+
[Object Copy (ms): Min: 7.7, Avg: 8.6, Max: 9.2, Diff: 1.5, Sum: 51.3]
46+
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
47+
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 6]
48+
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.4]
49+
[GC Worker Total (ms): Min: 33.1, Avg: 33.2, Max: 33.3, Diff: 0.3, Sum: 199.0]
50+
[GC Worker End (ms): Min: 1070089.7, Avg: 1070089.8, Max: 1070089.8, Diff: 0.1]
51+
[Code Root Fixup: 0.1 ms]
52+
[Code Root Purge: 0.0 ms]
53+
[String Dedup Fixup: 43.4 ms, GC Workers: 6]
54+
[Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
55+
[Table Fixup (ms): Min: 42.7, Avg: 42.9, Max: 43.1, Diff: 0.4, Sum: 257.3]
56+
[Clear CT: 0.3 ms]
57+
[Other: 28.6 ms]
58+
[Choose CSet: 0.0 ms]
59+
[Ref Proc: 25.8 ms]
60+
[Ref Enq: 0.0 ms]
61+
[Redirty Cards: 0.2 ms]
62+
[Humongous Register: 0.1 ms]
63+
[Humongous Reclaim: 0.1 ms]
64+
[Free CSet: 1.2 ms]
65+
[Eden: 336.0M(336.0M)->0.0B(328.0M) Survivors: 20.0M->28.0M Heap: 3728.6M(7168.0M)->3398.6M(7168.0M)]
66+
[Times: user=0.39 sys=0.10, real=0.11 secs]

0 commit comments

Comments
 (0)