RFR(S/M): 8217659 monitor_logging updates from Async Monitor Deflation project
Daniel D. Daugherty
daniel.daugherty at oracle.com
Wed Jan 30 16:07:41 UTC 2019
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