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