RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework

[Marcus Larsson]

Any further feedback on this?


On 03/18/2016 02:33 PM, Marcus Larsson wrote:
> Hi again,
>
> New webrev:
> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.02/
>
> Incremental:
> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.alt-02/
>
> Made all allocations regular C heap allocations because of the 
> problems with resource allocations that Thomas brought up. We can do a 
> follow up change for resource allocation support if we really need it.
> Also added some more tests for scoped messages.
>
>
> On 02/17/2016 12:19 AM, John Rose wrote:
>> On Feb 16, 2016, at 8:32 AM, Marcus Larsson 
>> <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>>>
>>> Alternative version where a LogMessage automatically writes its 
>>> messages when it goes out of scope:
>>> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.alt/ 
>>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.alt/>
>>
>>
>> I like this, with the LogMessageBuffer that does the heavy work, and 
>> the [Scoped]LogMessage which is the simplest way to use it.
>>
>> The LogMessageBuffer should have a neutral unallocated state, for use 
>> through the LogMessage macro.  I.e., is_c_allocated should be a 
>> three-state flag, including 'not allocated at all'. That way, if you 
>> create the thing only to ask 'is_debug' and get a false answer, you 
>> won't have done more than a few cycles of work.  Probably the 
>> set_prefix operation should be lazy in the same way.
>
> Fixed. Since I removed the resource allocation completely I could keep 
> it as a boolean.
>
>>
>> I think the destructor should call a user-callable flush function, 
>> something like this:
>>
>>   ~ScopedLogMessage() { flush(); }
>>   // in LogMessageBuffer:
>>   void flush() {
>>     if (_line_count > 0) {
>>       _log.write(*this);
>>       reset();
>>     }
>>   }
>>   void reset() {
>>      _line_count = 0;
>>      _message_buffer_size = 0;
>>   }
>>
>> It will be rare for user code to want to either flush early or cancel 
>> pending output, but when you need it, it should be there.
>
> Fixed.
>
>>
>>> I still prefer the first patch though, where messages are neither 
>>> tied to a particular log, nor automatically written when they go out 
>>> of scope. Like I've said, the explicit write line makes it easier to 
>>> read the code.
>>
>> There's a tradeoff here:  It's easier to read the *logging* code if 
>> all the *logging* operations are explicit.  But the point of logging 
>> code is to add logging to code that is busy doing *other* operations 
>> besides logging.  That's why (I assume) people have been noting that 
>> some uses of logging are "intrusive":  The logging logic calls too 
>> much attention to itself, and with attention being a limited 
>> resource, it takes away attention from the actual algorithm that's 
>> being logged about.
>>
>> The scoped (RAII) log buffer, with automatic write, is the best way I 
>> know to reduce the intrusiveness of this auxiliary mechanism.
>
> Fair point. I'm going with the automatic write on out of scope.
>
>>
>> Of course, I'm interested in finding out what your everyday customers 
>> think about it.  (Rachel, Coleen, David, Dan?)
>>
>>> For comparison I've updated the first suggestion with the guarantee 
>>> for unwritten messages, as well as cleaning it up a bit by moving 
>>> the implementation to the .cpp rather than the .hpp.
>>> Full webrev:http://cr.openjdk.java.net/~mlarsson/8145934/webrev.01/ 
>>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.01/>
>>> Incremental:http://cr.openjdk.java.net/~mlarsson/8145934/webrev.00-01/ 
>>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.00-01/>
>>>
>>> Let me know what you think.
>>
>> That option is more intrusive than the RAII buffered log alias.
>>
>> Separately, the review thread on JDK-8149383 shows a use for 
>> LogMessageBuffer to collect a complex log message.  The log message 
>> can then be sent down one of two log streams.  Something like:
>>
>>   if (need_to_log) {
>>     ResourceMark rm;
>>     LogMessageBuffer buf;
>>     buf.write("Revoking bias of object " INTPTR_FORMAT " , mark "
>>                             INTPTR_FORMAT " , type %s , prototype 
>> header " INTPTR_FORMAT
>>                             " , allow rebias %d , requesting thread " 
>> INTPTR_FORMAT,
>>                             p2i((void *)obj),
>>                             (intptr_t) mark,
>> obj->klass()->external_name(),
>>                             (intptr_t) obj->klass()->prototype_header(),
>>                             (allow_rebias ? 1 : 0),
>>                             (intptr_t) requesting_thread);
>>     if (!is_bulk)
>>       log_info(biasedlocking).write(buf);
>>     else
>>       log_trace(biasedlocking).write(buf);
>>   }
>>
>> It is important here (like you pointed out) that the LogMessageBuffer 
>> is decoupled from log levels and streams, so that it can be used as a 
>> flexible component of logic like this.
>>
>> But the commonest usage should (IMO) be supported by a scoped 
>> auto-writing log alias.
>
> Yeah, I agree.
>
> Thanks,
> Marcus