RFR: 8148630: Convert TraceStartupTime to Unified Logging
David Holmes
david.holmes at oracle.com
Tue Feb 16 21:20:01 UTC 2016
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