RFR: 8148630: Convert TraceStartupTime to Unified Logging

David Holmes david.holmes at oracle.com
Wed Feb 17 01:39:47 UTC 2016


I have filed:

https://bugs.openjdk.java.net/browse/JDK-8150015

"Integrate TraceTime with Unified Logging more seamlessly"

I have targeted it to JDK 9, so we need someone to pick this up very soon.

Thanks,
David

On 17/02/2016 7:20 AM, David Holmes wrote:
> On 17/02/2016 5:20 AM, Coleen Phillimore wrote:
>> On 2/16/16 11:23 AM, Marcus Larsson wrote:
>>> Hi,
>>>
>>> On 02/16/2016 05:31 AM, David Holmes wrote:
>>>> On 16/02/2016 8:39 AM, Rachel Protacio wrote:
>>>>> Hi,
>>>>>
>>>>> New changeset: http://cr.openjdk.java.net/~rprotacio/8148630.01/
>>>>
>>>> src/share/vm/runtime/timer.hpp
>>>>
>>>> + class outpuStream;
>>>>
>>>> Typo - so forward declaration is apparently not needed.
>>>>
>>>>> See comments below.
>>>>>
>>>>> On 2/15/2016 2:10 AM, David Holmes wrote:
>>>>>> On 13/02/2016 12:21 AM, Coleen Phillimore wrote:
>>>>>>>
>>>>>>> Hi Rachel, I think this looks like a good approach to minimize the
>>>>>>> intrusion of the timing code, ie. not adding resource marks and
>>>>>>> streams
>>>>>>> around TraceTime constructor.
>>>>>>>
>>>>>>> Maybe David's concern is that there are multiple instances of this
>>>>>>> sort
>>>>>>> of thing.
>>>>>>>
>>>>>>> *-TraceTime timer("StubRoutines generation 1",TraceStartupTime);*
>>>>>>> *+ log_is_enabled(Info, startuptime),*
>>>>>>> *+ LogTag::_startuptime);*
>>>>>>
>>>>>> That was my first observation - looks very verbose and repetitive.
>>>>>>
>>>>>> But my main concern is that TraceTime should not have a hard-wired
>>>>>> set
>>>>>> of LogTag values, nor should it know the log-level associated with
>>>>>> any
>>>>>> of those tags. If we store the tag (which we do) and the level, then
>>>>>> we should be able to use the full UL API (not necessarily the log_xxx
>>>>>> macros) to perform the logging. TraceTime can potentially be used
>>>>>> with
>>>>>> many different "tracing" options, and it should not need to know
>>>>>> about
>>>>>> them all.
>>>>>>
>>>>>>>
>>>>>>> Since there are so many of these, maybe instead introduce a wrapper
>>>>>>> class that inherits from TraceTime, like:
>>>>>>>
>>>>>>> add outputStream* _st; to TraceTime, initialized to tty.
>>>>>>>
>>>>>>> TraceStartupTime : public TraceTime {
>>>>>>>        TraceStartupTime(char* s) : TraceTime(s, log_is_enabled(etc),
>>>>>>> LogTag::_startuptime) {}
>>>>>>>        ~TraceStartupTime() { ResourceMark rm ; _st =
>>>>>>> logstream(startuptime);  } // this will call the TraceTime
>>>>>>> destructor
>>>>>>> next
>>>>>>> };
>>>>>>>
>>>>>>> If this doesn't work, I think you've found the cleanest change.
>>>>>>
>>>>>> A per-tracing-flag subclass just externalizes the hard-wiring of the
>>>>>> known tags and levels. :(
>>>>>>
>>>>>> This is really about modifying TraceTime to work nicely with UL.
>>>>>> TraceStartupTime is simply the first example of the conversion
>>>>>> process.
>>>>>>
>>>>> I appreciate your concerns; the issue with this structure is that the
>>>>> general idea of what we want is a TraceTime object that will be
>>>>> able to
>>>>> print to x logging tag streams at level y, but the UL framework
>>>>> basically doesn't support that in particular. If you look at the code,
>>>>> the UL functions we're calling are all nested macros (compile-time),
>>>>> but
>>>>> a dynamic non-hard-wired timer as you suggest would require run-time
>>>>> substitution of variables into levels and tags. This would require
>>>>> adding a subsystem into the logging framework, circumventing the
>>>>> macros
>>>>> in existence, etc.
>>>>
>>>> As I said a couple of times already I had expected you to dispense
>>>> with the convenience macros and use the "raw" UL API instead. Having
>>>> looked at that it is unclear, due to all template-plus-varargs-magic,
>>>> exactly how this might be achieved. But I can't see why runtime level
>>>> and tag variables should be a problem. I think the API to do what
>>>> I've suggested is buried in the UL framework somewhere, we might just
>>>> need help from a UL expert in digging it out.
>>>>
>>>
>>> Log tags are template arguments, so they need to be constant
>>> expressions and not variables. This makes it a bit tricky to do
>
> I don't really follow this given what is currently proposed already has:
>
>     LogTagType    _tag;       // stream to print to
>
> as a "variable" ??
>
>>> something like this. However, I still think there are better ways to
>>> do this than the current proposal.
>>>
>>> I'm leaning towards a solution similar to what Kim suggested, where
>>> it's not necessary for the timer to have such detailed knowledge of
>>> the logging framework. You could even avoid the unnecessary buffering
>>> happening in the streams by using a function pointer directly to the
>>> appropriate Log::write function, similar to how logStream is
>>> implemented today. Both of these approaches also allows for tag
>>> combinations to be used, which is a limitation of the current proposal
>>> (can only specify a single tag).
>>
>> So I have a proposal.  What Rachel has looks clean in the code (my
>> opinion), and correctly translates the TraceStartupTime to unified
>> logging framework.  You can file a further RFE to implement this more
>> general approach within the framework so that combinations of flags and
>> levels can be used.  That way we can make forward progress on the
>> runtime translation and you can use this flag as an example when the
>> more general framework approach is available.
>
> Agreed. But the typo I pointed out still needed fixing.
>
> David
> -----
>
>> Thanks,
>> Coleen
>>
>>
>>
>>>
>>> Regards,
>>> Marcus
>>>
>>>>> But we don't really need x tags and y levels; all we
>>>>> need is a way to print the TraceStartupTime,
>>>>> TraceSafepointCleanupTime,
>>>>> and maybe 2 other options into the logging streams. So a UL framework
>>>>> addition would be unnecessary. Plus, as we have heard many times from
>>>>> various reviewers, the ideal is having all the logging at "info" level
>>>>> whenever possible, and since that's what we want for these timer
>>>>> options
>>>>> anyway, it's not inappropriate to hard-wire it in.
>>>>
>>>> We'll have to agree to disagree.
>>>>
>>>> Thanks,
>>>> David
>>>>
>>>>>
>>>>> Because some sort of conditional statement is the simplest approach to
>>>>> achieve what we need for all the cases we need it, I've left in the
>>>>> switch statement in the TraceTime destructor. I have, however, added a
>>>>> wrapper class TraceStartupTime in the file runtime/logTimer.hpp, where
>>>>> we'll add the wrapper classes for the other timer logging changes as
>>>>> well. This change addresses the verboseness of the function calls to
>>>>> create the timers. As you can see, the calls are now just
>>>>>      TraceStartupTime s("Genesis");
>>>>>
>>>>>> Thanks,
>>>>>> David
>>>>>>
>>>>>>> Also, the new output is tons better. Why is there a newline after
>>>>>>> this
>>>>>>> in both cases?
>>>>>>>
>>>>>>>     [0.217s][info][startuptime] MethodHandles adapters generation,
>>>>>>>     0.0002843 secs
>>>>>>>
>>>>>>> I don't see it in the code.
>>>>>>>
>>>>>>> Thanks,
>>>>>>> Coleen
>>>>>>>
>>>>> That happened in the email somehow. The actual output does not
>>>>> contain a
>>>>> newline.
>>>>>
>>>>> Thanks,
>>>>> Rachel
>>>>>>> On 2/11/16 10:55 AM, Rachel Protacio wrote:
>>>>>>>> Hi,
>>>>>>>>
>>>>>>>> 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
>>>>>>>>     log_info(tag)(...)
>>>>>>>> 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.
>>>>>>>>
>>>>>>>> Rachel
>>>>>>>>>
>>>>>>>>> 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