RFR: 8141211: Convert TraceExceptions to Unified Logging

[David Holmes]

Hi Max,

On 18/12/2015 7:05 AM, Max Ockner wrote:
> Our goal is to copy over the old logging in an acceptable (not
> necessarily identical) way.

Preservation of structure was part of that goal - so converting 
multi-line to single-line isn't really an option.

> The two issues I see with splitting multi-line messages into multiple
> messages are (1) decorators in places where they weren't before, and (2)
> Possible interleaving of messages.
> Issue (1) does not really bother me.  There are currently multi-line
> logging statements that can be accessed with TraceClassResolution, but
> most of them have "RESOLVE" hard-coded into the beginning of each line
> anyway. So even the existing multi-line messages sometimes have
> decorators at the beginning of each line. I'm not super worried about
> this.  Issue (2) is annoying and shows how important it is to have
> support for multi-line messages. However, we don't have that support
> yet, and temporary implementations could be messy.
>
> I vote that we use multiple logging messages *for now* until there is
> support for multi-line messages. I say this because I want to avoid duct
> taping together a section of code that we have worked very hard to
> polish for the last few months.  We can file an RFE for a secondary
> conversion of multi-line messages to be solved once we have the
> necessary support.

Sorry I disagree. Taking two passes through this will be very time 
consuming and inefficient.

This is the point in time where we can see where we had atomic 
multi-line messages, as we remove the ttyLocker usage. If we convert to 
multiple log lines there will be no easy way to track which logging 
usages have to be revisited when the new support arrives.

If we use a single log statement, or separate buffer, with explicit 
newlines embedded then we preserve the structure and the atomicity now. 
We don't even necessarily have to revisit this in the future when the 
alternate multi-line mechanism arrives.

Or we make the new multi-line mechanism a top priority and defer the 
conversion until it is in place.

> As for decoration in multi-line messages, I don't think it matters.

I think it may need to be configurable.

David
-----

> Max
>
>
> On 12/17/2015 5:31 AM, Marcus Larsson wrote:
>> Hi,
>>
>>
>> On 2015-12-17 09:41, Bengt Rutisson wrote:
>>>
>>>
>>> On 2015-12-16 22:43, Coleen Phillimore wrote:
>>>>
>>>>
>>>> On 12/16/15 4:01 PM, John Rose wrote:
>>>>> On Dec 15, 2015, at 12:26 PM, Rachel Protacio
>>>>> <rachel.protacio at oracle.com> wrote:
>>>>>> - each incident of ttyLocker that involved separate logging lines
>>>>>> for the same message have been consolidated to one line
>>>>>> - each incident of ttyLocker that involved separate print
>>>>>> statements to one logging line has been changed to write to a
>>>>>> buffer first, then print the entire line at once to the log stream
>>>>> This is a strong argument for putting such functionality into the
>>>>> UL framework,
>>>>> instead of giving developers the unfortunate choice of either (a)
>>>>> doing it right
>>>>> with a bunch of random logic (Rachel's choice here) or (b) sweeping
>>>>> it under
>>>>> the carpet by breaking up a multi-part message into several log
>>>>> messages.
>>>>>
>>>>> We need to admit this is the Achilles Heel of logging as normally
>>>>> conceived
>>>>> (especially for very long multi-part messages like disassembler
>>>>> output,
>>>>> backtraces, or compilation logs), and just fix it in the UL frameowrk.
>>>>
>>>> Yes, I agree.  We should file a high priority RFE against UL for
>>>> this if one isn't filed already.  The runtime only uses ttyLocker
>>>> (as far as I found) for TraceExceptions but the compiler uses it
>>>> more often to aggregate messages.   The lack of a locking mechanism
>>>> seems to be one of the factors blocking the compiler group adoption
>>>> of this feature.   And will block more complex runtime logging
>>>> conversions.
>>>>
>>>> So what do people vote that we do?  Should we log the messages
>>>> separately until this is fixed?  I agreed with making these logs one
>>>> line because even though they wrap, they weren't that long. It would
>>>> be nice to be able to do the conversion work to UL concurrently
>>>> while finding problems in the framework, and not be stuck.
>>>
>>> From my point of view it would be very unfortunate to require all
>>> logging to take an extra lock. If the multiline support can be
>>> implemented in the UL framework without any extra cost for "normal"
>>> logging I would be fine with it. But if it would slow down the normal
>>> logging, which I assume would be the case if we require an extra
>>> lock, then I would prefer to push the responsibility up to the users
>>> of the UL framework to synchronize properly.
>>
>> Support for multi line logging was a stretch goal of the UL project
>> that was never implemented. I think it might be a good feature to
>> have, given that there is a lot of logging requiring such
>> functionality. Regardless, having this discussion is good, because I
>> think we need to work out the details of how it should work. For
>> example, should each line in a multi-line message be decorated? Do we
>> write anything special to signify that these lines are tied together?
>>
>> The current implementation relies on the OS to do proper
>> synchronization of the streams for the printf calls, which should
>> guarantee that each line will be written atomically. Introducing a
>> lock will be necessary for multi-line logging, but perhaps it won't be
>> too bad if we use light weight locks very fine grained around the
>> printfs. If we measure an increased cost for this, it should probably
>> be weighed against the benefit for the use cases requiring it.
>>
>> Regards,
>> Marcus
>>
>>>
>>> Bengt
>>>
>>>>
>>>> Thanks,
>>>> Coleen
>>>>>
>>>>> — John
>>>>
>>>
>>
>