RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework

[Thomas Stüfe]

Hi Marcus,

nice to see progress on that issue!

Unfortunately your patch did not apply to my freshly synced hs-rt
repository. So I took a "dry look" at your code, and here some feedback (by
no means complete, and also I am not a (R)eviewer):

- thank you for taking my input and avoiding resource area for memory. I am
still apprehensive about UL using NEW_C_HEAP_ARRAY instead of raw malloc()
here, but I see it has pros and cons.

- I am not sure about flockfile(): I really do not like file locks, this
always bites in customer scenarios. Also, by using this lock, are we not
just reintroducing the ttyLocker at a deeper level? Instead, how about
assembling the total message in memory - like it would appear in the file -
and print it in one go using ::write()? That usually is atomic. This way
you would have to write out the decorators for each line in memory as they
are added, but you could get rid of the _lines[] array and all its
surrounding code. So, no lock, less complicated code, at the cost of a bit
more memory usage.

- If I understand this correctly, there is no way to print part of a line
to the message object? So, if I would want to assemble a line from various
inputs, I would still have to assemble it on the stack and feed it to say
ScopedLogMessage::debug() in one go? Would it be posssible to get an
outputStream* from the ScopedLogMessage to write into?

- I like how you implemented os::log_vsnprintf(), using _vscprintf() on
windows. Would it be worthwhile to merge this with jio_vsnprintf(), which
does the same but returns -1 on truncation?

Kind Regards, Thomas


On Thu, Mar 31, 2016 at 10:53 AM, Marcus Larsson <marcus.larsson at oracle.com>
wrote:

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