RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework
Marcus Larsson
marcus.larsson at oracle.com
Thu Apr 14 13:25:40 UTC 2016
Updated webrev:
http://cr.openjdk.java.net/~mlarsson/8145934/webrev.04/
Incremental:
http://cr.openjdk.java.net/~mlarsson/8145934/webrev.03-04/
Changed according to Thomas' feedback. John, are you fine with the
latest changes?
Thanks,
Marcus
On 04/06/2016 03:45 PM, Marcus Larsson wrote:
> Hi,
>
> On 2016-04-06 11:38, Thomas Stüfe wrote:
>> Hi Marcus,
>>
>> still no luck applying your patch to hs-rt. On a freshly cloned repo
>> I get:
>>
>> hg qpush -v
>>
>> ....
>> cannot patch src/share/vm/logging/logMessage.hpp: file is not tracked
>> ....
>>
>
> Weird. Seems like webrev doesn't like my patch queue. I've regenerated
> the webrev with a single patch, updated in place.
>
>> ----
>>
>> I still feel that the benefit of different levels per log message is
>> not worth the added complexity, especially since it prevents one from
>> using the log message like a string stream (as you explained, using
>> different log levels means a write must always be a complete line).
>>
>> I understand your motivation, but what you describe could just as
>> well be done as (pseudocode):
>>
>> LogMessage(logging) msg;
>> if (level >= debug) {
>> msg.print("debug message");
>> if (level >= trace) {
>> msg.print("additional trace information");
>> }
>> }
>>
>> easier to understand, too. At the added costs of additional
>> comparisons in the caller code. That way LogMessage does not have to
>> know anything about log levels, and hence does not need to keep meta
>> infos about lines, and could have a print() and print_cr() method.
>
> Assuming that message would then be written on debug level, you would
> get trace messages included in the debug output depending on whether
> or not you have trace enabled. It makes it all very confusing for the
> consumers instead.
>
>>
>> But that is just my opinion.
>>
>> ....
>>
>> Other than that, code looks fine. Small remarks:
>>
>> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.03/src/share/vm/logging/log.cpp.udiff.html
>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.03/src/share/vm/logging/log.cpp.udiff.html>
>>
>>
>> file_contains_substrings_in_order:
>>
>> Potential truncation if line length > 1024.
>>
>
> Will fix.
>
>> --
>>
>> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.03/src/share/vm/logging/logFileStreamOutput.cpp.udiff.html
>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.03/src/share/vm/logging/logFileStreamOutput.cpp.udiff.html>
>>
>>
>> Both LogFileStreamOutput::write(const LogDecorations& decorations,
>> const char* msg) and
>> LogFileStreamOutput::write(LogMessageBuffer::Iterator msg_iterator)
>> can be made a tiny bit smaller by unifying the else branches, eg:
>>
>> + int written = 0;
>> + os::flockfile(_stream);
>> + for (; !msg_iterator.is_at_end(); msg_iterator++) {
>> + if (use_decorations) {
>> + written += write_decorations(msg_iterator.decorations());
>> + }
>> + written += jio_fprintf(_stream, "%s\n", msg_iterator.message());
>> + }
>> + fflush(_stream);
>> + os::funlockfile(_stream);
>
> I will have to include a jio_fprintf in the if-case (or in
> write_decorations) for the separating space between decorations and
> message. It saves the else case though, so I'll update it.
>
>> ---
>>
>> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.03/src/share/vm/logging/logPrefix.hpp.udiff.html
>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.03/src/share/vm/logging/logPrefix.hpp.udiff.html>
>>
>>
>> DEBUG_ONLY(buf[0] = '\0';) \
>>
>> I would get either rid of this or do this for product too. Doing this
>> only for debug just hides "append-assuming-empty-string" errors in
>> debug case.
>
> I'll remove it and change the assert to:
>
> assert(ret == 0 || ret == strlen(buf), ...
>
>
>>
>> Otherwise it looks fine to me. Still not a reviewer though :) so
>> others should look at this too.
>>
>> Kind Regards, Thomas
>
> Thanks!
> Marcus
>
>>
>>
>>
>> On Tue, Apr 5, 2016 at 4:14 PM, Marcus Larsson
>> <marcus.larsson at oracle.com <mailto:marcus.larsson at oracle.com>> wrote:
>>
>> Hi,
>>
>> Rebased and aligned the patch with the latest changes to the UL
>> API. Webrevs updated in place.
>>
>> Are we ready to wrap this up?
>>
>> Thanks,
>> Marcus
>>
>>
>> On 04/01/2016 03:33 PM, Marcus Larsson wrote:
>>
>> Hi again,
>>
>> Updated webrev with removed decoration buffers. Decorations
>> are now written directly to the streams with the help of
>> flockfile/funlockfile as you suggested.
>>
>> Webrev:
>> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.03/
>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.03/>
>>
>> Incremental:
>> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.02-03/
>> <http://cr.openjdk.java.net/%7Emlarsson/8145934/webrev.02-03/>
>>
>> Thanks,
>> Marcus
>>
>> On 03/31/2016 05:05 PM, Marcus Larsson wrote:
>>
>>
>> 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>
>> <mailto: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.
>>
>>
>> Yeah.
>>
>> Regards,
>> Marcus
>>
>>
>> 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>
>> <mailto: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/>
>> <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/>
>> <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>>
>> <mailto: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/>
>> <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/>
>> <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/>
>> <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