RFR(S/M): 8217659 monitor_logging updates from Async Monitor Deflation project
David Holmes
david.holmes at oracle.com
Thu Jan 31 02:46:01 UTC 2019
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. :(
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