RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework

Marcus Larsson marcus.larsson at oracle.com
Thu Mar 31 12:13:53 UTC 2016

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.

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

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

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

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


[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