RFR(S/M): 8217659 monitor_logging updates from Async Monitor Deflation project

[Daniel D. Daugherty]

On 1/24/19 2:41 AM, David Holmes wrote:
> Hi Dan,
>
> This looks generally fine too.

Thanks for the review!


> ObjectSynchronizer::audit_and_print_stats is pretty hard to digest!

Agreed! Writing it was also "interesting"... :-)


> I think the logging can be simpler if you extract the log stream 
> rather than repeating "log_info(monitorinflation)" so many times.

Sounds good. I'll figure out how to do that and update the code.


>
> + // I'm not sure why the baseline monitorinflation logic only
> + // issues logging mesgs for instance objects.
> + //      if (obj->is_instance()) {
>
> This needs to be resolved.

Yes, that would be why I left that comment in for the review. :-)
I'll check the code history for the original monitor deflation
logging code and see if I can discern a reason.


> If the alternative to being an instance is being an array, then I 
> think we should be logging for those too (that might actually catch 
> use of the class initialization monitors).

In my debugging of a recent test failure, I saw logging output
for and inflated "[I" at the end of the VM's life (IIRC)...


> When we have different Info versus Debug logging eg:
>
> !   if (deflated_count != 0) {
> !     if (log_is_enabled(Info, monitorinflation)) {
> !       log_info(monitorinflation)("deflating global idle monitors, 
> %3.7f secs, %d monitors", timer.seconds(), deflated_count);
> !     }
> !   } else {
> !     if (log_is_enabled(Debug, monitorinflation)) {
> !       log_debug(monitorinflation)("deflating global idle monitors, 
> %3.7f secs, 0 monitors", timer.seconds());
> !     }
> !   }
>
> is it possible to rewrite that as:
>
>  if (log_is_enabled( deflated_count != 0 ? Info : Debug,
>                     monitorinflation)) {
> !       log_info(monitorinflation)("deflating global idle monitors, 
> %3.7f secs, %d monitors", timer.seconds(), deflated_count);
> !     }
>
> or does the logging macro-magic not allow it?

Good question. I'll check it out.

Maybe after the above simplifications, other ways to make this
function more digestible will become apparent...


> Finally, not sure if IncludeInUseMonitorDetailsInLogMsgs carries its 
> own weight. Could we not put that additional info at the Trace level, 
> rather than Info ?

Thanks for chiming in on IncludeInUseMonitorDetailsInLogMsgs. I tend
to agree hence the question during this review cycle. I'm thinking
that at VM-exit time, it should be at Debug level and at safepoint
time it should be at Trace level. I expect most casual use of
monitorinflation logging to be at the Info level... And this output
is far from casual...

Thanks again for the review.

Dan



>
> Thanks,
> David
> -----
>
> On 24/01/2019 6:16 am, Daniel D. Daugherty wrote:
>> Greetings,
>>
>> I have a (S)mall/(M)edium patch extracted from the Async Monitor 
>> Deflation
>> project that is ready for code review. I'm calling this a 
>> (S)mall/(M)edium
>> because the logic changes are (S)mall, but the logging code is 
>> tedious and
>> there's a bunch of it in audit_and_print_stats() so (M)edium.
>>
>> The short version of what this patch is about:
>>
>>      This sub-task captures updates and additions to the
>>      baseline monitor logging code.
>>
>> The details are in the bug report:
>>
>>      JDK-8217659 monitor_logging updates from Async Monitor Deflation 
>> project
>>      https://bugs.openjdk.java.net/browse/JDK-8217659
>>
>> Here's the webrev:
>>
>> http://cr.openjdk.java.net/~dcubed/8217659-webrev/0-for-jdk13/
>>
>> This patch along with the other two patches for Async Monitor Deflation
>> project have been through Mach5 
>> builds-tier1,hs-tier1,jdk-tier1,hs-tier2,hs-tier3
>> testing and I'm currently running my stress testing kits on my Linux-X64
>> and Solaris-X64 servers.
>>
>> I have been actively using this new logging code while debugging my
>> port of the Async Monitor Deflation project code.
>>
>> Thanks, in advance, for any questions, comments or suggestions.
>>
>> Dan
>>