RFR: 8148630: Convert TraceStartupTime to Unified Logging

[Coleen Phillimore]

David said it was okay too (for now, then deciding how to change 
depending on the other rfe).
Coleen

On 2/17/16 11:22 AM, Rachel Protacio wrote:
> Thank you everyone for the discussion. I'm linking the most updated 
> webrev here: http://cr.openjdk.java.net/~rprotacio/8148630.02/
>
> The only difference from the last one was the removal of the (typo'ed) 
> forward declaration. But as I believe my only self-declared reviewer 
> so far has been Coleen, I still need someone else to 
> review/approve/ask for this-RFE-specific changes that do not apply to 
> David's 8150015 improvement RFE.
>
> Thanks,
> Rachel
>
> On 2/17/2016 4:47 AM, Marcus Larsson wrote:
>>
>>
>> On 02/17/2016 02:39 AM, David Holmes wrote:
>>> 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" ??
>>
>> That variable is used in a switch-case mapping it to a constant 
>> expression. It works fine for a single tag like this, but all 
>> supported tags need to be hard coded in the switch-case. And with tag 
>> combinations it breaks pretty badly.
> Fair point. This can be addressed in the follow-up RFE. It's safe for 
> now since it only gets called from within the code, i.e. can't be 
> broken by the user.
>>
>>>>
>>>>>> 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.
>>
>> Sounds good!
> Fixed in this webrev.
> Rachel
>>
>> Thanks,
>> Marcus
>>
>>>>
>>>> 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
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>
>>>>>>
>>>>>
>>
>