RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework
Thomas Stüfe
thomas.stuefe at gmail.com
Wed Apr 6 09:38:54 UTC 2016
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
....
----
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.
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
file_contains_substrings_in_order:
Potential truncation if line length > 1024.
--
http://cr.openjdk.java.net/~mlarsson/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);
---
http://cr.openjdk.java.net/~mlarsson/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.
Otherwise it looks fine to me. Still not a reviewer though :) so others
should look at this too.
Kind Regards, Thomas
On Tue, Apr 5, 2016 at 4:14 PM, Marcus Larsson <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/
>>
>> Incremental:
>> http://cr.openjdk.java.net/~mlarsson/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>> 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>>
>>>>> 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