RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework

Thomas Stüfe thomas.stuefe at gmail.com
Thu Mar 31 13:40:25 UTC 2016 

Hi Marcus,

On Thu, Mar 31, 2016 at 2:13 PM, Marcus Larsson <marcus.larsson at oracle.com>
wrote:

> Hi Thomas,
>
>
> On 03/31/2016 12:48 PM, Thomas Stüfe wrote:
>
> Hi Marcus,
>
> nice to see progress on that issue!
>
>
> Thanks for taking time to look at it.
>
>
> 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):
>
>
> I'll rebase it and update the webrev.
>
>
> - 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.
>
>
> It might be worth investigating, but if so it should probably be a
> separate RFE.
>
>
Ok. Easy enough to fix should e.g. NMT ever want to use UL.

>
> - 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?
>
>
> The fprintfs locks the FILE* internally even if we don't. This is AFAIU
> how fprintf guarantees the writes to be atomic. With the explicit flock
> calls we're just ensuring nothing can be printed in-between our fprintf
> calls, it shouldn't add any cost.
>
>
Ah, I see. If we really feel safe about flockfile(), we might just as well
use it in LogFileStreamOutput::write() too. There, we assemble the
decorators in a stack local buffer to fprintf them out to the FILE* in a
separate step - I guess to prevent tearing? But if flockfile comes without
cost, we could save the stack local buffer and do:

flockfile()
fputs(decorators)
fputs(message)
funlockfile()

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.
>
>
> As the message might go to different outputs, configured for different
> levels, we can't really get rid of the _lines[] array. We could assemble
> each applicable message as a long string for each of the outputs, but given
> how fprintf seems to work we won't really have gained anything for that
> extra work and memory usage.
>
>
Oh, I see. I did not understand the complexity of the whole thing. Why is
it needed to write lines to a message with different log levels? I may be
slow, but I find that not easy to understand. The fact that different lines
in my message may go to different outputs is a bit surprising. I would have
thought a message is just a text blob I assemble offline and send to the
logging framework in one go, like a glorified String, and that I would hand
it down to UL "send this for this level/tagset combination". And that the
message itself would not even need to know anything about log levels and
tagsets.

- 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?
>
>
> Yes, that's right. I wanted to avoid streams for multi-line messages
> because I thought the API would become a bit messy with that functionality.
> The logStreams we have today are line buffered, and will send completed
> lines to the log outputs when they see a terminating newline character.
> This means that it won't be obvious how lines from different streams or
> writes to the message will be ordered in the output. Perhaps it's not that
> bad, but I figured that we could use stringStreams or similar for when we
> need to build up lines for the message. This has the nice side effect that
> it will be very obvious when, and in what order, each line is written to
> the outputs. Perhaps it's worth a follow up RFE if we find ourselves
> writing one too many log cases with stringStreams?
>
>
Sorry, I think I was not clear enough. What I meant was simpler. We have
now ScopedLogMessage::debug() which does LogMessageBuffer::write() which
writes a line and terminates the line. Line outputStream::print_cr(). I
would like to have an option to just write but not terminate the current
line, like outputStream::print(). That way one could assemble a line piece
by piece, maybe in a loop (e.g. for table row values) without needing
another temporary buffer.


> - 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?
>
>
> The patch for JDK-8138916 [0] added the log_vsnprintf. You mean to change
> jio_vsnprintf to not return -1 on truncation, and instead work like
> vsnprintf on POSIX? I think that would be useful, and it allows us to
> remove log_vsnprintf.
>

That is exactly what I meant. I think that would be a separate RFE though,
one would have to check on all callers of jio_snprintf.


>
> Thanks,
> Marcus
>
>
Thank you!

..Thomas


> [0] https://bugs.openjdk.java.net/browse/JDK-8138916
>
>
>
> 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>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
>>>
>>
>>
>
>

More information about the hotspot-dev mailing list