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

[Daniel D. Daugherty]

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
>>
>>
>
>