8148630: Convert TraceStartupTime to Unified Logging

The former -XX:+TraceStartupTime flag has been converted to the UL option -Xlog:startuptime=info

Reviewed-by: coleenp, dholmes

hotspot/src/share/vm/interpreter/cppInterpreter.cpp

@@ -27,6 +27,7 @@
 #include "interpreter/cppInterpreterGenerator.hpp"
 #include "interpreter/interpreter.hpp"
 #include "interpreter/interpreterRuntime.hpp"
+#include "runtime/logTimer.hpp"
 
 #ifdef CC_INTERP
 
@@ -42,7 +43,7 @@ void CppInterpreter::initialize() {
 
   // generate interpreter
   { ResourceMark rm;
-    TraceTime timer("Interpreter generation", TraceStartupTime);
+    TraceStartupTime timer("Interpreter generation");
     int code_size = InterpreterCodeSize;
     NOT_PRODUCT(code_size *= 4;)  // debug uses extra interpreter code space
     _code = new StubQueue(new InterpreterCodeletInterface, code_size, NULL,

hotspot/src/share/vm/interpreter/templateInterpreter.cpp

@@ -31,6 +31,7 @@
 #include "interpreter/templateInterpreterGenerator.hpp"
 #include "interpreter/templateTable.hpp"
 #include "memory/resourceArea.hpp"
+#include "runtime/logTimer.hpp"
 
 #ifndef CC_INTERP
 
@@ -48,7 +49,7 @@ void TemplateInterpreter::initialize() {
 
   // generate interpreter
   { ResourceMark rm;
-    TraceTime timer("Interpreter generation", TraceStartupTime);
+    TraceStartupTime timer("Interpreter generation");
     int code_size = InterpreterCodeSize;
     NOT_PRODUCT(code_size *= 4;)  // debug uses extra interpreter code space
 #if INCLUDE_JVMTI

hotspot/src/share/vm/interpreter/templateTable.cpp

@@ -26,8 +26,7 @@
 #include "gc/shared/collectedHeap.hpp"
 #include "interpreter/interp_masm.hpp"
 #include "interpreter/templateTable.hpp"
-#include "runtime/timer.hpp"
-
+#include "runtime/logTimer.hpp"
 
 #ifdef CC_INTERP
 
@@ -246,7 +245,7 @@ void TemplateTable::initialize() {
   if (_is_initialized) return;
 
   // Initialize table
-  TraceTime timer("TemplateTable initialization", TraceStartupTime);
+  TraceStartupTime timer("TemplateTable initialization");
 
   _bs = Universe::heap()->barrier_set();
 

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

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2015, 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
@@ -73,6 +73,7 @@
   LOG_TAG(scavenge) \
   LOG_TAG(scrub) \
   LOG_TAG(start) \
+  LOG_TAG(startuptime) \
   LOG_TAG(state) \
   LOG_TAG(stats) \
   LOG_TAG(stringdedup) \

hotspot/src/share/vm/memory/metaspaceShared.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2012, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2012, 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
@@ -40,6 +40,7 @@
 #include "memory/metaspaceShared.hpp"
 #include "oops/objArrayOop.hpp"
 #include "oops/oop.inline.hpp"
+#include "runtime/logTimer.hpp"
 #include "runtime/os.hpp"
 #include "runtime/signature.hpp"
 #include "runtime/vmThread.hpp"
@@ -771,7 +772,7 @@ void MetaspaceShared::prepare_for_dumping() {
 // Preload classes from a list, populate the shared spaces and dump to a
 // file.
 void MetaspaceShared::preload_and_dump(TRAPS) {
-  TraceTime timer("Dump Shared Spaces", TraceStartupTime);
+  { TraceStartupTime timer("Dump Shared Spaces");
     ResourceMark rm;
     char class_list_path_str[JVM_MAXPATHLEN];
 
@@ -853,6 +854,7 @@ void MetaspaceShared::preload_and_dump(TRAPS) {
     tty->print_cr("Rewriting and linking classes: done");
 
     VMThread::execute(&op);
+  }
   // Since various initialization steps have been undone by this process,
   // it is not reasonable to continue running a java process.
   exit(0);

hotspot/src/share/vm/memory/universe.cpp

@@ -64,6 +64,7 @@
 #include "runtime/init.hpp"
 #include "runtime/java.hpp"
 #include "runtime/javaCalls.hpp"
+#include "runtime/logTimer.hpp"
 #include "runtime/sharedRuntime.hpp"
 #include "runtime/synchronizer.hpp"
 #include "runtime/thread.inline.hpp"
@@ -626,7 +627,9 @@ jint universe_init() {
   guarantee(sizeof(oop) >= sizeof(HeapWord), "HeapWord larger than oop?");
   guarantee(sizeof(oop) % sizeof(HeapWord) == 0,
             "oop size is not not a multiple of HeapWord size");
-  TraceTime timer("Genesis", TraceStartupTime);
+
+  TraceStartupTime timer("Genesis");
+
   JavaClasses::compute_hard_coded_offsets();
 
   jint status = Universe::initialize_heap();

hotspot/src/share/vm/prims/methodHandles.cpp

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2008, 2015, Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 2008, 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
@@ -40,6 +40,7 @@
 #include "prims/jvmtiRedefineClassesTrace.hpp"
 #include "runtime/compilationPolicy.hpp"
 #include "runtime/javaCalls.hpp"
+#include "runtime/logTimer.hpp"
 #include "runtime/reflection.hpp"
 #include "runtime/signature.hpp"
 #include "runtime/stubRoutines.hpp"
@@ -76,7 +77,7 @@ bool MethodHandles::generate_adapters() {
   assert(_adapter_code == NULL, "generate only once");
 
   ResourceMark rm;
-  TraceTime timer("MethodHandles adapters generation", TraceStartupTime);
+  TraceStartupTime timer("MethodHandles adapters generation");
   _adapter_code = MethodHandlesAdapterBlob::create(adapter_code_size);
   if (_adapter_code == NULL) {
      return false;

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

@@ -1482,9 +1482,6 @@ public:
   develop(bool, TraceCompiledIC, false,                                     \
           "Trace changes of compiled IC")                                   \
                                                                             \
-  develop(bool, TraceStartupTime, false,                                    \
-          "Trace setup time")                                               \
-                                                                            \
   develop(bool, TraceProtectionDomainVerification, false,                   \
           "Trace protection domain verification")                           \
                                                                             \

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

@@ -0,0 +1,43 @@
+/*
+ * 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.
+ *
+ */
+
+#ifndef SHARE_VM_RUNTIME_LOG_TIMER_HPP
+#define SHARE_VM_RUNTIME_LOG_TIMER_HPP
+
+#include "logging/log.hpp"
+#include "runtime/timer.hpp"
+
+// TraceStartupTime is used for tracing the execution time of a block with logging
+// Usage:
+//  { TraceStartupTime t("block time")
+//    some_code();
+//  }
+//
+
+class TraceStartupTime : public TraceTime {
+  public:
+    TraceStartupTime(const char* s) : TraceTime(s, log_is_enabled(Info, startuptime), LogTag::_startuptime) {}
+};
+
+#endif // SHARE_VM_RUNTIME_LOG_TIMER_HPP

hotspot/src/share/vm/runtime/stubRoutines.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
@@ -28,9 +28,9 @@
 #include "memory/resourceArea.hpp"
 #include "oops/oop.inline.hpp"
 #include "runtime/interfaceSupport.hpp"
+#include "runtime/logTimer.hpp"
 #include "runtime/sharedRuntime.hpp"
 #include "runtime/stubRoutines.hpp"
-#include "runtime/timer.hpp"
 #include "utilities/copy.hpp"
 #ifdef COMPILER2
 #include "opto/runtime.hpp"
@@ -183,7 +183,7 @@ extern void StubGenerator_generate(CodeBuffer* code, bool all); // only interfac
 void StubRoutines::initialize1() {
   if (_code1 == NULL) {
     ResourceMark rm;
-    TraceTime timer("StubRoutines generation 1", TraceStartupTime);
+    TraceStartupTime timer("StubRoutines generation 1");
     _code1 = BufferBlob::create("StubRoutines (1)", code_size1);
     if (_code1 == NULL) {
       vm_exit_out_of_memory(code_size1, OOM_MALLOC_ERROR, "CodeCache: no room for StubRoutines (1)");
@@ -276,7 +276,7 @@ static void test_safefetchN() {
 void StubRoutines::initialize2() {
   if (_code2 == NULL) {
     ResourceMark rm;
-    TraceTime timer("StubRoutines generation 2", TraceStartupTime);
+    TraceStartupTime timer("StubRoutines generation 2");
     _code2 = BufferBlob::create("StubRoutines (2)", code_size2);
     if (_code2 == NULL) {
       vm_exit_out_of_memory(code_size2, OOM_MALLOC_ERROR, "CodeCache: no room for StubRoutines (2)");

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

@@ -67,6 +67,7 @@
 #include "runtime/java.hpp"
 #include "runtime/javaCalls.hpp"
 #include "runtime/jniPeriodicChecker.hpp"
+#include "runtime/logTimer.hpp"
 #include "runtime/memprofiler.hpp"
 #include "runtime/mutexLocker.hpp"
 #include "runtime/objectMonitor.hpp"
@@ -3341,7 +3342,7 @@ void Threads::threads_do(ThreadClosure* tc) {
 }
 
 void Threads::initialize_java_lang_classes(JavaThread* main_thread, TRAPS) {
-  TraceTime timer("Initialize java.lang classes", TraceStartupTime);
+  TraceStartupTime timer("Initialize java.lang classes");
 
   if (EagerXrunInit && Arguments::init_libraries_at_startup()) {
     create_vm_init_libraries();
@@ -3388,6 +3389,8 @@ void Threads::initialize_java_lang_classes(JavaThread* main_thread, TRAPS) {
 }
 
 void Threads::initialize_jsr292_core_classes(TRAPS) {
+  TraceStartupTime timer("Initialize java.lang.invoke classes");
+
   initialize_class(vmSymbols::java_lang_invoke_MethodHandle(), CHECK);
   initialize_class(vmSymbols::java_lang_invoke_MemberName(), CHECK);
   initialize_class(vmSymbols::java_lang_invoke_MethodHandleNatives(), CHECK);
@@ -3457,7 +3460,7 @@ jint Threads::create_vm(JavaVMInitArgs* args, bool* canTryAgain) {
   HOTSPOT_VM_INIT_BEGIN();
 
   // Timing (must come after argument parsing)
-  TraceTime timer("Create VM", TraceStartupTime);
+  TraceStartupTime timer("Create VM");
 
   // Initialize the os module after parsing the args
   jint os_init_2_result = os::init_2();
@@ -3542,7 +3545,8 @@ jint Threads::create_vm(JavaVMInitArgs* args, bool* canTryAgain) {
   JvmtiExport::transition_pending_onload_raw_monitors();
 
   // Create the VMThread
-  { TraceTime timer("Start VMThread", TraceStartupTime);
+  { TraceStartupTime timer("Start VMThread");
+
   VMThread::create();
     Thread* vmthread = VMThread::vm_thread();
 

hotspot/src/share/vm/runtime/timer.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
@@ -23,6 +23,7 @@
  */
 
 #include "precompiled.hpp"
+#include "logging/log.hpp"
 #include "oops/oop.inline.hpp"
 #include "runtime/timer.hpp"
 #include "utilities/ostream.hpp"
@@ -114,14 +115,15 @@ jlong TimeStamp::ticks_since_update() const {
 }
 
 TraceTime::TraceTime(const char* title,
-                     bool doit) {
+                     bool doit,
+                     LogTagType tag) {
   _active   = doit;
   _verbose  = true;
+  _tag      = tag;
+  _title    = title;
 
   if (_active) {
     _accum = NULL;
-    tty->print("[%s", title);
-    tty->flush();
     _t.start();
   }
 }
@@ -129,14 +131,14 @@ TraceTime::TraceTime(const char* title,
 TraceTime::TraceTime(const char* title,
                      elapsedTimer* accumulator,
                      bool doit,
-                     bool verbose) {
+                     bool verbose,
+                     LogTagType tag) {
   _active   = doit;
   _verbose  = verbose;
+  _tag      = tag;
+  _title    = title;
+
   if (_active) {
-    if (_verbose) {
-      tty->print("[%s", title);
-      tty->flush();
-    }
     _accum = accumulator;
     _t.start();
   }
@@ -147,11 +149,18 @@ TraceTime::~TraceTime() {
     _t.stop();
     if (_accum!=NULL) _accum->add(_t);
     if (_verbose) {
-      tty->print_cr(", %3.7f secs]", _t.seconds());
+      switch (_tag) {
+        case LogTag::_startuptime :
+          log_info(startuptime)("%s, %3.7f secs", _title, _t.seconds());
+          break;
+        case LogTag::__NO_TAG :
+       default :
+          tty->print_cr("[%s, %3.7f secs]", _title, _t.seconds());
           tty->flush();
       }
     }
   }
+}
 
 TraceCPUTime::TraceCPUTime(bool doit,
                bool print_cr,

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

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 1997, 2013, 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
@@ -25,6 +25,7 @@
 #ifndef SHARE_VM_RUNTIME_TIMER_HPP
 #define SHARE_VM_RUNTIME_TIMER_HPP
 
+#include "logging/logTag.hpp"
 #include "utilities/globalDefinitions.hpp"
 
 // Timers for simple measurement.
@@ -85,14 +86,19 @@ class TraceTime: public StackObj {
   bool          _verbose;   // report every timing
   elapsedTimer  _t;         // timer
   elapsedTimer* _accum;     // accumulator
+  const char*   _title;     // name of timer
+  LogTagType    _tag;       // stream to print to
+
  public:
   // Constructors
   TraceTime(const char* title,
-            bool doit = true);
+            bool doit = true,
+            LogTagType tag = LogTag::__NO_TAG);
   TraceTime(const char* title,
             elapsedTimer* accumulator,
             bool doit = true,
-            bool verbose = false);
+            bool verbose = false,
+            LogTagType tag = LogTag::__NO_TAG);
   ~TraceTime();
 
   // Accessors

hotspot/test/runtime/logging/StartupTimeTest.java

@@ -0,0 +1,68 @@
+/*
+ * Copyright (c) 2015, 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 8148630
+ * @summary -Xlog:startuptime should produce logging from the source code
+ * @library /testlibrary
+ * @modules java.base/sun.misc
+ *          java.management
+ * @build jdk.test.lib.OutputAnalyzer jdk.test.lib.ProcessTools
+ * @run driver StartupTimeTest
+ */
+
+import jdk.test.lib.OutputAnalyzer;
+import jdk.test.lib.ProcessTools;
+
+public class StartupTimeTest {
+    static void analyzeOutputOn(ProcessBuilder pb) throws Exception {
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldMatch("(Genesis, [0-9]+.[0-9]+ secs)");
+        output.shouldMatch("(Start VMThread, [0-9]+.[0-9]+ secs)");
+        output.shouldMatch("(Create VM, [0-9]+.[0-9]+ secs)");
+        output.shouldHaveExitValue(0);
+    }
+
+    static void analyzeOutputOff(ProcessBuilder pb) throws Exception {
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldNotContain("[startuptime]");
+        output.shouldHaveExitValue(0);
+    }
+
+    public static void main(String[] args) throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-Xlog:startuptime",
+                                                                  InnerClass.class.getName());
+        analyzeOutputOn(pb);
+
+        pb = ProcessTools.createJavaProcessBuilder("-Xlog:startuptime=off",
+                                                   InnerClass.class.getName());
+        analyzeOutputOff(pb);
+    }
+
+    public static class InnerClass {
+        public static void main(String[] args) throws Exception {
+            System.out.println("Testing startuptime.");
+        }
+    }
+}