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
