RFR: 8141211: Convert TraceExceptions to Unified Logging

[Rachel Protacio]

Hello, everyone!

I've filed an RFE for this issue. 
https://bugs.openjdk.java.net/browse/JDK-8145934

It'll probably be easier to continue the discussion there.

Thanks,
Rachel

On 12/18/2015 8:29 AM, Staffan Larsen wrote:
>
>> On 18 dec. 2015, at 14:06, David Holmes <david.holmes at oracle.com 
>> <mailto:david.holmes at oracle.com>> wrote:
>>
>> 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 <mailto: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.
>
> Have you seen this happen with UL as well?
>
>>
>> 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
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/serviceability-dev/attachments/20151221/a114683f/attachment-0001.html>