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

Thu Jan 24 23:52:46 UTC 2019

Hi Coleen,

Thanks for the review. Replies embedded below...

On 1/24/19 3:39 PM, coleen.phillimore at oracle.com wrote:
>
> http://cr.openjdk.java.net/~dcubed/8217659-webrev/0-for-jdk13/src/hotspot/share/runtime/synchronizer.cpp.frames.html 
>
>
> 1426 if (log_is_enabled(Trace, monitorinflation)) {
> 1427         if (object->is_instance()) {
> 1428           ResourceMark rm(Self);
> 1429 log_trace(monitorinflation)("inflate(has_locker): "
> 1430                                       "object=" INTPTR_FORMAT ", 
> mark=" INTPTR_FORMAT ", type='%s'",
> 1431                                       p2i(object), 
> p2i(object->mark()),
> 1432 object->klass()->external_name());
> 1433         }
> 1434       }
>
> It seems like extra overhead to ask if logging is enabled in both 1426 
> and internally in 1429.  It seems that if object->is_instance() is a 
> cheap test, 1426 is unnecessary.  I realize it was like this.   Same 
> at 1477, 1532.  I don't think ResourceMarks are expensive either.

I'll take a closer look at the various 'log_is_enabled()' calls
and how to make things more efficient in general. I have a memory
of someone saying that log_is_enabled() is pretty cheap.

If memory serves correctly, 'ResourceMark rm' is expensive and
'ResourceMark rm(thread)' is much less expensive, but still has a
non-trivial cost. If the parameters to a log_foo() call are
expensive to assemble, we don't want to do that only to throw them
away because the log_foo() code skips the log output.

The call to external_name() which allocates a C-string buffer and
translates the Java char string into the C-string is not cheap so
I think this is one of the cases where we don't want the log_foo()
call to make the decision.

Also, the object->is_instance() check may be going away. Neither
David nor I can remember why this logging code makes that check
so I need to chase that down.

 > 1652   if (deflated_count != 0) {
> 1653 if (log_is_enabled(Info, monitorinflation)) {
> 1654 log_info(monitorinflation)("deflating global idle monitors, %3.7f 
> secs, %d monitors", timer.seconds(), deflated_count);
> 1655 }
> 1656 } else {
> 1657 if (log_is_enabled(Debug, monitorinflation)) {
> 1658 log_debug(monitorinflation)("deflating global idle monitors, 
> %3.7f secs, 0 monitors", timer.seconds());
> 1659 }
>
>
> log_info/log_debug also ask if log_is_enabled, so the log_is_enabled 
> test isn't necessary here, and 1673, 1677 and 1664.  I think a lot of 
> these were early logging changes that weren't caught then.

David had a suggested rewrite for these lines in his comments that
I'm going to check out. One thing I'm trying to avoid is double
output lines if we're at log level Debug.

> Duplicating David's comment
>
> audit_and_print_stats
>
> can create a LogStream log and use that instead of doing log_info/etc.

Yup. I'm going to figure out how to do that.

> Instead of
>
> 2048 if (IncludeInUseMonitorDetailsInLogMsgs) {
>
> You can add a tag to the logging, so that you can say 
> -Xlog:monitorinflation+inuse or some such tag.
>
> It's not worth adding another command line option when logging gives 
> you the ability to be specific about what output you want.

Thanks for chiming in on IncludeInUseMonitorDetailsInLogMsgs.

That's another possibility. I'll look at that also. In my reply
to David I said:

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

so I have two possible solutions to look at...

> Lastly, I didn't look at what you're verifying and logging but maybe 
> the ~300 line function could be split and you could add more tags in 
> the future to taylor what specific information and verification you 
> are looking for.

I'm not sure what you're suggesting here.

> It looks there's a bit of duplication in the logging messages.

I wasn't aware of any duplication, but I could have missed somthing...

Dan

>
> Coleen
>
> On 1/23/19 3:16 PM, 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
>>
>