RFR: 8148630: Convert TraceStartupTime to Unified Logging

[Rachel Protacio]

Will do.
Rachel


On 2/12/2016 8:40 AM, Vladimir Ivanov wrote:
> Rachel,
>
> While you are in that code, please, add tracing for java.lang.invoke 
> classes:
>
>   void Threads::initialize_jsr292_core_classes(TRAPS) {
> +   TraceTime timer("Initialize java.lang.invoke classes", 
> TraceStartupTime);
> +
>     initialize_class(vmSymbols::java_lang_invoke_MethodHandle(), CHECK);
>     initialize_class(vmSymbols::java_lang_invoke_MemberName(), CHECK);
> initialize_class(vmSymbols::java_lang_invoke_MethodHandleNatives(), 
> CHECK);
>   }
>
> Thanks!
>
> Best regards,
> Vladimir Ivanov
>
> On 2/11/16 12:46 AM, Rachel Protacio wrote:
>> Hello,
>>
>> Please review this fix for
>> https://bugs.openjdk.java.net/browse/JDK-8148630, converting
>> -XX:+TraceStartupTime to -Xlog:startuptime, with the old option aliased
>> to the new logging one since it is product-level.
>>
>> Open webrev: http://cr.openjdk.java.net/~rprotacio/8148630/
>>
>> Contains new jtreg test, and tested using JPRT. Currently running RBT
>> quick and non-colo tests to verify embedded/ARM (testing delayed because
>> of RBT's being down); I'll reply with an update if they don't pass.
>>
>> Note that in memory/metaspaceShared.cpp, I've added curly brackets
>> around the MetaspaceShared::preload_and_dump(TRAPS) code before exit(0)
>> is called because Dmitry noticed that without it, the timer's destructor
>> was not in fact being called, so it wouldn't print out the info.
>>
>> Also, note that I have altered the printing scheme for the TraceTime
>> objects, so that they print the title and time all at once. In the
>> original code, there was often interleaving and therefore potentially
>> misleading output because the title was printed at initialization, and
>> the time printed at destruction. There was no guarantee of order or
>> correlation in the printed output.
>>
>> Original output:
>>
>>     $ java -XX:+TraceStartupTime -version
>>     [Create VM[StubRoutines generation 1, 0.0020992 secs]
>>     [Genesis, 0.0707006 secs]
>>     [TemplateTable initialization, 0.0000252 secs]
>>     [Interpreter generation, 0.0078040 secs]
>>     [StubRoutines generation 2, 0.0016265 secs]
>>     [Start VMThread, 0.0003409 secs]
>>     [Initialize java.lang classes, 0.1160241 secs]
>>     [MethodHandles adapters generation, 0.0003382 secs]
>>     , 0.3457703 secs]
>>     java version "9-internal"
>>     Java(TM) SE Runtime Environment (fastdebug build
>>     9-internal+0-2016-02-03-174035.rprotaci.clean)
>>     Java HotSpot(TM) 64-Bit Server VM (fastdebug build
>>     9-internal+0-2016-02-03-174035.rprotaci.clean, mixed mode)
>>
>> New output:
>>
>>     $ java -Xlog:startuptime -version
>>     [0.017s][info][startuptime] StubRoutines generation 1, 0.0008210 
>> secs
>>     [0.078s][info][startuptime] Genesis, 0.0614780 secs
>>     [0.078s][info][startuptime] TemplateTable initialization, 0.0000223
>> secs
>>     [0.084s][info][startuptime] Interpreter generation, 0.0054339 secs
>>     [0.131s][info][startuptime] StubRoutines generation 2, 0.0015735 
>> secs
>>     [0.132s][info][startuptime] Start VMThread, 0.0003322 secs
>>     [0.189s][info][startuptime] Initialize java.lang classes, 0.0568726
>> secs
>>     [0.217s][info][startuptime] MethodHandles adapters generation,
>>     0.0002843 secs
>>     [0.218s][info][startuptime] Create VM, 0.2115240 secs
>>     java version "9-internal"
>>     Java(TM) SE Runtime Environment (fastdebug build
>>     9-internal+0-2016-02-01-141226.rprotaci.8148630)
>>     Java HotSpot(TM) 64-Bit Server VM (fastdebug build
>>     9-internal+0-2016-02-01-141226.rprotaci.8148630, mixed mode)
>>
>> So the new output for non-TraceStartupTime options looks the same as
>> before, but all the printing is done during destruction.
>>
>> Thank you,
>> Rachel