RFR: 8141211: Convert TraceExceptions to Unified Logging

[Thomas Stüfe]

Hi all,

we at SAP have years ago added a logging system to our hotspot port which
is in many ways similar to UL but solves the multiline-problem differently.

(Side note: we are currently discussing whether to abandon our logging
system in favour of UL, just because merging down- and upstream would be
easier if we use the same logging system)

In our system, we assemble the multiline content in memory and then print
it in one go. Only during the printing part we lock (and only on platforms
where we cannot be sure that one write call would not be atomic). The
advantage is that locking is not responsibility of the caller.

Basically, we have a Message class, which serves as message buffer to grow
on demand (dynamically allocates C heap), with some care taken to balance
number or (re)allocation calls and memory usage. The caller itself is
responsible for adding newlines.

Basically, it looks like this:

Message mymsg = new Message;
mymgs->print("hallo1\nhallo2\nhallo3");
tracer->print(mymsg); <- here, tracer will lock, write, unlock

When we print it, we precede the multiline message with the decorators in
the first line and indent the rest of the lines to the same position:

[time][pid][tid]  hallo1
                  hallo2
                  hallo3

This approach has served us quite well. We decided against locking done by
the caller because users to minimize the danger of deadlocks.

Kind Regards, Thomas

On Thu, Dec 17, 2015 at 11:31 AM, Marcus Larsson <marcus.larsson at oracle.com>
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
>>>>
>>>
>>>
>>
>