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

Daniel D. Daugherty daniel.daugherty at oracle.com
Fri Jan 25 21:22:45 UTC 2019 

On 1/25/19 3:45 PM, coleen.phillimore at oracle.com wrote:
> On 1/24/19 6:52 PM, Daniel D. Daugherty wrote:
>> 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.
>
> It is but you're testing it twice unnecessarily in most cases.

I'll be looking at making the log_is_enabled() calls efficient.


>>
>> 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.
>
> Yes, this is the canonical example.  If you call as_C_string() or 
> external_name() or some such, testing log_is_enabled() is a good 
> idea.   It looked like some instances didn't need to check if the 
> logging is enabled first.
>
> I think the string formatting doesn't happen if the logging isn't 
> enabled, but, yes, as_C_string() etc will be.

I'll be looking at making the log_is_enabled() calls efficient
for the trivial logging calls.


>
>>
>> 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.
>>
>>
> ok.
>
>> > 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.
>
> The suggestion is to break this function up into smaller functions 
> that aren't so mind numbing to read through.  Maybe it just looked 
> like duplication after a while, but naming the thing you're verifying 
> with a function name would be easier to understand.

Okay. Now I'm grok'ing what you're saying.


> And you might want to add more logging tags to some of the 
> checks/functions, if you have some specific thing that you're 
> interested in the future.

For this bug, I'll likely keep the tag as 'monitorinflation'
and use logging Levels to differentiate. Obviously, as work
continues on the Async Monitor Deflation piece, the need for
some new logging tags may present itself...

Dan


>
> thanks,
> Coleen
>
>>
>>
>>> 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
>>>>
>>>
>>
>

More information about the hotspot-runtime-dev mailing list