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

Daniel D. Daugherty daniel.daugherty at oracle.com
Fri Feb 1 14:12:59 UTC 2019


On 1/31/19 11:30 PM, David Holmes wrote:
> 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).

Thanks for closing the loop on this. I wanted to make sure
we were on the same page (understanding what we each mean).
Yes, not having duplicates is important to me. :-)

Dan

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