From d7ec81b40c44ae596f3fba0a1ce0a6d16c7e9371 Mon Sep 17 00:00:00 2001 From: chewiebug Date: Wed, 1 Aug 2018 16:24:34 +0200 Subject: [PATCH] #200 generalise handling of System.gc() events --- .../perf/gcviewer/imp/DataReaderTools.java | 2 +- .../perf/gcviewer/model/AbstractGCEvent.java | 23 ++++++------ .../gcviewer/imp/TestDataReaderSun1_6_0.java | 2 ++ .../imp/TestDataReaderSun1_6_0G1.java | 2 +- .../imp/TestDataReaderSun1_8_0G1.java | 31 ++++++++++++++++ .../imp/TestDataReaderUJLShenandoah.java | 10 ++++-- .../openjdk/SampleSun1_8_0G1SystemGcYoung.txt | 35 +++++++++++++++++++ ...mpleSun1_8_0G1YoungMetadataGcThreshold.txt | 29 +++++++++++++++ 8 files changed, 118 insertions(+), 16 deletions(-) create mode 100644 src/test/resources/openjdk/SampleSun1_8_0G1SystemGcYoung.txt create mode 100644 src/test/resources/openjdk/SampleSun1_8_0G1YoungMetadataGcThreshold.txt diff --git a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java index 58ef64e3..d84c9f49 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/imp/DataReaderTools.java @@ -13,7 +13,7 @@ */ public class DataReaderTools { - private static Pattern parenthesesPattern = Pattern.compile("\\([^()]*\\) ?"); + private static Pattern parenthesesPattern = Pattern.compile("\\([^)]*(\\))?\\) ?"); private Logger logger; 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 711a7a08..fddb01f9 100644 --- a/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java +++ b/src/main/java/com/tagtraum/perf/gcviewer/model/AbstractGCEvent.java @@ -248,6 +248,14 @@ public boolean isFull() { return false; } + /** + * Returns true, if this event was triggered by a call to "System.gc()" + * @return true if triggered by "System.gc()" + */ + public boolean isSystem() { + return getExtendedType().getName().contains("System"); + } + public boolean isInc() { return getExtendedType().getType() == GCEvent.Type.INC_GC; } @@ -494,9 +502,7 @@ public String toString() { public static final Type SCAVENGE_BEFORE_REMARK = new Type("Scavenge-Before-Remark", Generation.ALL); public static final Type FULL_GC = new Type("Full GC", Generation.ALL); - public static final Type FULL_GC_SYSTEM = new Type("Full GC (System)", Generation.ALL); public static final Type GC = new Type("GC", Generation.YOUNG); - public static final Type GC_SYSTEM = new Type("GC (System.gc())", Generation.YOUNG); public static final Type DEF_NEW = new Type("DefNew", Generation.YOUNG, Concurrency.SERIAL); // single threaded public static final Type PAR_NEW = new Type("ParNew", Generation.YOUNG); // parallel public static final Type ASPAR_NEW = new Type("ASParNew", Generation.YOUNG); // parallel (CMS AdaptiveSizePolicy) @@ -519,11 +525,11 @@ public String toString() { public static final Type CMS_PERM = new Type("CMS Perm", Generation.PERM, Concurrency.SERIAL, GcPattern.GC_MEMORY); // Parnew (promotion failed) - public static final Type PAR_NEW_PROMOTION_FAILED = new Type("ParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL); + public static final Type PAR_NEW_PROMOTION_FAILED = new Type("ParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL); // CMS (concurrent mode failure / interrupted) - public static final Type CMS_CMF = new Type("CMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL); - public static final Type CMS_CMI = new Type("CMS (concurrent mode interrupted)", Generation.TENURED, Concurrency.SERIAL); + public static final Type CMS_CMF = new Type("CMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL); + public static final Type CMS_CMI = new Type("CMS (concurrent mode interrupted)", Generation.TENURED, Concurrency.SERIAL); // CMS (Concurrent Mark Sweep) Event Types public static final Type CMS_CONCURRENT_MARK_START = new Type("CMS-concurrent-mark-start", Generation.TENURED, Concurrency.CONCURRENT, GcPattern.GC); @@ -544,7 +550,7 @@ public String toString() { public static final Type ASCMS = new Type("ASCMS", Generation.TENURED); // Parnew (promotion failed) AdaptiveSizePolicy - public static final Type ASPAR_NEW_PROMOTION_FAILED = new Type("ASParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL); + public static final Type ASPAR_NEW_PROMOTION_FAILED = new Type("ASParNew (promotion failed)", Generation.YOUNG, Concurrency.SERIAL); // CMS (concurrent mode failure / interrupted) AdaptiveSizePolicy public static final Type ASCMS_CMF = new Type("ASCMS (concurrent mode failure)", Generation.TENURED, Concurrency.SERIAL); @@ -564,9 +570,6 @@ public String toString() { public static final Type ASCMS_INITIAL_MARK = new Type("ASCMS-initial-mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_PAUSE, CollectionType.CONCURRENCY_HELPER); public static final Type ASCMS_REMARK = new Type("ASCMS-remark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY, CollectionType.CONCURRENCY_HELPER); - // G1 stop the world types - public static final Type G1_FULL_GC_SYSTEM = new Type("Full GC (System.gc())", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); - // only young collection public static final Type G1_YOUNG = new Type("GC pause (young)", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); public static final Type G1_YOUNG_MARK_STACK_FULL = new Type("GC pause (young)Mark stack is full.", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); @@ -583,7 +586,6 @@ public String toString() { // TODO: Generation: young and tenured! public static final Type G1_YOUNG_INITIAL_MARK = new Type("GC pause (young) (initial-mark)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); - public static final Type G1_YOUNG_INITIAL_MARK_SYSTEM_GC = new Type("GC pause (System.gc()) (young) (initial-mark)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); public static final Type G1_YOUNG_INITIAL_MARK_TO_SPACE_OVERFLOW = new Type("GC pause (young) (to-space overflow) (initial-mark)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); // The following two Types are basically the same but in a different order. In JDK 6 the order was defined, no longer the case with JDK 7 (see: https://github.com/chewiebug/GCViewer/issues/100) public static final Type G1_YOUNG_INITIAL_MARK_TO_SPACE_EXHAUSTED = new Type("GC pause (young) (initial-mark) (to-space exhausted)", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); @@ -612,7 +614,6 @@ public String toString() { // unified jvm logging generic event types public static final Type UJL_PAUSE_YOUNG = new Type("Pause Young", Generation.YOUNG, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); public static final Type UJL_PAUSE_FULL = new Type("Pause Full", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); - public static final Type UJL_PAUSE_FULL_SYSTEM = new Type("Pause Full (System.gc())", Generation.ALL, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE); // unified jvm logging cms / g1 event types public static final Type UJL_PAUSE_INITIAL_MARK = new Type("Pause Initial Mark", Generation.TENURED, Concurrency.SERIAL, GcPattern.GC_MEMORY_PAUSE, CollectionType.CONCURRENCY_HELPER); 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 1a2da0bc..abef124d 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 @@ -127,6 +127,7 @@ public void testCMSFullGcCmsInterrupted() throws Exception { assertEquals("count", 1, model.getPause().getN()); assertEquals("full gc pause", 0.0089351, model.getFullGCPause().getSum(), 0.00000001); + assertThat("is system gc", model.get(0).isSystem(), is(true)); } @Test @@ -493,6 +494,7 @@ public void testAdaptiveSizePolicyFullSystemGc() throws Exception { assertEquals("GC count", 1, model.size()); assertEquals("Full GC pause", 0.0070749, model.getFullGCPause().getMax(), 0.00000001); + assertThat("is system gc", model.get(0).isSystem(), is(true)); } @Test diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0G1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0G1.java index 3dfafab6..9e22da49 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0G1.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_6_0G1.java @@ -91,7 +91,7 @@ public void testG1FullGcSystemGc() throws Exception { assertEquals("count", 1, model.size()); assertEquals("full gc pause", 0.1604955, model.getFullGCPause().getMax(), 0.000001); - + assertThat("is system gc", model.get(0).isSystem(), is(true)); } @Test diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java index ba75e7c7..669bec4a 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderSun1_8_0G1.java @@ -143,4 +143,35 @@ public void extendedRemark() throws Exception { assertThat("number of errors", handler.getCount(), is(0)); assertThat("pause duration", model.get(0).getPause(), closeTo(0.1005220, 0.00000001)); } + + @Test + public void youngInitialMarkSystemGc() throws Exception { + TestLogHandler handler = new TestLogHandler(); + handler.setLevel(Level.WARNING); + GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1SystemGcYoung.txt"); + gcResource.getLogger().addHandler(handler); + + DataReader reader = getDataReader(gcResource); + GCModel model = reader.read(); + + assertThat("number of events", model.size(), is(1)); + assertThat("number of errors", handler.getCount(), is(0)); + assertThat("pause duration", model.get(0).getPause(), closeTo(0.2124664, 0.00000001)); + assertThat("is system gc", model.get(0).isSystem(), is(true)); + } + + @Test + public void youngInitialMarkMetadataThreshold() throws Exception { + TestLogHandler handler = new TestLogHandler(); + handler.setLevel(Level.WARNING); + GCResource gcResource = new GcResourceFile("SampleSun1_8_0G1YoungMetadataGcThreshold.txt"); + gcResource.getLogger().addHandler(handler); + + DataReader reader = getDataReader(gcResource); + GCModel model = reader.read(); + + assertThat("number of events", model.size(), is(1)); + assertThat("number of errors", handler.getCount(), is(0)); + assertThat("pause duration", model.get(0).getPause(), closeTo(0.0229931, 0.00000001)); + } } diff --git a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java index 8c2fa449..242d1c1e 100644 --- a/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java +++ b/src/test/java/com/tagtraum/perf/gcviewer/imp/TestDataReaderUJLShenandoah.java @@ -1,6 +1,7 @@ package com.tagtraum.perf.gcviewer.imp; import static org.hamcrest.Matchers.closeTo; +import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.is; import static org.hamcrest.Matchers.startsWith; import static org.junit.Assert.assertThat; @@ -82,7 +83,8 @@ public void parseDefaultConfiguration() throws Exception { assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5)); GCEvent event = (GCEvent) model.get(0); - assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString())); + assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())")); + assertThat("is system gc", event.isSystem(), is(true)); assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024)); assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024)); assertThat("total heap size", event.getTotal(), is(128 * 1024)); @@ -129,7 +131,8 @@ public void parseSingleSystemGCEvent() throws Exception { assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(5)); GCEvent event = (GCEvent) model.get(0); - assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString())); + assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())")); + assertThat("is system gc", event.isSystem(), is(true)); assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024)); assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024)); assertThat("total heap size", event.getTotal(), is(128 * 1024)); @@ -146,7 +149,8 @@ public void parseSeveralSystemGCEvents() throws Exception { assertThat("amount of concurrent pause types", model.getConcurrentEventPauses().size(), is(0)); GCEvent event = (GCEvent) model.get(0); - assertThat("type", event.getTypeAsString(), is(Type.UJL_PAUSE_FULL_SYSTEM.toString())); + assertThat("type", event.getTypeAsString(), equalTo(Type.UJL_PAUSE_FULL + " (System.gc())")); + assertThat("is system gc", event.isSystem(), is(true)); assertThat("preUsed heap size", event.getPreUsed(), is(10 * 1024)); assertThat("postUsed heap size", event.getPostUsed(), is(1 * 1024)); assertThat("total heap size", event.getTotal(), is(128 * 1024)); diff --git a/src/test/resources/openjdk/SampleSun1_8_0G1SystemGcYoung.txt b/src/test/resources/openjdk/SampleSun1_8_0G1SystemGcYoung.txt new file mode 100644 index 00000000..cc6e4f48 --- /dev/null +++ b/src/test/resources/openjdk/SampleSun1_8_0G1SystemGcYoung.txt @@ -0,0 +1,35 @@ +2661.447: [GC pause (System.gc()) (young) (initial-mark) +Desired survivor size 826277888 bytes, new threshold 15 (max 15) +- age 1: 3836312 bytes, 3836312 total +- age 2: 56044632 bytes, 59880944 total +- age 3: 27522352 bytes, 87403296 total +- age 4: 18308584 bytes, 105711880 total +- age 5: 14670480 bytes, 120382360 total +- age 6: 10051000 bytes, 130433360 total +, 0.2124664 secs] + [Parallel Time: 150.8 ms, GC Workers: 8] + [GC Worker Start (ms): Min: 2661451.7, Avg: 2661451.9, Max: 2661452.2, Diff: 0.5] + [Ext Root Scanning (ms): Min: 5.8, Avg: 7.8, Max: 9.3, Diff: 3.5, Sum: 62.6] + [Update RS (ms): Min: 15.7, Avg: 16.3, Max: 18.4, Diff: 2.7, Sum: 130.1] + [Processed Buffers: Min: 16, Avg: 31.0, Max: 63, Diff: 47, Sum: 248] + [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 1.5] + [Code Root Scanning (ms): Min: 0.0, Avg: 1.5, Max: 2.3, Diff: 2.3, Sum: 12.1] + [Object Copy (ms): Min: 120.9, Avg: 123.0, Max: 124.5, Diff: 3.5, Sum: 984.1] + [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8] + [GC Worker Other (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 2.0] + [GC Worker Total (ms): Min: 148.8, Avg: 149.1, Max: 149.4, Diff: 0.6, Sum: 1192.5] + [GC Worker End (ms): Min: 2661600.8, Avg: 2661601.0, Max: 2661601.1, Diff: 0.3] + [Code Root Fixup: 0.2 ms] + [Code Root Purge: 0.2 ms] + [Clear CT: 2.6 ms] + [Other: 58.7 ms] + [Choose CSet: 0.0 ms] + [Ref Proc: 50.6 ms] + [Ref Enq: 0.6 ms] + [Redirty Cards: 0.9 ms] + [Humongous Register: 0.1 ms] + [Humongous Reclaim: 0.0 ms] + [Free CSet: 2.3 ms] + [Eden: 8944.0M(12.1G)->0.0B(12.1G) Survivors: 144.0M->376.0M Heap: 22.7G(30.0G)->14.2G(30.0G)] + [Times: user=1.13 sys=0.10, real=0.21 secs] diff --git a/src/test/resources/openjdk/SampleSun1_8_0G1YoungMetadataGcThreshold.txt b/src/test/resources/openjdk/SampleSun1_8_0G1YoungMetadataGcThreshold.txt new file mode 100644 index 00000000..15b58217 --- /dev/null +++ b/src/test/resources/openjdk/SampleSun1_8_0G1YoungMetadataGcThreshold.txt @@ -0,0 +1,29 @@ +58.352: [GC pause (Metadata GC Threshold) (young) (initial-mark) +Desired survivor size 50331648 bytes, new threshold 15 (max 15) +, 0.0229931 secs] + [Parallel Time: 17.8 ms, GC Workers: 8] + [GC Worker Start (ms): Min: 58352.7, Avg: 58353.6, Max: 58354.1, Diff: 1.4] + [Ext Root Scanning (ms): Min: 5.2, Avg: 6.2, Max: 7.2, Diff: 2.0, Sum: 49.2] + [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] + [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] + [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] + [Code Root Scanning (ms): Min: 0.0, Avg: 4.6, Max: 10.3, Diff: 10.3, Sum: 36.9] + [Object Copy (ms): Min: 0.0, Avg: 5.2, Max: 9.4, Diff: 9.4, Sum: 41.5] + [Termination (ms): Min: 0.0, Avg: 0.8, Max: 1.1, Diff: 1.1, Sum: 6.3] + [Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9] + [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] + [GC Worker Total (ms): Min: 16.2, Avg: 16.7, Max: 17.7, Diff: 1.5, Sum: 134.0] + [GC Worker End (ms): Min: 58370.3, Avg: 58370.3, Max: 58370.3, Diff: 0.0] + [Code Root Fixup: 0.0 ms] + [Code Root Purge: 0.0 ms] + [Clear CT: 0.7 ms] + [Other: 4.4 ms] + [Choose CSet: 0.0 ms] + [Ref Proc: 3.3 ms] + [Ref Enq: 0.1 ms] + [Redirty Cards: 0.6 ms] + [Humongous Register: 0.0 ms] + [Humongous Reclaim: 0.0 ms] + [Free CSet: 0.1 ms] + [Eden: 264.0M(768.0M)->0.0B(752.0M) Survivors: 0.0B->16.0M Heap: 264.0M(8192.0M)->13.6M(8192.0M)] + [Times: user=0.10 sys=0.00, real=0.03 secs]