RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework

Marcus Larsson marcus.larsson at oracle.com
Thu Mar 31 15:05:37 UTC 2016

On 03/31/2016 03:40 PM, Thomas Stüfe wrote:
> Hi Marcus,
> On Thu, Mar 31, 2016 at 2:13 PM, Marcus Larsson 
> <marcus.larsson at oracle.com <mailto: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()

Good idea.

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

The use case I want to support with multi-part messages on different 
levels is when you have an event you want to log, on for example info 
level, but where part of that event might include data that is too 
verbose to fit the info level. So then you could split the event into 
two parts, one line with the basic information on info level and the 
other line (or multiple lines) on debug or trace level. The framework 
then makes sure these lines are delivered together non-interleaved.

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

Ok, so say we add the debug_no_cr() family of functions that writes into 
the log message buffer without newlines. Then, what does it mean if 
someone does debug_no_cr(s1); trace_no_cr(s2); info(s3); ?

It would be simpler if it wasn't for the support for different levels on 
different parts of the message. Maybe some well defined rules for how it 
should work would solve this, but I intended to avoid the whole use case 
for now. It can be done manually with stringStreams, so I don't think 
it's that serious.

>>     - 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 <mailto: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/
>>             <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.02/>
>>             Incremental:
>>             http://cr.openjdk.java.net/~mlarsson/8145934/webrev.alt-02/
>>             <http://cr.openjdk.java.net/%7Emlarsson/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>
>>                 <mailto: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/>
>>                     <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/>
>>                     <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/>
>>                     <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