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

Daniel D. Daugherty daniel.daugherty at oracle.com
Wed Jan 30 22:26:54 UTC 2019 

Thank you for the (many) re-reviews!

Dan



On 1/30/19 5:20 PM, coleen.phillimore at oracle.com wrote:
>
> "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