RFR (M) JDK-8210012: Implement Unified Logging Option for -XX:+TraceMethodHandles and -XX:+TraceInvokeDynamic

[David Holmes]

Hi Lois,

On 11/04/2020 7:55 am, Lois Foltan wrote:
> On 4/9/2020 11:12 PM, David Holmes wrote:
>> Hi Lois,
>>
>> On 10/04/2020 4:42 am, Lois Foltan wrote:
>>> Please review the following change to implement unified logging 
>>> options for -XX:+TraceMethodHandles and -XX:+TraceInvokeDynamic. The 
>>> new options map as follows:
>>>
>>> -XX:+TraceMethodHandles --> -Xlog:methodhandles=info
>>> -XX:+TraceInvokeDynamic -->  -Xlog:methodhandles+indy=debug
>>>
>>> and in addition dynamic constants can now be viewed under their own 
>>> option via -Xlog:methodhandles+condy=debug
>>>
>>> open webrev at: 
>>> http://cr.openjdk.java.net/~lfoltan/bug_jdk8210012.0/webrev/
>>> bug link: https://bugs.openjdk.java.net/browse/JDK-8210012
>>
>> Generally looks good. A couple of things.
> 
> Thanks David for the review!
> 
>>
>> First the change in compileTask.cpp seems wrong: you should get the 
>> timestamp from the specified stream not the tty.
> 
> At first it looked wrong to me as well, but I was receiving an assert 
> about the TimeStamp associated with the outputStream being cleared, (the 
> first assert in TimeStamp::milliseconds).  After investigation it turns 
> out that CompileTask::print_impl() has never been called with any 
> outputStream other than tty.  And 3-or 4 levels up when I call it with a 
> LogStream (which inherits from outputStream and constructs with a 
> default ctor that does not set a time stamp), it seems odd at that point 
> that I have to determine a timestamp, one that does not seem relevant to 
> CompileTask.  What I believe CompileTask wants, and what it seems other 
> calls in the compiler directory use is the time since the vm was 
> started.  See the support for PrintCompilation in 
> compiler/compileBroker.cpp for the use of tty->timestamp() vs. 
> CompileBroker's _time* timestamps.  Thus I think my change to use tty in 
> CompileTask::print_impl() is correct.

So we have an outputStream API for timestamps, but in practice it is 
enabled on a per-instance basis (only the tty?) and we have whole 
subclasses (stringStream, LogStream) that don't support it. Yet we have 
code that claims to generically operate on any outputstream but calls 
timestamp() which may assert if not called on a supporting instance! 
What a mess. :(

We also have two notions of "uptime" in the VM:
- one is the timestamp held within the tty
- the other is os::elapsedTime()  (which is used by UL)

Probably some scope for some cleanup here ... like get rid of timestamp 
from the tty/outputStream as it is barely used and used incorrectly in a 
couple of places. Further, it's main use was consistency across all the 
logging output to the tty, but now very little is logged to the tty so 
we have inconsistencies across different log output anyway.

But not for this RFE.

>>
>> Second the changes to wrap_dynamic_exception seem rather awkward, both 
>> in terms of having to remember what the initial boolean arg represents 
>> at the call site, and more so in the logic to determine which log 
>> stream to use. I was wondering if it might be better to add 
>> wrap_dynamic_exception_for_indy to keep the call sites clean? 
>> Otherwise perhaps document like "true /* indy */" and "false /* not 
>> indy */.
> 
> I would rather not break wrap_dynamic_exception into 2 methods since 
> this is a JVMS behavior to wrap certain exceptions into a 
> BootstrapMethodError for both indy and condy.  So I have instead opted 
> for your suggestion of using comments when calling wrap_dynamic_exception.
> 
> New webrev at: 
> http://cr.openjdk.java.net/~lfoltan/bug_jdk8210012.1/webrev/index.html

Updates look fine.

Thanks,
David

> Thanks,
> Lois
> 
>>
>> For the log stream logic I was assuming there must be a better/simpler 
>> way, but after looking at it in some detail it seems not. :(
>>
>> Thanks,
>> David
>>
>>> Testing: hs-tier1-5
>>>
>>> Thanks,
>>> Lois
>