hotspot.log overlapping log statements (JITWatch)

[Staffan Larsen]

Just for reference I’d like to throw in a link to JEP 158: Unified JVM Logging: http://openjdk.java.net/jeps/158. Things like this would be good to fix as part of that project.

/Staffan

On 26 feb 2014, at 07:25, 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.
> 
> David
> -----
> 
> David
> 
>> Another example I found was:
>> 
>> [Entry Point]
>> [Constants]
>>   # {method} &apos;ind
>> <writer thread='3340'/>
>> [Loaded sun.nio.cs.ThreadLocalCoders from C:\Program
>> Files\Java\jre7\lib\rt.jar]
>> <writer thread='2660'/>
>> exOf&apos; &apos;(II)I&apos; in &apos;java/lang/String&apos;
>>   # this:     ecx       = &apos;java/lang/String&apos;
>>   # parm0:    edx       = int
>>   # parm1:    [sp+0x20]   = int  (sp of caller)
>>   0x009e07e0: nop
>> 
>> but even here the XML and classloader logs can be identified and I can
>> reform the assembly without too much hassle.
>> 
>> Kind regards,
>> 
>> Chris
>> 
>>> 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
>> 
>>