hotspot.log overlapping log statements (JITWatch)

[John Rose]

On Feb 24, 2014, at 10:54 PM, David Holmes <david.holmes at oracle.com> wrote:

> If all the trace/logging output is directed to the default output stream (or the same file) then they will be intermixed. Fixing this would be non-trivial due to the need for explicit locking around compound trace/logging statements; and locking in tracing/log output can itself be problematic.
> 
> Using different log files where possible would assist, but then you have no temporal relationship between the different entries.

Yes, that is the essential trade-off between logging global order and capturing separate streams of information.

The JVM's internal "tty" mechanism is designed to serialize reported output into one order, which (arguably) is a logging function.

When large blocks of output appear, we don't want to cause other components to hang until the output is all out.  That would disturb timing more than we want.  (At least, that's the current theory.)

So the compromise is to allow output to be broken up the way Chris points out.

In the log format, newlines and tags are used to separate the output from different threads.

On 21/02/2014 7:46 AM, Chris Newland wrote:
> Hi all,
> 
> I've written a visualiser/analyser for the hotspot.log JIT compilation log
> called JITWatch[1] and I'm encountering problems with log statements from
> various parts of the VM/HotSpot overlapping and producing garbled output
> in hotspot.log[2].

What would help you to reconnect the output blocks?  There's not much we can do about the tags and interleaving, but is there a problem reassembling the information?  Should we emit a tag when a line is split?

— John