hotspot.log overlapping log statements (JITWatch)

[John Rose]

On Feb 25, 2014, at 10:25 PM, David Holmes <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