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

Staffan Larsen staffan.larsen at oracle.com
Wed Feb 26 00:26:27 PST 2014

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 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. David ----- David Another example I found was: [Entry Point] [Constants] # {method} 'ind [Loaded sun.nio.cs.ThreadLocalCoders from C:\Program Files\Java\jre7\lib\rt.jar] exOf' '(II)I' in 'java/lang/String' # this: ecx = 'java/lang/String' # 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

More information about the hotspot-dev mailing list