hotspot.log overlapping log statements (JITWatch)

[Dmitry Samersoff]

David,

Other option is to write to UDP rather than tty with an appropriate
sequence number.

UDP is much faster than tty and it allows customer to use whole bunch of
UNIX tools that exists around syslog.

-Dmitry

On 2014-02-26 16:35, David Holmes wrote:
> Hi John,
> 
> I really didn't follow how you could untangle arbitrary non-delimited
> text, but I think it will still require changes to the use of the print
> functions to fix it - right? Logically what we want is per-thread
> buffering so that we only do a write() of a full line of text.
> 
> Cheers,
> David
> 
> On 26/02/2014 6:32 PM, John Rose wrote:
>> On Feb 25, 2014, at 10:25 PM, David Holmes <david.holmes at oracle.com
>> <mailto:david.holmes at oracle.com>> wrote:
>>
>>> On 26/02/2014 6:20 AM, Chris Newland wrote:
>>>> Hi John, David,
>>>>
>>>> Thank you for this information.
>>>>
>>>> I think the knowledge that a single line will only ever contain one
>>>> flavour of log output will allow me perform reordering as I parse the
>>>> log.
>>>
>>> I don't have John's confidence that this is indeed the case. A
>>> print_cr obviously ends a line and every print call is processed
>>> atomically (in most cases) due to the underlying ttyLock acquired by
>>> the hold() method.
>>>
>>> However, unless the content of every individual print is indeed
>>> delimited, as suggested by John:
>>>
>>> >> In the log format, newlines and tags are used to separate the output
>>> >> from different threads.
>>>
>>> then things will still be interleaved. Here's an example where this
>>> does not hold in classFileParser.cpp (the first file I looked at):
>>>
>>>    if (TraceClassLoadingPreorder) {
>>>      tty->print("[Loading %s", (name != NULL) ?
>>> name->as_klass_external_name() : "NoName");
>>>      if (cfs->source() != NULL) tty->print(" from %s", cfs->source());
>>>      tty->print_cr("]");
>>>    }
>>>
>>> If you know [ and ] are delimiters then that helps but the "from %s"
>>> is not delimited.
>>
>> Output might look like:
>> <tty>
>> ...
>> <writer thread='6'/>
>> [Loading bauxite
>> <writer thread='1234'/>
>> la la la la la da
>> <writer thread='6'/>
>>   from the open pit.
>> <writer thread='1234'/>
>> la da da la la da
>> <writer thread='6'/>
>> ]
>> ...
>> </tty>
>>
>> After untangling the different writer streams, you get:
>>
>> <writer thread='6'/>
>> [Loading bauxite
>>   from the open pit.
>> ]
>>
>> and then
>>
>> <writer thread='1234'/>
>> la la la la la da
>> la da da la la da
>>
>> The code of thread 6 got three lines due to output switching, but
>> expected to log a single line:
>>
>> [Loading bauxite from the open pit.]
>>
>> We could emit a little more info around the output switch markers like
>> this:
>>
>> <writer thread='6'/>
>> [Loading bauxite
>> <join/>
>> <writer thread='1234'/>
>> la la la la la da
>> <writer thread='6'/>
>>   from the open pit.
>> <join/>
>> <writer thread='1234'/>
>> la da da la la da
>> <writer thread='6'/>
>> ]
>>
>> The untangled output from thread 6 would be:
>> [Loading bauxite
>> <join/>
>>   from the open pit.
>> <join/>
>> ]
>>
>> It would be easy to process the <join/> tokens suitably.
>>
>> — John
>>


-- 
Dmitry Samersoff
Oracle Java development team, Saint Petersburg, Russia
* I would love to change the world, but they won't give me the sources.