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

[David Holmes]

Hi Dan,

First a couple of nits:

1. I don't like the ck_* naming as an abbreviation for "check". chk 
would be better, or even check.

2. We don't need comments like this:

1430         // Use log_is_enabled() to avoid ResourceMark creation and
1431         // external_name() use if possible.

else we'd be using them in 90% of logging blocks.

There is one erroneous pattern here. You can't do this:

1654   if ((deflated_count != 0 && log_is_enabled(Info, 
monitorinflation)) ||
1655       log_is_enabled(Debug, monitorinflation)) {
1656     log_info(monitorinflation)("deflating global idle monitors, 
%3.7f secs, %d monitors", timer.seconds(), deflated_count);
1657   }

While Info normally implies Debug, they can be controlled independently, 
further you may be writing Info output and Debug output to different 
streams. So you can't just use log_info when it should really be 
log_debug. Probably the way to handle this without duplication is to 
again use LogStreams (or outputstreams):

LogStream* ls;
if (log_is_enabled(Debug, monitorinflation))
   ls = <debug log>
else if (log_is_enabled(Info, monitorinflation))
   ls = <info log>
if (ls != null)
   ls.print(...);

Using a LogStream can also avoid duplicate is_enabled checks in places 
like ObjectSynchronizer::finish_deflate_idle_monitors.

Thanks,
David
-----


On 30/01/2019 7:26 am, Daniel D. Daugherty wrote:
> I've snipped this reply down to just the part about refactoring...
> 
> 
> On 1/28/19 5:22 PM, Daniel D. Daugherty wrote:
>> On 1/28/19 5:15 PM, coleen.phillimore at oracle.com wrote:
>>>>
>>>>> My eyes are terrible, but it looks like this is 
>>>>> ObjectMonitor::verify_free()
>>>>
>>>>> + if (n->is_busy()) {
>>>>> + out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": free global 
>>>>> monitor "
>>>>> + "must not be busy.", p2i(n));
>>>>> + *error_cnt_p = *error_cnt_p + 1;
>>>>> + }
>>>>> + if (n->header() != NULL) {
>>>>> + out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": free global 
>>>>> monitor "
>>>>> + "must have NULL _header field: _header=" INTPTR_FORMAT,
>>>>> + p2i(n), p2i(n->header()));
>>>>> + *error_cnt_p = *error_cnt_p + 1;
>>>>> + }
>>>>> + if (n->object() != NULL) {
>>>>> + out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": free global 
>>>>> monitor "
>>>>> + "must have NULL _object field: _object=" INTPTR_FORMAT,
>>>>> + p2i(n), p2i(n->object()));
>>>>> + *error_cnt_p = *error_cnt_p + 1;
>>>>> + } ...
> 
> I have refactored the common code for "verify free" into:
> 
> +// Check a free monitor entry; log any errors.
> +void ObjectSynchronizer::ck_free_entry(JavaThread * jt, ObjectMonitor * n,
> +                                       outputStream * out, int 
> *error_cnt_p) {
> 
> And here's what one of the checks looks like. I tried to put it all into
> a single out->print_cr() call with conditional inclusion of format strings
> and parameters, but the compiler really hated it. So I went with:
> 
> +  if (n->is_busy()) {
> +    if (jt != NULL) {
> +      out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
> +                    ": free per-thread monitor must not be busy.", 
> p2i(jt),
> +                    p2i(n));
> +    } else {
> +      out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": free global 
> monitor "
> +                    "must not be busy.", p2i(n));
> +    }
> +    *error_cnt_p = *error_cnt_p + 1;
> +  }
> 
> 
> 
>>>>> And this is ObjectMonitor::verify_in_use()
>>>>>
>>>>> + if (n->header() == NULL) {
>>>>> + out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": in-use global 
>>>>> monitor "
>>>>> + "must have non-NULL _header field.", p2i(n));
>>>>> + *error_cnt_p = *error_cnt_p + 1;
>>>>> + }
>>>>> + if (n->object() == NULL) {
>>>>> + out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": in-use global 
>>>>> monitor "
>>>>> + "must have non-NULL _object field.", p2i(n));
>>>>> + *error_cnt_p = *error_cnt_p + 1;
>>>>> + } ...
> 
> I have refactored the common code for "verify in use" into:
> 
> +// Check an in-use monitor entry; log any errors.
> +void ObjectSynchronizer::ck_in_use_entry(JavaThread * jt, ObjectMonitor 
> * n,
> +                                         outputStream * out, int 
> *error_cnt_p) {
> 
> And here's what one of the checks looks like:
> 
> +  if (n->header() == NULL) {
> +    if (jt != NULL) {
> +      out->print_cr("ERROR: jt=" INTPTR_FORMAT ", monitor=" INTPTR_FORMAT
> +                    ": in-use per-thread monitor must have non-NULL 
> _header "
> +                    "field.", p2i(jt), p2i(n));
> +    } else {
> +      out->print_cr("ERROR: monitor=" INTPTR_FORMAT ": in-use global 
> monitor "
> +                    "must have non-NULL _header field.", p2i(n));
> +    }
> +    *error_cnt_p = *error_cnt_p + 1;
> +  }
> 
> Hopefully this is the last refactor for this bug fix... :-)
> 
> 
> Here's an incremental webrev:
> 
> http://cr.openjdk.java.net/~dcubed/8217659-webrev/2-for-jdk13.inc/
> 
> Here's a full webrev:
> 
> http://cr.openjdk.java.net/~dcubed/8217659-webrev/2-for-jdk13.full/
> 
> Another Mach5 builds-tier1,hs-tier1,jdk-tier1,hs-tier2,hs-tier3 test
> run is in process...
> 
> Thanks, in advance, for any questions, comments or suggestions.
> 
> Dan
> 
>> 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
>