hotspot.log overlapping log statements (JITWatch) (original) (raw)

John Rose john.r.rose at oracle.com
Wed Feb 26 00:32:40 PST 2014

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 printcr 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->asklassexternalname() : "NoName"); if (cfs->source() != NULL) tty->print(" from %s", cfs->source()); tty->printcr("]"); } If you know [ and ] are delimiters then that helps but the "from %s" is not delimited.

Output might look like: ... [Loading bauxite la la la la la da from the open pit. la da da la la da ] ...

After untangling the different writer streams, you get:

[Loading bauxite from the open pit. ]

and then

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:

[Loading bauxite la la la la la da from the open pit. la da da la la da ]

The untangled output from thread 6 would be: [Loading bauxite from the open pit. ]

It would be easy to process the tokens suitably.

— John

More information about the hotspot-dev mailing list