RFR(XS): 8202415: Incorrect time logged for monitor deflation

[Daniel D. Daugherty]

On 11/27/18 4:42 PM, David Holmes wrote:
> Hi Dan,
>
> Updated webrev looks good - thanks.

Thanks for catching the bug!!


> Only nit - for seperate RFE - is that it doesn't make much sense 
> reporting these times in seconds when all the action is down at the 
> nano-/micro- second level.

Agreed that this should be re-examined at some point. The new logging
for deflating per-thread idle monitors is matching the existing logging
for deflating global idle monitors. I suspect it was done that way
because of limitations of elapsedTimer...

Thanks for the re-review.

Dan


>
> Thanks,
> David
>
> On 28/11/2018 2:51 am, Daniel D. Daugherty wrote:
>> Running the logging option on a simple Hello.java:
>>
>> $ jr -Xlog:safepoint+cleanup=info Hello | grep deflating
>> [0.112s][info][safepoint,cleanup] deflating global idle monitors, 
>> 0.0000002 secs
>> [0.112s][info][safepoint,cleanup] deflating per-thread idle monitors, 
>> 0.0000028 secs
>> [0.119s][info][safepoint,cleanup] deflating global idle monitors, 
>> 0.0000002 secs
>> [0.119s][info][safepoint,cleanup] deflating per-thread idle monitors, 
>> 0.0000016 secs
>> [0.128s][info][safepoint,cleanup] deflating global idle monitors, 
>> 0.0000001 secs
>> [0.128s][info][safepoint,cleanup] deflating per-thread idle monitors, 
>> 0.0000016 secs
>>
>> Dan
>>
>> On 11/27/18 10:28 AM, Daniel D. Daugherty wrote:
>>> Greetings,
>>>
>>> I re-reviewed my webrev and verified that the only line that I messed
>>> up is the one that David spotted. Thanks for the catch!
>>>
>>> Full webrev against jdk/jdk:
>>>
>>> http://cr.openjdk.java.net/~dcubed/8202415-webrev/1_for_jdk_jdk.full/
>>>
>>> Incremental webrev:
>>>
>>> http://cr.openjdk.java.net/~dcubed/8202415-webrev/1_for_jdk_jdk.inc/
>>>
>>> Sanity check build and retest is in process.
>>>
>>> Thanks, in advance, for any comments, questions or suggestions.
>>>
>>> Dan
>>>
>>> On 11/27/18 9:16 AM, Daniel D. Daugherty wrote:
>>>> Hi David,
>>>>
>>>> Thanks for the review!More below.
>>>>
>>>> On 11/26/18 11:04 PM, David Holmes wrote:
>>>>> Hi Dan,
>>>>>
>>>>> On 27/11/2018 5:36 am, Daniel D. Daugherty wrote:
>>>>>> Greetings,
>>>>>>
>>>>>> I have an extra small fix for the following bug:
>>>>>>
>>>>>>      JDK-8202415 Incorrect time logged for monitor deflation
>>>>>>      https://bugs.openjdk.java.net/browse/JDK-8202415
>>>>>>
>>>>>> Here's the webrev URL:
>>>>>>
>>>>>> http://cr.openjdk.java.net/~dcubed/8202415-webrev/0_for_jdk_jdk/
>>>>>
>>>>> Why is it that you only track the time for
>>>>>
>>>>> log_is_enabled(Debug, monitorinflation)
>>>>
>>>> Ouch. That's a cut-n-paste error from when I manually extracted
>>>> the patch out of my monitor deflation repo into the current
>>>> jdk/jdk baseline repo.
>>>>
>>>> This line:
>>>>
>>>>     L1695:   if (log_is_enabled(Debug, monitorinflation)) {
>>>>
>>>> should be:
>>>>
>>>>     L1695:   if (log_is_enabled(Info, safepoint, cleanup)) {
>>>>
>>>> I must have grabbed from the wrong diff when I did that part.
>>>>
>>>>
>>>>> but you only report the time under:
>>>>>
>>>>> log_info(safepoint, cleanup)
>>>>>
>>>>> ?? Unless you explicitly know to enable monitorinflation enabling 
>>>>> the safepoint-cleanup logging will just report zero. I would have 
>>>>> expected to see the deflation time recorded and printed for both 
>>>>> log settings
>>>>
>>>> The intent for the new "deflating per-thread idle monitors" log mesg
>>>> is to match the existing "deflating global idle monitors" log mesg.
>>>> Both should be controlled by: log_is_enabled(Info, safepoint, cleanup)
>>>>
>>>>
>>>>>
>>>>> And under what conditions is the existing "global deflation" time 
>>>>> reported?
>>>>
>>>> That's done by this piece of code:
>>>>
>>>>     src/hotspot/share/runtime/safepoint.cpp:
>>>>     L621:       TraceTime timer(name, TRACETIME_LOG(Info, 
>>>> safepoint, cleanup));
>>>>
>>>> That helper object includes a call to:
>>>>
>>>>     log_is_enabled(Info, safepoint, cleanup)
>>>>
>>>> along with built-in timer support.
>>>>
>>>>
>>>>>
>>>>>> The fix has been tested with a Mach5 
>>>>>> builds-tier1,hs-tier1,jdk-tier1,
>>>>>> hs-tier2,hs-tier3 job. The modified SafepointCleanupTest.java has
>>>>>> been verified to pass in all Mach5 configs.
>>>>>
>>>>> But the test doesn't enable monitorinflation logging so doesn't 
>>>>> actually verify the logging works.
>>>>
>>>> It does when the right check is in place. :-(
>>>>
>>>>
>>>>>
>>>>>> This bug is currently targeted at jdk13, but I think it is safe
>>>>>> enough to be pushed to jdk12 if the reviewers agree.
>>>>>
>>>>> No problem with fixing in 12.
>>>>
>>>> Thanks.
>>>>
>>>> Dan
>>>>
>>>>>
>>>>> Thanks,
>>>>> David
>>>>>
>>>>>> Thanks, in advance, for any comments, questions or suggestions.
>>>>>>
>>>>>> Dan
>>>>
>>>>
>>>
>>>
>>