Need comments on JEP-158: Unified JVM Logging

Tue May 20 07:59:25 UTC 2014

Hi all,

I like you proposal and hope this tracing system turns out well.

I'm with the SAP JVM; we have had our own homebrewn tracing system for
years, which resembles your proposal a lot. If your solution turns out
well, we may decide to abandon our propietary solution in favor of your
proposal.

Here are some aspects we found important over the last years with our
tracing system:

1) tracing during initialization phase.
  When tracing in code which gets executed very early it would be nice to
have a solution which works right from the start. So, argument parsing for
the tracing system should happen as early as possible, or not rely only on
command line arguments.
  Often I found myself tracing initialization code only to find that my
output was not visible, so there was always the question "did I not hit my
code or was the tracing system not yet initialized?" - in the end, due to
time, one often falls back to fprintf.

2) Tracing system should be implemented as "lowest VM layer", without
dependencies to VM infrastructure
  This one is clear and also very important. It also affects all adapters.
  For instance, tracing system should not use os::malloc, because I might
want to trace os::malloc. So, it should be implemented as an independend
module, with no dependencies to other infrastructure.
  This is also related to (1), as it makes it possible to trace right from
VM start without having to wait for VM initialization

3) inactive trace points should not incurr costs

In our tracing system, we have a flat vector of "loggers" which are
controlled by a global bit array; this means that at runtime, any decision
to actually trace costs one memory access to a memory location which
hopefully is already cached. Simple and stupid, but it works, and costs to
not trace are at a minimum.

In your proposal I would have to call "Log::log()". The logger class has to
be resolved, and its state queried, which, depending on how this is
implemented, may cause more than one memory accesses.

4) Adapters

  This whole thing seems a bit too complicated.
  - Do we really need the ability to attach different adapters to different
Loggers? Would one adapter for the whole VM not suffice?
  - Do we really need the ability to chain adapters, especially chain
different file loggers?
  This seems to me like something the OS does far better than the VM.

  This flexibility would cause a lot of testing effort, and you never can
be sure that you tested all possible combinations. Also timing: different
adapters may show different timing behaviour, and if different loggers may
cause different adapters or combination of adapters, timing of different
trace spots in respect to each other may differ greatly.

  I am also concerned about the reliability of adapters. In my experience,
the tracing backends are a weak spot in a tracing system, especially if one
allows other teams to extend them by writing new adapters.

5) Just cosmetics:

I would prefer the logging calls to be simpler. Instead of writing

Log::log(Log::vm_init(), LogLevel::info(), "Init took %lu ms to complete.",
time);

I would prefer something like

logI(vm_init, "Init took %lu ms to complete.", time);

or for an error:

logE(vm_init, "All is lost.");

Some minor proposals:

6) Shared memory adapter

  I would propose another adaptor (beside stdout and file), which writes to
a preallocated large shared memory segment; overwriting old entries if
full. That shared memory segment could be read from the outside with a
command line tool.

  (Arguably the same could be done with memory file systems, in an OS
dependend way).

7) LogMark

    Log& Log::<logger>().begin_transaction();
    bool Log::<logger>().commit_transaction();

could be wrapped into something like a LogMark, similar to a ResourceMark,
to end the transaction when the stack unwinds.

Kind Regards

Thomas Stüfe

On 18 May 2014 17:29, Fredrik Arvidsson <fredrik.arvidsson at oracle.com>wrote:

> Hi Chris
>
> You will find my comments in-line below.
>
>
> On 2014-05-17 09:47, Chris Newland wrote:
>
>> Hi Fredrik,
>>
>> The discussion I had with David Holmes and John Rose on hotspot-dev back
>> in February might be relevant to this JEP:
>> http://mail.openjdk.java.net/pipermail/hotspot-dev/2014-
>> February/012718.html
>>
> I will use some time to read this discussion. Thanks.
>
>  I'm the author of a JITWatch[1], a JIT compiler log analysis tool which
>> relies on -XX:+TraceClassLoading -XX:+LogCompilation -XX:+PrintAssembly
>> all being present in hotspot.log
>>
>> Occasionally the lack of thread safety in the VM logging presents me with
>> jumbled output:
>>
>> [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' '(II)I' in 'java/lang/String'
>>     # this:     ecx       = 'java/lang/String'
>>     # parm0:    edx       = int
>>     # parm1:    [sp+0x20]   = int  (sp of caller)
>>     0x009e07e0: nop
>>
>> The JEP goal of no interleaving would fix this problem but if the locking
>> adds too much cost/complexity then John's suggestion of tagging partial
>> lines would be a great help to log tool writers.
>>
> There could be several reasons for the current logs to be interleaved I
> think. One reason can be that the lowest level log writing primitives
> aren't thread safe themselves.
> A second reason can be that the current log framework doesn’t provide any
> form of log transactions making it easy for developer to implement the
> logging in a way that guarantees non partial lines in the log.
> JEP-158 tries to address both of these reasons. Thread safety issues can
> be addressed using the leanest locking/critical section technique we can
> have. This might have different solutions depending on platform and log
> adapter in question. The 'broken up log code' is addressed with our log
> transaction which enables the developer to split the actual line of logging
> in to several calls to the log API. The log line is then committed to the
> underlying framework to be written all at once.
>
>
>> Otherwise my only comment is that the goals look like a massive
>> improvement to current VM logging but for post-execution log tool writers
>> it is also useful for end users to be able to easily locate and load a
>> single log file.
>>
> This really captures the intent of JEP-158 I think. We want to have a
> common framework for logging so that all output can be formatted the same
> well defined way, and we want to be able to have a single entry of
> configuration letting users configuring all logging in a consolidated and
> clear way.
>
>  Kind regards,
>>
>> Chris
>>
>> [1] https://github.com/AdoptOpenJDK/jitwatch
>>
>>  Cheers
>
> /Fredrik
>