RFR: 8148630: Convert TraceStartupTime to Unified Logging

Rachel Protacio rachel.protacio at oracle.com
Thu Feb 11 15:55:34 UTC 2016


On 2/11/2016 1:45 AM, David Holmes wrote:
> Looking in some more detail ...
> 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.
> It is a develop flag, not product. But I don't see the aliasing in the 
> webrev anyway.
Sorry about that, you're absolutely right. I got confused in writing the 
email because of the other change I'm working on right now.
> Looking at the TraceTime destructor:
>        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();
>        }
> TraceTime should not have a hard-wired set of LogTag values, nor 
> should it know the log-level associated with any tags. That 
> information should all be stored in the TraceTime instance when 
> constructed and the logging performed in a generic way based on the 
> stored level and tag.
So there are two problems here. First, because the log_<level> functions 
are macros, you can't just set a variable "tag = LogTag::_startuptime" 
and then do
because the compiler will complain that "tag" is not a valid tag.

The second approach would be to pass in the logging stream to the 
constructor, and then print to that stream, but because the stream 
requires a ResourceMark, I was unable to find a successful way to do 
that. I tried declaring the ResourceMark before the code that 
initializes the TraceTime object, but if it is scoped within a 
log_is_enabled conditional, i.e.

    if (log_is_enabled(startuptime)) {
         ResourceMark rm;
         TraceTime timer("Interpreter generation", log_is_enabled(Info,
    startuptime), LogTag::_startuptime);

then the ResourceMark removes the stream before the destructor is 
called. And if it is not scoped, i.e. just

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

then it messes up the rest of the functions between the TraceTime 
construction and the destruction.

And I was unable to find a way to create a ResourceMark within the 
TraceTime object itself - it would not compile if it was made a member 
of the class, I think what was happening is that it would try to make it 
when loading the .hpp file, but there was no THREAD at that time. And if 
it's not in the .hpp file, then it's not stored in the instance. So I 
agree that it would be better with one of these approaches, but there 
doesn't seem to be a way to do it.

> Thanks,
> David
> -----
>> 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

More information about the hotspot-runtime-dev mailing list