hotspot.log overlapping log statements (JITWatch)

[David Holmes]

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
>