hotspot.log overlapping log statements (JITWatch)

[David Holmes]

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} '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
>
>