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

[Lois Foltan]

On 4/13/2020 1:40 AM, Ioi Lam wrote:
>
>
> On 4/10/20 3:05 PM, Lois Foltan wrote:
>>
>>> On 4/9/20 8: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.
>>>>
>>>> First the change in compileTask.cpp seems wrong: you should get the 
>>>> timestamp from the specified stream not the tty.
>>>>
>>>> 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 */.
>>>>
>>>> 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. :(
>>>>
>>>
>>> Hi Lois,
>>
>> Hi Ioi,
>>
>> Thanks for the review!
>>
>>>
>>>
>>> LinkResolver::lookup_polymorphic_method()
>>> +  ResourceMark rm(THREAD);
>>>
>>> Is this ResourceMark used only for logging?
>>
>> Yes.  As a matter of fact specifying -XX:+TraceMethodHandles or 
>> -XX:+TraceInvokeDynamic currently on my sample test case results 
>> today in crashes concerning the lack of allocating without a 
>> ResourceMark.
>>
>>>
>>> =================
>>> For code like this in ConstantPool::resolve_constant_at_impl:
>>>
>>>     if (log_is_enabled(Debug, methodhandles, condy)) {
>>>       LogTarget(Debug, methodhandles, condy) lt;
>>>       LogStream ls(lt);
>>>       bootstrap_specifier.print_msg_on(&ls, 
>>> "resolve_constant_at_impl");
>>>     }
>>>
>>> The second set of tags can be avoided by declaring LogTarget(Debug, 
>>> methodhandles, condy) first. There's an example of this style in 
>>> FileMapInfo::log_paths().
>>>
>>>     LogTarget(Debug, methodhandles, condy) lt;
>>>     if (lt.is_enabled()) {
>>>       LogStream ls(lt);
>>>       bootstrap_specifier.print_msg_on(&ls, 
>>> "resolve_constant_at_impl");
>>>     }
>>
>> Fixed, I have changed all checks in this webrev to consistently use 
>> this form of checking if LogTarget is enabled.
>>
>>>
>>> =================
>>>
>>> unpack_method_and_appendix() {
>>>
>>>       if (log_develop_is_enabled(Info, methodhandles)) {
>>>         ResourceMark rm(THREAD);
>>>         LogTarget(Info, methodhandles) lt;
>>>         LogStream ls(lt);
>>>         ls->print_on(.....);
>>>
>>> This can be fixed similarly, if we add a new function to LogTargetImpl:
>>>
>>>    class LogTargetImpl {
>>>      static bool develop_is_enabled() {
>>>        NOT_PRODUCT(return LogImpl<T0, T1, T2, T3, T4, 
>>> GuardTag>::is_level(level));
>>>        PRODUCT_ONLY(return false);
>>>      }
>>>      ...
>>>    }
>>>
>>>       LogTarget(Info, methodhandles) lt;
>>>       if (lt.develop_is_enabled()) {
>>>         ResourceMark rm(THREAD);
>>>         LogStream ls(lt);
>>>         ls->print_on(.....);
>>
>> Fixed. Added the method "develop_is_enabled()" to class 
>> LogTargetImpl.  However my method looks more like this:
>>
>> static bool develop_is_enabled() {
>>   NOT_PRODUCT(return is_enabled();)
>>   PRODUCT_ONLY(return false);
>> }
>>
>>>
>>> =================
>>> void ConstantPoolCacheEntry::set_method_handle_common()
>>>
>>>   LogStreamHandle(Debug, methodhandles, indy) lsh;
>>>   if (log_is_enabled(Debug, methodhandles, indy)) {
>>>
>>> Maybe we should add a new function LogStream::is_enabled so we can:
>>>
>>>   LogStreamHandle(Debug, methodhandles, indy) lsh;
>>>   if (lsh.is_enabled()) {
>>
>> Fixed. Turns out that a LogTargetHandle already has an "is_enabled()" 
>> method.  So I added an "is_enabled()" method to class LogStream to 
>> check if its field, _log_handle, whose type is LogTargetHandle, is 
>> enabled.
>>
>>>
>>>
>>> =================
>>> Not a comment about this patch, but in general, I am not happy with 
>>> the verbosity when a ResourceMark is needed in logging.
>>>
>>> I think the best way to avoid the verbosity would be to use C++ 
>>> lambda expressions (are we allowed??), or (oh gosh!) maybe a macro? 
>>> (Probably in a separate RFE).
>>>
>>>     LOG_WITH_RESOURCE_MARK((Info, methodhandles), THREAD,ls, {
>>>         ls->print_on(.....);
>>>       });
>>
>> Good idea, but will create an RFE for this.

Created https://bugs.openjdk.java.net/browse/JDK-8242589 for this RFE.

>>
>> New webrev at: 
>> http://cr.openjdk.java.net/~lfoltan/bug_jdk8210012.1/webrev/index.html
>>
>
> Hi Lois,
>
> This new version looks good to me.

Thanks again for the review Ioi!
Lois

>
> Thanks
> - Ioi
>
>
>> Thanks,
>> Lois
>>
>>>
>>>
>>> Thanks
>>> - Ioi
>>>
>>>
>>>> Thanks,
>>>> David
>>>>
>>>>> Testing: hs-tier1-5
>>>>>
>>>>> Thanks,
>>>>> Lois
>>>
>>
>