8149991: Convert TraceSafepointCleanupTime to Unified Logging

Converted TraceSafepointCleanupTime to -Xlog:safepointcleanup=info

Reviewed-by: hseigel, mockner, ddmitriev, dholmes, coleenp

hotspot/src/share/vm/logging/logTag.hpp

@@ -73,6 +73,7 @@
   LOG_TAG(region) \
   LOG_TAG(remset) \
   LOG_TAG(safepoint) \
+  LOG_TAG(safepointcleanup) \
   LOG_TAG(scavenge) \
   LOG_TAG(scrub) \
   LOG_TAG(start) \

hotspot/src/share/vm/runtime/arguments.cpp

@@ -405,13 +405,14 @@ static AliasedFlag const aliased_jvm_flags[] = {
 };
 
 static AliasedLoggingFlag const aliased_logging_flags[] = {
+  { "TraceBiasedLocking",        LogLevel::Info,  true,  LogTag::_biasedlocking },
   { "TraceClassLoading",         LogLevel::Info,  true,  LogTag::_classload },
   { "TraceClassPaths",           LogLevel::Info,  true,  LogTag::_classpath },
   { "TraceClassResolution",      LogLevel::Info,  true,  LogTag::_classresolve },
   { "TraceClassUnloading",       LogLevel::Info,  true,  LogTag::_classunload },
   { "TraceExceptions",           LogLevel::Info,  true,  LogTag::_exceptions },
   { "TraceMonitorInflation",     LogLevel::Debug, true,  LogTag::_monitorinflation },
-  { "TraceBiasedLocking",        LogLevel::Info,  true,  LogTag::_biasedlocking },
+  { "TraceSafepointCleanupTime", LogLevel::Info,  true,  LogTag::_safepointcleanup },
   { NULL,                        LogLevel::Off,   false, LogTag::__NO_TAG }
 };
 

hotspot/src/share/vm/runtime/globals.hpp

@@ -2545,10 +2545,6 @@ public:
   LP64_ONLY(range(-1, max_intx/MICROUNITS))                                 \
   NOT_LP64(range(-1, max_intx))                                             \
                                                                             \
-  product(bool, TraceSafepointCleanupTime, false,                           \
-          "Print the break down of clean up tasks performed during "        \
-          "safepoint")                                                      \
-                                                                            \
   product(bool, Inline, true,                                               \
           "Enable inlining")                                                \
                                                                             \

hotspot/src/share/vm/runtime/logTimer.hpp

@@ -28,7 +28,7 @@
 #include "logging/log.hpp"
 #include "runtime/timer.hpp"
 
-// TraceStartupTime is used for tracing the execution time of a block with logging
+// These classes are used for tracing the execution time of a block with logging
 // Usage:
 //  { TraceStartupTime t("block time")
 //    some_code();
@@ -40,4 +40,9 @@ class TraceStartupTime : public TraceTime {
     TraceStartupTime(const char* s) : TraceTime(s, log_is_enabled(Info, startuptime), LogTag::_startuptime) {}
 };
 
+class TraceSafepointTime : public TraceTime {
+  public:
+    TraceSafepointTime(const char* s) : TraceTime(s, log_is_enabled(Info, safepointcleanup), LogTag::_safepointcleanup) {}
+};
+
 #endif // SHARE_VM_RUNTIME_LOG_TIMER_HPP

hotspot/src/share/vm/runtime/safepoint.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 1997, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1997, 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
@@ -44,6 +44,7 @@
 #include "runtime/deoptimization.hpp"
 #include "runtime/frame.inline.hpp"
 #include "runtime/interfaceSupport.hpp"
+#include "runtime/logTimer.hpp"
 #include "runtime/mutexLocker.hpp"
 #include "runtime/orderAccess.inline.hpp"
 #include "runtime/osThread.hpp"
