RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework
Marcus Larsson
marcus.larsson at oracle.com
Fri Apr 1 13:33:39 UTC 2016
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