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

Daniel D. Daugherty daniel.daugherty at oracle.com
Thu Jan 31 03:23:37 UTC 2019 

On 1/30/19 9:46 PM, David Holmes wrote:
> Hi Dan,
>
> On 31/01/2019 5:23 am, 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/
>
> Sorry but I gave you some bad advice, the pattern I suggested doesn't 
> work either:
>
> 1648   LogStreamHandle(Debug, monitorinflation) lsh_debug;
> 1649   LogStreamHandle(Info, monitorinflation) lsh_info;
> 1650   LogStream * ls = NULL;
> 1651   if (log_is_enabled(Debug, monitorinflation)) {
> 1652     ls = &lsh_debug;
> 1653   } else if (deflated_count != 0 && log_is_enabled(Info, 
> monitorinflation)) {
> 1654     ls = &lsh_info;
> 1655   }
> 1656   if (ls != NULL) {
> 1657     ls->print_cr("deflating global idle monitors, %3.7f secs, %d 
> monitors", timer.seconds(), deflated_count);
> 1658   }
>
> Assume both Debug and Info are enabled, but directed to different 
> files. You potentially need to log to both of them, but the code above 
> will only log to one of them. I don't think you have a choice but to 
> duplicate the logging statements. :(

Doing that would duplicate the logging statements in the output
if both Debug and Info were logging to the same place and I don't
want that.

If both Debug and Info are enabled and directed to different files,
I'm happy to find most of the output in the Debug log file and only
the log_info() output in the Info log file. This is particularly
true for audit_and_print_stats() output.

I'm planning to move forward with the latest webrev if you are okay
with that...

Dan


>
> Sorry again.
>
> David
> -----
>
>
>
>> 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