@@ -487,38 +488,38 @@ bool SafepointSynchronize::is_cleanup_needed() {
 // Various cleaning tasks that should be done periodically at safepoints
 void SafepointSynchronize::do_cleanup_tasks() {
   {
-    TraceTime t1("deflating idle monitors", TraceSafepointCleanupTime);
+    TraceSafepointTime t1("deflating idle monitors");
     ObjectSynchronizer::deflate_idle_monitors();
   }
 
   {
-    TraceTime t2("updating inline caches", TraceSafepointCleanupTime);
+    TraceSafepointTime t2("updating inline caches");
     InlineCacheBuffer::update_inline_caches();
   }
   {
-    TraceTime t3("compilation policy safepoint handler", TraceSafepointCleanupTime);
+    TraceSafepointTime t3("compilation policy safepoint handler");
     CompilationPolicy::policy()->do_safepoint_work();
   }
 
   {
-    TraceTime t4("mark nmethods", TraceSafepointCleanupTime);
+    TraceSafepointTime t4("mark nmethods");
     NMethodSweeper::mark_active_nmethods();
   }
 
   if (SymbolTable::needs_rehashing()) {
-    TraceTime t5("rehashing symbol table", TraceSafepointCleanupTime);
+    TraceSafepointTime t5("rehashing symbol table");
     SymbolTable::rehash_table();
   }
 
   if (StringTable::needs_rehashing()) {
-    TraceTime t6("rehashing string table", TraceSafepointCleanupTime);
+    TraceSafepointTime t6("rehashing string table");
     StringTable::rehash_table();
   }
 
   {
     // CMS delays purging the CLDG until the beginning of the next safepoint and to
     // make sure concurrent sweep is done
-    TraceTime t7("purging class loader data graph", TraceSafepointCleanupTime);
+    TraceSafepointTime t7("purging class loader data graph");
     ClassLoaderDataGraph::purge_if_needed();
   }
 }

hotspot/src/share/vm/runtime/timer.cpp

@@ -153,6 +153,9 @@ TraceTime::~TraceTime() {
         case LogTag::_startuptime :
           log_info(startuptime)("%s, %3.7f secs", _title, _t.seconds());
           break;
+        case LogTag::_safepointcleanup :
+          log_info(safepointcleanup)("%s, %3.7f secs", _title, _t.seconds());
+          break;
         case LogTag::__NO_TAG :
        default :
           tty->print_cr("[%s, %3.7f secs]", _title, _t.seconds());

hotspot/test/runtime/logging/SafepointCleanupTest.java

@@ -0,0 +1,79 @@
+/*
+ * 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
+ * @bug 8149991
+ * @summary safepointcleanup=info should have output from the code
+ * @library /testlibrary
+ * @modules java.base/sun.misc
+ *          java.management
+ * @build jdk.test.lib.OutputAnalyzer jdk.test.lib.ProcessTools
+ * @run driver SafepointCleanupTest
+ */
+
+import jdk.test.lib.OutputAnalyzer;
+import jdk.test.lib.ProcessTools;
+
+public class SafepointCleanupTest {
+    static void analyzeOutputOn(ProcessBuilder pb) throws Exception {
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldContain("[safepointcleanup]");
+        output.shouldContain("deflating idle monitors");
+        output.shouldContain("updating inline caches");
+        output.shouldContain("compilation policy safepoint handler");
+        output.shouldContain("mark nmethods");
+        output.shouldContain("purging class loader data graph");
+        output.shouldHaveExitValue(0);
+    }
+
+    static void analyzeOutputOff(ProcessBuilder pb) throws Exception {
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldNotContain("[safepointcleanup]");
+        output.shouldHaveExitValue(0);
+    }
+
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:safepointcleanup=info",
+                                                                  InnerClass.class.getName());
+        analyzeOutputOn(pb);
+
+        pb = ProcessTools.createJavaProcessBuilder("-XX:+TraceSafepointCleanupTime",
+                                                   InnerClass.class.getName());
+        analyzeOutputOn(pb);
+
+        pb = ProcessTools.createJavaProcessBuilder("-Xlog:safepointcleanup=off",
+                                                   InnerClass.class.getName());
+        analyzeOutputOff(pb);
+
+        pb = ProcessTools.createJavaProcessBuilder("-XX:-TraceSafepointCleanupTime",
+                                                   InnerClass.class.getName());
+        analyzeOutputOff(pb);
+    }
+
+    public static class InnerClass {
+        public static void main(String[] args) throws Exception {
+            System.out.println("Safepoint Cleanup test");
+        }
+    }
+}