[prev in list] [next in list] [prev in thread] [next in thread] 

List:       openjdk-serviceability-dev
Subject:    Re: Need comments on JEP-158: Unified JVM Logging
From:       Fredrik Arvidsson <fredrik.arvidsson () oracle ! com>
Date:       2014-05-21 12:39:47
Message-ID: 537C9E93.20901 () oracle ! com
[Download RAW message or body]

Hi Thomas and thanks for the feedback.

Interesting to see that you already have a design that is so close to 
what we are proposing in this JEP.
I have added some comments in-line below.

On 2014-05-20 09:59, Thomas Stüfe wrote:
> 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.
>
This is of course an implementation specific question, but in my proof 
of concept implementation I initialize the logger framework very early 
in the Threads::create_vm() method which is as early as it gets I think. 
There are some prerequisites for my code that os::init() have been run 
to have Atomic::cmpxchg() available.
> 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
>
We should strive to make the logger implementation having as few 
dependencies to the rest of the vm code as possible. I think it will be 
a balance between having to re-implement and reuse whats in there 
already. One example is the Atomic CAS function I use to implement a 
read-writer lock.
> 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.
>
The loggers in my implementation are statically declared. Loggers and 
all related code is 'generated' by just a few xmacro's at compile time 
and will be low cost to use I hope. A logging call will make one 
comparison to find out if it needs to log or not.
This is something we have to look in to later, and we will have to spend 
some time on optimization I'm sure. But as you say, a good design from 
the start lays the foundation for a good implementation.
>
> 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.
>
I have asked my colleagues about the need to have multiple adapters and 
different adapters for different loggers and it seem there are cases 
when this is desired. I have not yet thought about the test 
implications, but as you say it will be harder to test this 
functionality than if we just had one adapter for all loggers.
>
> 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.");
>
I have experimented some with a couple of macros making logging less 
verbose, it is still not ready though. One thing i added to the macro 
was to check if logging is enabled for the current level on the logger. 
This saves us one call to the logger passing all parameters etc... still 
experimental.
>
>
> 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).

This is definitely a candidate for an adapter. Probably pretty easy to 
implement also.
>
> 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.
>
I will investigate if I can add some support for this. I have done 
similar things before when implementing lock/concurrency primitives and 
they are pretty handy at many times.
>
> Kind Regards
>
> Thomas Stüfe

Cheers
/Fredrik
[prev in list] [next in list] [prev in thread] [next in thread]