RFR: 8141211: Convert TraceExceptions to Unified Logging

[David Holmes]

On 18/12/2015 7:14 PM, Bengt Rutisson wrote:
>
>
> On 2015-12-18 06:44, David Holmes wrote:
>> On 17/12/2015 6:41 PM, 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.
>>
>> How would users of the framework synchronize access to a shared
>> resource where some of the users of the resource are not party to the
>> synchronization process? AFAICS the synchronization has to be at the
>> resource-level.
>
> I think it depends on what problem we are trying to solve. In most cases
> I have seen so far it would be fine for two different activities to log
> their output interleaved. If for example the compiler would log
> something during a GC I wouldn't see that as a serious problem. It is

I don't really agree but I see where you are coming from.

> easy for a reader of the log file (human or machine) to sort out the
> logging since logging is never interleaved on the same line. And there

Actually ... we have seen Trace output "corrupted" somehow where lines 
are combined. This happened with some CDS-related tests earlier this 
year with TraceClassLoading - we had to relax the pattern so the 
corrupted lines would be accepted. Never did get to the bottom of it.

Cheers,
David

> is also the possibility for a user to pipe the logging to different
> files based on their tags.
>
> The problem I thought this email thread was about was when the same type
> of logging is done from multiple threads. Having multiple threads log
> multiple lines of similar data at the same time will be very hard to
> sort out after-the-fact in the log file. But since it is the same
> subsystem that does the logging that subsystem could introduce its own
> synchronization. It would of course not be synchronized with all other
> users of the UL framework, but I don't think that is such a big problem.
>
> Having said that, I am not against introducing multi-line logging
> support in the UL framework. I just would like to make sure that it does
> not come with a too high cost for all the use cases where the
> synchronization is not a problem.
>
> Using a buffered logger, as is being discussed now, would probably be a
> good solution since it wouldn't introduce a cost for the other logging.
>
> Bengt
>
>
>
>>
>> David
>> -----
>>
>>> Bengt
>>>
>>>>
>>>> Thanks,
>>>> Coleen
>>>>>
>>>>> — John
>>>>
>>>
>