--- old/src/share/vm/prims/methodHandles.cpp 2016-02-10 16:34:40.633482372 -0500 +++ new/src/share/vm/prims/methodHandles.cpp 2016-02-10 16:34:40.440625277 -0500 @@ -32,6 +32,7 @@ #include "interpreter/interpreter.hpp" #include "interpreter/oopMapCache.hpp" #include "interpreter/linkResolver.hpp" +#include "logging/log.hpp" #include "memory/allocation.inline.hpp" #include "memory/oopFactory.hpp" #include "oops/objArrayOop.inline.hpp" @@ -76,7 +77,9 @@ assert(_adapter_code == NULL, "generate only once"); ResourceMark rm; - TraceTime timer("MethodHandles adapters generation", TraceStartupTime); + TraceTime timer("MethodHandles adapters generation", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); _adapter_code = MethodHandlesAdapterBlob::create(adapter_code_size); if (_adapter_code == NULL) { return false; --- old/src/share/vm/logging/logTag.hpp 2016-02-10 16:34:40.642367847 -0500 +++ new/src/share/vm/logging/logTag.hpp 2016-02-10 16:34:40.498468883 -0500 @@ -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) \ --- old/src/share/vm/runtime/thread.cpp 2016-02-10 16:34:40.631555439 -0500 +++ new/src/share/vm/runtime/thread.cpp 2016-02-10 16:34:40.455462384 -0500 @@ -3326,7 +3326,9 @@ } void Threads::initialize_java_lang_classes(JavaThread* main_thread, TRAPS) { - TraceTime timer("Initialize java.lang classes", TraceStartupTime); + TraceTime timer("Initialize java.lang classes", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); if (EagerXrunInit && Arguments::init_libraries_at_startup()) { create_vm_init_libraries(); @@ -3442,7 +3444,9 @@ HOTSPOT_VM_INIT_BEGIN(); // Timing (must come after argument parsing) - TraceTime timer("Create VM", TraceStartupTime); + TraceTime timer("Create VM", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); // Initialize the os module after parsing the args jint os_init_2_result = os::init_2(); @@ -3527,8 +3531,11 @@ JvmtiExport::transition_pending_onload_raw_monitors(); // Create the VMThread - { TraceTime timer("Start VMThread", TraceStartupTime); - VMThread::create(); + { TraceTime timer("Start VMThread", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); + + VMThread::create(); Thread* vmthread = VMThread::vm_thread(); if (!os::create_thread(vmthread, os::vm_thread)) { --- old/src/share/vm/runtime/timer.cpp 2016-02-10 16:34:40.652589795 -0500 +++ new/src/share/vm/runtime/timer.cpp 2016-02-10 16:34:40.500127609 -0500 @@ -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 @@ -114,14 +114,15 @@ } 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 +130,14 @@ TraceTime::TraceTime(const char* title, elapsedTimer* accumulator, bool doit, - bool verbose) { - _active = doit; - _verbose = 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,8 +148,15 @@ _t.stop(); if (_accum!=NULL) _accum->add(_t); if (_verbose) { - tty->print_cr(", %3.7f secs]", _t.seconds()); - tty->flush(); + 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(); + } } } } --- old/src/share/vm/memory/metaspaceShared.cpp 2016-02-10 16:34:40.641920190 -0500 +++ new/src/share/vm/memory/metaspaceShared.cpp 2016-02-10 16:34:40.470833234 -0500 @@ -771,88 +771,92 @@ // 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); - ResourceMark rm; - char class_list_path_str[JVM_MAXPATHLEN]; - - tty->print_cr("Allocated shared space: " SIZE_FORMAT " bytes at " PTR_FORMAT, - MetaspaceShared::shared_rs()->size(), - p2i(MetaspaceShared::shared_rs()->base())); - - // Preload classes to be shared. - // Should use some os:: method rather than fopen() here. aB. - const char* class_list_path; - if (SharedClassListFile == NULL) { - // Construct the path to the class list (in jre/lib) - // Walk up two directories from the location of the VM and - // optionally tack on "lib" (depending on platform) - os::jvm_path(class_list_path_str, sizeof(class_list_path_str)); - for (int i = 0; i < 3; i++) { - char *end = strrchr(class_list_path_str, *os::file_separator()); - if (end != NULL) *end = '\0'; - } - int class_list_path_len = (int)strlen(class_list_path_str); - if (class_list_path_len >= 3) { - if (strcmp(class_list_path_str + class_list_path_len - 3, "lib") != 0) { - if (class_list_path_len < JVM_MAXPATHLEN - 4) { - jio_snprintf(class_list_path_str + class_list_path_len, - sizeof(class_list_path_str) - class_list_path_len, - "%slib", os::file_separator()); - class_list_path_len += 4; + { ResourceMark rm; + TraceTime timer("Dump Shared Spaces", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); + + char class_list_path_str[JVM_MAXPATHLEN]; + + tty->print_cr("Allocated shared space: " SIZE_FORMAT " bytes at " PTR_FORMAT, + MetaspaceShared::shared_rs()->size(), + p2i(MetaspaceShared::shared_rs()->base())); + + // Preload classes to be shared. + // Should use some os:: method rather than fopen() here. aB. + const char* class_list_path; + if (SharedClassListFile == NULL) { + // Construct the path to the class list (in jre/lib) + // Walk up two directories from the location of the VM and + // optionally tack on "lib" (depending on platform) + os::jvm_path(class_list_path_str, sizeof(class_list_path_str)); + for (int i = 0; i < 3; i++) { + char *end = strrchr(class_list_path_str, *os::file_separator()); + if (end != NULL) *end = '\0'; + } + int class_list_path_len = (int)strlen(class_list_path_str); + if (class_list_path_len >= 3) { + if (strcmp(class_list_path_str + class_list_path_len - 3, "lib") != 0) { + if (class_list_path_len < JVM_MAXPATHLEN - 4) { + jio_snprintf(class_list_path_str + class_list_path_len, + sizeof(class_list_path_str) - class_list_path_len, + "%slib", os::file_separator()); + class_list_path_len += 4; + } } } + if (class_list_path_len < JVM_MAXPATHLEN - 10) { + jio_snprintf(class_list_path_str + class_list_path_len, + sizeof(class_list_path_str) - class_list_path_len, + "%sclasslist", os::file_separator()); + } + class_list_path = class_list_path_str; + } else { + class_list_path = SharedClassListFile; } - if (class_list_path_len < JVM_MAXPATHLEN - 10) { - jio_snprintf(class_list_path_str + class_list_path_len, - sizeof(class_list_path_str) - class_list_path_len, - "%sclasslist", os::file_separator()); - } - class_list_path = class_list_path_str; - } else { - class_list_path = SharedClassListFile; - } - int class_count = 0; - GrowableArray* class_promote_order = new GrowableArray(); + int class_count = 0; + GrowableArray* class_promote_order = new GrowableArray(); - // sun.io.Converters - static const char obj_array_sig[] = "[[Ljava/lang/Object;"; - SymbolTable::new_permanent_symbol(obj_array_sig, THREAD); - - // java.util.HashMap - static const char map_entry_array_sig[] = "[Ljava/util/Map$Entry;"; - SymbolTable::new_permanent_symbol(map_entry_array_sig, THREAD); - - // Need to allocate the op here: - // op.misc_data_space_alloc() will be called during preload_and_dump(). - ClassLoaderData* loader_data = ClassLoaderData::the_null_class_loader_data(); - VM_PopulateDumpSharedSpace op(loader_data, class_promote_order); - - tty->print_cr("Loading classes to share ..."); - _has_error_classes = false; - class_count += preload_and_dump(class_list_path, class_promote_order, - THREAD); - if (ExtraSharedClassListFile) { - class_count += preload_and_dump(ExtraSharedClassListFile, class_promote_order, + // sun.io.Converters + static const char obj_array_sig[] = "[[Ljava/lang/Object;"; + SymbolTable::new_permanent_symbol(obj_array_sig, THREAD); + + // java.util.HashMap + static const char map_entry_array_sig[] = "[Ljava/util/Map$Entry;"; + SymbolTable::new_permanent_symbol(map_entry_array_sig, THREAD); + + // Need to allocate the op here: + // op.misc_data_space_alloc() will be called during preload_and_dump(). + ClassLoaderData* loader_data = ClassLoaderData::the_null_class_loader_data(); + VM_PopulateDumpSharedSpace op(loader_data, class_promote_order); + + tty->print_cr("Loading classes to share ..."); + _has_error_classes = false; + class_count += preload_and_dump(class_list_path, class_promote_order, THREAD); - } - tty->print_cr("Loading classes to share: done."); + if (ExtraSharedClassListFile) { + class_count += preload_and_dump(ExtraSharedClassListFile, class_promote_order, + THREAD); + } + tty->print_cr("Loading classes to share: done."); - if (PrintSharedSpaces) { - tty->print_cr("Shared spaces: preloaded %d classes", class_count); - } + if (PrintSharedSpaces) { + tty->print_cr("Shared spaces: preloaded %d classes", class_count); + } - // Rewrite and link classes - tty->print_cr("Rewriting and linking classes ..."); + // Rewrite and link classes + tty->print_cr("Rewriting and linking classes ..."); - // Link any classes which got missed. This would happen if we have loaded classes that - // were not explicitly specified in the classlist. E.g., if an interface implemented by class K - // fails verification, all other interfaces that were not specified in the classlist but - // are implemented by K are not verified. - link_and_cleanup_shared_classes(CATCH); - tty->print_cr("Rewriting and linking classes: done"); + // Link any classes which got missed. This would happen if we have loaded classes that + // were not explicitly specified in the classlist. E.g., if an interface implemented by class K + // fails verification, all other interfaces that were not specified in the classlist but + // are implemented by K are not verified. + link_and_cleanup_shared_classes(CATCH); + tty->print_cr("Rewriting and linking classes: done"); - VMThread::execute(&op); + 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); --- old/src/share/vm/memory/universe.cpp 2016-02-10 16:34:40.646939013 -0500 +++ new/src/share/vm/memory/universe.cpp 2016-02-10 16:34:40.462903235 -0500 @@ -626,7 +626,9 @@ 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); + + TraceTime timer("Genesis", log_is_enabled(Info, startuptime), LogTag::_startuptime); + JavaClasses::compute_hard_coded_offsets(); jint status = Universe::initialize_heap(); --- old/src/share/vm/interpreter/templateTable.cpp 2016-02-10 16:34:40.684783601 -0500 +++ new/src/share/vm/interpreter/templateTable.cpp 2016-02-10 16:34:40.465540113 -0500 @@ -26,6 +26,7 @@ #include "gc/shared/collectedHeap.hpp" #include "interpreter/interp_masm.hpp" #include "interpreter/templateTable.hpp" +#include "logging/log.hpp" #include "runtime/timer.hpp" @@ -246,7 +247,9 @@ if (_is_initialized) return; // Initialize table - TraceTime timer("TemplateTable initialization", TraceStartupTime); + TraceTime timer("TemplateTable initialization", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); _bs = Universe::heap()->barrier_set(); --- old/src/share/vm/interpreter/cppInterpreter.cpp 2016-02-10 16:34:40.684393116 -0500 +++ new/src/share/vm/interpreter/cppInterpreter.cpp 2016-02-10 16:34:40.471264053 -0500 @@ -27,6 +27,7 @@ #include "interpreter/cppInterpreterGenerator.hpp" #include "interpreter/interpreter.hpp" #include "interpreter/interpreterRuntime.hpp" +#include "logging/log.hpp" #ifdef CC_INTERP @@ -42,7 +43,9 @@ // generate interpreter { ResourceMark rm; - TraceTime timer("Interpreter generation", TraceStartupTime); + TraceTime timer("Interpreter generation", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); int code_size = InterpreterCodeSize; NOT_PRODUCT(code_size *= 4;) // debug uses extra interpreter code space _code = new StubQueue(new InterpreterCodeletInterface, code_size, NULL, --- old/src/share/vm/runtime/timer.hpp 2016-02-10 16:34:40.689204107 -0500 +++ new/src/share/vm/runtime/timer.hpp 2016-02-10 16:34:40.503950339 -0500 @@ -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,20 @@ bool _verbose; // report every timing elapsedTimer _t; // timer elapsedTimer* _accum; // accumulator + LogTagType _tag; // stream to print to + const char* _title; // name of timer + + outputStream* getStream(); 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 --- old/src/share/vm/interpreter/templateInterpreter.cpp 2016-02-10 16:34:40.688329960 -0500 +++ new/src/share/vm/interpreter/templateInterpreter.cpp 2016-02-10 16:34:40.502346534 -0500 @@ -30,6 +30,7 @@ #include "interpreter/templateInterpreter.hpp" #include "interpreter/templateInterpreterGenerator.hpp" #include "interpreter/templateTable.hpp" +#include "logging/log.hpp" #include "memory/resourceArea.hpp" #ifndef CC_INTERP @@ -48,7 +49,9 @@ // generate interpreter { ResourceMark rm; - TraceTime timer("Interpreter generation", TraceStartupTime); + TraceTime timer("Interpreter generation", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); int code_size = InterpreterCodeSize; NOT_PRODUCT(code_size *= 4;) // debug uses extra interpreter code space #if INCLUDE_JVMTI --- old/src/share/vm/runtime/globals.hpp 2016-02-10 16:34:40.684429252 -0500 +++ new/src/share/vm/runtime/globals.hpp 2016-02-10 16:34:40.498464989 -0500 @@ -1487,9 +1487,6 @@ develop(bool, TraceCompiledIC, false, \ "Trace changes of compiled IC") \ \ - develop(bool, TraceStartupTime, false, \ - "Trace setup time") \ - \ develop(bool, TraceProtectionDomainVerification, false, \ "Trace protection domain verification") \ \ --- old/src/share/vm/runtime/stubRoutines.cpp 2016-02-10 16:34:40.694517458 -0500 +++ new/src/share/vm/runtime/stubRoutines.cpp 2016-02-10 16:34:40.507582900 -0500 @@ -25,6 +25,7 @@ #include "precompiled.hpp" #include "asm/codeBuffer.hpp" #include "code/codeCacheExtensions.hpp" +#include "logging/log.hpp" #include "memory/resourceArea.hpp" #include "oops/oop.inline.hpp" #include "runtime/interfaceSupport.hpp" @@ -183,7 +184,9 @@ void StubRoutines::initialize1() { if (_code1 == NULL) { ResourceMark rm; - TraceTime timer("StubRoutines generation 1", TraceStartupTime); + TraceTime timer("StubRoutines generation 1", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); _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 +279,9 @@ void StubRoutines::initialize2() { if (_code2 == NULL) { ResourceMark rm; - TraceTime timer("StubRoutines generation 2", TraceStartupTime); + TraceTime timer("StubRoutines generation 2", + log_is_enabled(Info, startuptime), + LogTag::_startuptime); _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)"); --- /dev/null 2016-02-04 16:00:06.822541092 -0500 +++ new/test/runtime/logging/StartupTimeTest.java 2016-02-10 16:34:41.293276238 -0500 @@ -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 each of 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."); + } + } +}