RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework

[Marcus Larsson]

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