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

coleen.phillimore at oracle.com coleen.phillimore at oracle.com
Wed Jan 30 22:20:29 UTC 2019 

"inc" version looks good.
Coleen

On 1/30/19 2:23 PM, Daniel D. Daugherty wrote:
> Greetings,
>
> I've addressed David H's latest round of comments.
>
> Here's an incremental webrev:
>
> http://cr.openjdk.java.net/~dcubed/8217659-webrev/3-for-jdk13.inc/
>
> Here's a full webrev:
>
> http://cr.openjdk.java.net/~dcubed/8217659-webrev/3-for-jdk13.full/
>
> Another Mach5 builds-tier1,hs-tier1,jdk-tier1,hs-tier2,hs-tier3 test
> run is in process... I've manually verified that we get fewer log
> messages at the Info level (deflate count == 0 are skipped) and that
> get those deflate count == 0 mesgs at the Debug level.
>
> Thanks, in advance, for any questions, comments or suggestions.
>
> Dan
>
>
> On 1/30/19 11:07 AM, Daniel D. Daugherty wrote:
>> On 1/29/19 10:07 PM, David Holmes wrote:
>>> Hi Dan,
>>
>> Hi David!
>>
>> And thanks for the re-review.
>>
>>
>>> 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.
>>
>> I'll change 'ck_' -> 'chk_'.
>>
>>
>>> 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.
>>
>> I added that comment in two places in response to a comment from Coleen
>> to remove the 'log_is_enabled()' call. Since you're saying that my 
>> comment
>> is 'common knowledge' then I'll remove both of them.
>>
>>
>>> 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. 
>>
>> Thanks for catching this one. Obviously I still have more to learn
>> about logging...
>>
>>
>>> 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(...);
>>
>> Thanks for the pattern. I'll take care of it. I think the bug is
>> in at least two places.
>>
>>
>>> Using a LogStream can also avoid duplicate is_enabled checks in 
>>> places like ObjectSynchronizer::finish_deflate_idle_monitors.
>>
>> I'll revisit finish_deflate_idle_monitors() also.
>>
>> Thanks again for the re-review.
>>
>> Dan
>>
>>
>>>
>>> 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
>>>>
>>
>>
>

More information about the hotspot-runtime-dev mailing list