RFR(S/M): 8217659 monitor_logging updates from Async Monitor Deflation project
David Holmes
david.holmes at oracle.com
Fri Feb 1 04:30:22 UTC 2019
Hi Dan,
On 1/02/2019 12:49 am, Daniel D. Daugherty wrote:
> On 1/30/19 10:50 PM, David Holmes wrote:
>> 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.
>
> Let me make sure we're talking about the same thing. When you said
> duplicate the logging statement, I assume you meant:
>
> log_info(monitorinflation)("This is my message.");
> log_debug(monitorinflation)("This is my message.");
>
> which makes sure that the same message goes to the Info log and
> the Debug log when those logs are separate files. I'll double
> check, but I believe that construct will send "This is my message."
> to the combined log twice. Why wouldn't it? You've made two
> independent log calls at two different logging levels that happen
> to have the same message.
Right that's exactly how it works and you will get duplicate messages.
But you said you didn't want duplicate messages so you're choosing to
log to only one stream instead of the two the user may have asked for.
But there's no way to write to the two separate logs and not get
duplicates -> design omission (which is more accurate than design flaw).
Cheers,
David
> I'm not sure that I agree that this is a design flaw. The logging
> subsystem would have no way of knowing your intentions with these
> two separate calls. You might be sprinkling log messages through
> code paths to see where the code goes... and happen to have the
> same "XXX" message back to back (logging call wise), but at two
> different logging levels (which is strange)...
>
>
>>
>>> 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.
>
> Thanks!
>
>
>> One nit though:
>>
>> 1673 } else if (counters->perThreadScavenged != 0 != 0 &&
>> log_is_enabled(Info, monitorinflation)) {
>>
>>
>> !=0 is repeated.
>
> I'll fix that! I'm guessing the compiler evaluated it like this:
>
> ((counters->perThreadScavenged != 0) != 0)
> ((true) != 0)
> (true)
> or
> ((false) != 0)
> (false)
>
> Thanks for the catch!
>
> Dan
>
>
>
>>
>> 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