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

David Holmes david.holmes at oracle.com
Thu Jan 31 03:50:36 UTC 2019 

On 31/01/2019 1:23 pm, Daniel D. Daugherty wrote:
> 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.

<shrug> Seems like a flaw in the UL design then.

> 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...

Not completely happy but not strongly objecting.

One nit though:

1673   } else if (counters->perThreadScavenged != 0 != 0 && 
log_is_enabled(Info, monitorinflation)) {


!=0 is repeated.

Thanks,
David

> 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