RFR: 8148630: Convert TraceStartupTime to Unified Logging

[David Holmes]

Hi Rachel,

Can we internalize more of this into the TraceTime class - eg instead of:

TraceTime timer("Interpreter generation",
                 log_is_enabled(Info, startuptime),
                 LogTag::_startuptime);

have:

TraceTime timer("Interpreter generation",
                 Info, LogTag::_startuptime);

or even have Info be the default so you can drop that in many cases ?

Thanks,
David


On 11/02/2016 7: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