8165292: The gc+task logging is repeated a lot, decreasing the usefulness of -Xlog:gc*=info
authortschatzl
Wed, 07 Sep 2016 09:20:10 +0200
changeset 40922 d9f1eaf18f9a
parent 40921 cc129ac8e609
child 40923 10fe1c28b9f6
child 40924 226073476e18
8165292: The gc+task logging is repeated a lot, decreasing the usefulness of -Xlog:gc*=info Summary: Separate number of workers used debugging information from adaptive worker sizing log messages. Reviewed-by: ehelin, sjohanss, jmasa
hotspot/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp
hotspot/src/share/vm/gc/cms/parNewGeneration.cpp
hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp
hotspot/src/share/vm/gc/g1/g1ConcurrentMark.cpp
hotspot/src/share/vm/gc/shared/workgroup.hpp
hotspot/test/gc/TestNumWorkerOutput.java
--- a/hotspot/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp	Tue Sep 06 22:52:35 2016 +0200
+++ b/hotspot/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp	Wed Sep 07 09:20:10 2016 +0200
@@ -3511,6 +3511,7 @@
                                                                   conc_workers()->active_workers(),
                                                                   Threads::number_of_non_daemon_threads());
   num_workers = conc_workers()->update_active_workers(num_workers);
+  log_info(gc,task)("Using %u workers of %u for marking", num_workers, conc_workers()->total_workers());
 
   CompactibleFreeListSpace* cms_space  = _cmsGen->cmsSpace();
 
--- a/hotspot/src/share/vm/gc/cms/parNewGeneration.cpp	Tue Sep 06 22:52:35 2016 +0200
+++ b/hotspot/src/share/vm/gc/cms/parNewGeneration.cpp	Wed Sep 07 09:20:10 2016 +0200
@@ -899,6 +899,8 @@
                                                workers->active_workers(),
                                                Threads::number_of_non_daemon_threads());
   active_workers = workers->update_active_workers(active_workers);
+  log_info(gc,task)("Using %u workers of %u for evacuation", active_workers, workers->total_workers());
+
   _old_gen = gch->old_gen();
 
   // If the next generation is too full to accommodate worst-case promotion
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Tue Sep 06 22:52:35 2016 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Wed Sep 07 09:20:10 2016 +0200
@@ -1332,6 +1332,7 @@
                                                 workers()->active_workers(),
                                                 Threads::number_of_non_daemon_threads());
       workers()->update_active_workers(n_workers);
+      log_info(gc,task)("Using %u workers of %u to rebuild remembered set", n_workers, workers()->total_workers());
 
       ParRebuildRSTask rebuild_rs_task(this);
       workers()->run_task(&rebuild_rs_task);
@@ -3068,6 +3069,7 @@
                                                                   workers()->active_workers(),
                                                                   Threads::number_of_non_daemon_threads());
     workers()->update_active_workers(active_workers);
+    log_info(gc,task)("Using %u workers of %u for evacuation", active_workers, workers()->total_workers());
 
     TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
     TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
--- a/hotspot/src/share/vm/gc/g1/g1ConcurrentMark.cpp	Tue Sep 06 22:52:35 2016 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1ConcurrentMark.cpp	Wed Sep 07 09:20:10 2016 +0200
@@ -1035,6 +1035,8 @@
   // worker threads may currently exist and more may not be
   // available.
   active_workers = _parallel_workers->update_active_workers(active_workers);
+  log_info(gc, task)("Using %u workers of %u for marking", active_workers, _parallel_workers->total_workers());
+
   // Parallel task terminator is set in "set_concurrency_and_phase()"
   set_concurrency_and_phase(active_workers, true /* concurrent */);
 
--- a/hotspot/src/share/vm/gc/shared/workgroup.hpp	Tue Sep 06 22:52:35 2016 +0200
+++ b/hotspot/src/share/vm/gc/shared/workgroup.hpp	Wed Sep 07 09:20:10 2016 +0200
@@ -162,7 +162,7 @@
     _active_workers = MIN2(v, _total_workers);
     add_workers(false /* exit_on_failure */);
     assert(v != 0, "Trying to set active workers to 0");
-    log_info(gc, task)("GC Workers: using %d out of %d", _active_workers, _total_workers);
+    log_trace(gc, task)("%s: using %d out of %d workers", name(), _active_workers, _total_workers);
     return _active_workers;
   }
 
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/test/gc/TestNumWorkerOutput.java	Wed Sep 07 09:20:10 2016 +0200
@@ -0,0 +1,103 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test TestNumWorkerOutput
+ * @bug 8165292
+ * @summary Check that when PrintGCDetails is enabled, gc,task output is printed only once per collection.
+ * @key gc
+ * @requires vm.gc=="null"
+ * @modules java.base/jdk.internal.misc
+ * @library /test/lib
+ * @build sun.hotspot.WhiteBox
+ * @run main ClassFileInstaller sun.hotspot.WhiteBox
+ * @run main/othervm -XX:+UseConcMarkSweepGC TestNumWorkerOutput UseConcMarkSweepGC
+ * @run main/othervm -XX:+UseG1GC TestNumWorkerOutput UseG1GC
+ */
+
+import sun.hotspot.WhiteBox;
+
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
+
+import jdk.test.lib.Platform;
+import jdk.test.lib.process.OutputAnalyzer;
+import jdk.test.lib.process.ProcessTools;
+
+import static jdk.test.lib.Asserts.*;
+
+public class TestNumWorkerOutput {
+
+    public static void checkPatternOnce(String pattern, String what) throws Exception {
+        Pattern r = Pattern.compile(pattern);
+        Matcher m = r.matcher(what);
+
+        if (!m.find()) {
+            throw new RuntimeException("Could not find pattern " + pattern + " in output");
+        }
+        if (m.find()) {
+            throw new RuntimeException("Could find pattern " + pattern + " in output more than once");
+        }
+    }
+
+    public static void runTest(String gcArg) throws Exception {
+        final String[] arguments = {
+            "-Xbootclasspath/a:.",
+            "-XX:+UnlockExperimentalVMOptions",
+            "-XX:+UnlockDiagnosticVMOptions",
+            "-XX:+WhiteBoxAPI",
+            "-XX:+" + gcArg,
+            "-Xmx10M",
+            "-XX:+PrintGCDetails",
+            GCTest.class.getName()
+            };
+
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder(arguments);
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+
+        output.shouldHaveExitValue(0);
+
+        System.out.println(output.getStdout());
+
+        String stdout = output.getStdout();
+
+        checkPatternOnce(".*[info.*].*[gc,task.*].*GC\\(0\\) .*Using \\d+ workers of \\d+ for evacuation.*", stdout);
+    }
+
+    public static void main(String[] args) throws Exception {
+        runTest(args[0]);
+    }
+
+    static class GCTest {
+        private static final WhiteBox WB = WhiteBox.getWhiteBox();
+
+        public static Object holder;
+
+        public static void main(String [] args) {
+            holder = new byte[100];
+            WB.youngGC();
+            System.out.println(holder);
+        }
+    }
+}
+