Hi
Comments below.
/Fredrik
On 2014-05-19 00:55, Kirk Pepperdine wrote:
My primary objection with the current specification is that the JEP is both
over-reaching and restrictive. It suggest taxonomy a closed hierarchical
taxonomy instead of a more open and flexible arrangement. The JEP overreaches
in that it defines or suggests extremely limited levels which are all
completely devoid of context or context that allow one to pull out certain
pieces of information in exclusion to other pieces of information. It also
allows for developers to make very arbitrary decisions as to what to log at
each “levels”. Where as PrintAdapativeSizingPolicy gives a very clear
indication as what will be logged, G1.logging=WARNING is… well... I don’t know
what is and is not suppose to be included. In addition, maybe
PrintAdaptiveSizingPolicy is not interesting but PrintTenuringDistribution is.
And lets say they are both at WARNING log level. Even better, lets say that
with CMS you get PrintTenuringDistribution at FINE and with G1 you get it at
FINEST. The point of all this is the logging framework is complicating
questions that are none of it’s concern. So I would suggest that the logging
framework get out of the business of trying to predefine categories of logging,
especially hierarchical categories of logging.
With the hierarchical logger design proposed in the JEP I cant see why you
could not get the behaviour you're asking for. By targeting sub/child loggers
it is possible to enable/disable arbitrary levels in the tree. And at the same
time you could enable logging for lets say all GC related activity by enable
the top most logger (root). It is possible to create sparse configurations
including/excluding single loggers.
I think that pub/sub is a much simpler model that is easier to understand than
what you’ve described.
I don't think the difference is that big. Enabling logging on a logger is
essentially the same as subscribing to a topic.
the only exception is that the JEP eliminates all possibilities besides the
topics that the JEP decided are “needed”.
The JEP does not specify or enforce any specific loggers. The loggers
mentioned in the JEP are all just examples on how the naming scheme
could look like. It is up to the developers to add loggers whenever they
are needed. Adding a logger is as easy as adding one line of text in a
header file.
The logger hierarchy does not need to be 'component oriented' even if I think
it makes the most sense.
I think you put far too much emphasis on log levels.
Funny but I think the spec puts far too much emphasis on log levels.
Loggers and Adapters are the most important things in the JEP. Log levels are
just to a way to select the verbosity of the output.
So my argument has been, why not just use user defined topics to select the
verbosity? The topics will have semantic meaning where as these predefined
levels have none.
The log levels will only have a meaning in the sense of selecting
verbosity of the output, not selecting the type of output. The
-XX:PrintGCXXXX flags of today would correspond to a logger, not a log
level.
Log levels should not be used to categorise information.
In practice they do categorize information because there is no other practical
way to categorize it. I set verbosity to debug because I expect all debug
messages to show up.
It should be used to select the verbosity of the log data output.
I guess to understand this further I’d need to see an example of how it would
be used. For example, this is a single G1GC event
1.047: [Full GC (System.gc()) 17M->3728K(13M), 0.0212570 secs]
[Eden: 18.0M(24.0M)->0.0B(5120.0K) Survivors: 0.0B->0.0B Heap:
17.2M(256.0M)->3728.7K(13.0M)]
How would you suggest that the JVM use the logging framework to log this
message?
This information should probably be logged in the 'info' level since the
purpose of the information is to provide information. Maybe 'debug' level could
be used to log even more information about how the numbers were computed.
This information is logged at PrintGCDetails level in the 1.8 and at
PrintGCDetails PrintGCCause in the 1.7.0_45 and better. There is more detail
available but that comes to you via different flags. For example adaptive
sizing and reference processing. Are these both debug and if so how could I get
one without getting the other?
We could have 'gc_instrumentation_details', 'gc_instrumentation_cause'
and 'gc_instrumentation_XXXX' loggers defined. All logging on 'info'
level as default. Logging using 'debug' and 'trace' level could add even
more details on each type of information if needed. Again, the GC
logging is only one use of this logging framework, and it happens to be
a bit special. More like a form of instrumentation than classic logging.
There are many other parts of the JVM that needs logging in a more
traditional way.
We have only five levels of verbosity in the JEP (plus disabled). I think that
is a well balanced number.
I don’t know how to respond to this without risking sounding inflammatory and
I’d really like not like to be inflammatory. ;-)
Well, you just did ;)
By pre defining all available loggers(categories) in the source code we
actually give the user the possibility to enumerate all those, and see what
different type of information that are in there.
Why do you need to know levels prior to iterating? Pub/Sub does not come with
this requirement.
If you are not to get a lot of noise/unwanted information you would have to
know what topics to subscribe to. I can't really see the difference here. its
like saying that you want news, and then start subscribing to all newspapers.
You will get news, but a lot of it you're not interested in.
What I’m saying is that of course one is going to have to know what to
subscribe to. As it is one needs to know which flags should be set if you need
to get a information from the JVM. If I subscribe to the wrong topics then for
sure I’ll get information that you don’t want or need. However if I happen to
subscribe to debug, I’m very certain to get information that I neither want nor
need. In either case it will not relieve the developer to document what is
being logged so the consumer understand what is being produced.
Agreed. Documentation must still be there. But having the system knowing
what topics there are in runtime will open up for some really nice
features I think. The ability to enumerate loggers/topics can be very
useful.
On top of that we get compile time checks of that its valid.
Your proposal would require any module implementer to carefully document all
'tags' used in some place in some way. The latter would not make it easier for
users, it would make it even worse than it is today.
What I read here, and maybe I’m reading it wrong, is that the log levels are
used to categorize messages and that simply using your predefined tags
alleviates developers from carefully documenting the information that is
included with each tag/level. This is exactly one of the bigger problems that I
see in the field. Developers drop things into a log level and they don’t
document what comes with each level. You can’t relieve developers of the
responsibility of documenting what will happen when I turn the logging level to
debug (or some other level).
Log levels aren't used to categorize anything They are used to select verbosity
of the output. Loggers are what is used to categorize the information/messages.
Most of the GC logging discussed would as I see it end up in the 'info' log
level in a couple of loggers, maybe corrsponding todays -XX:+PrintXXX. Debug
logging and even more verbose information would be put in the debug and trace
level. The latter two is nothing normally used to get GC data/instrumentation
into log files.
Instead I believe it is more useful for the framework to support more of a
pub/sub model where each of the frameworks or components in the JVM are free to
devise a logging scheme or taxonomy that makes sense for that component.
This would not be something targeted by this JEP. The JEP title is: *Unified*
JVM Logging. what you describe is similar to what we have today. All modules
have their own way of doing logging. This whole discussion is about addressing
that problem, not making it a rule. I have gotten heaps of feedback from
developers asking me to bring an end to this arbitrary 'log as you like'
situation they live in today.
I’m not advocating what is in the JVM today. Unifying the logging scheme makes
sense. It allows for better standardization of tooling, just like we have with
JMS client technology.
Well if we leave it up to each module to devise a logging scheme and the
taxonomy for its logs, in what way would this make the logging more unified?
It would provide a common framework for logging. For example, GC logging can be
directed to a log file where JIT information can only be written to stdout. One
of the tasks would be to allow me to pump the information to a file, stdout, a
JMX client or anything else that I might see fit to write an adaptor for. The
information should come to the sink point in a coherent manner. IOWs, what we
see in GC logging is that incomplete messages are delivered to the sink and
then another event interrupts, that event gets pushed out, either in it’s
entirety or maybe not and then maybe you get the terminating information from
the interrupted event. I would expect the common framework to help prevent this
type of “corruption” from occurring.
Much of what you mention here I would class as bugs. Fixing disrupted
and fragmented log output due to concurrency issues isn't the main
purpose of this JEP, its just one small part of it.
The concept of Adapters mentioned in the JEP opens up for developers to
add more ways of getting the data out from the JVM. The initial goal is
to provide console logging and logging to file. I can see more Adapters
further down the road. Syslog adapter for *nix systems and an EventLog
adapter for Windows are natural candidates. Adapters for JMX, JFR and
sockets might be added later.
For example, Twitter provides a communication platform. By convention we all
use @ and # to specify targets and subjects. Imagine if Twitter limited all #
tags to be Fine, Finer and Finest. It’s a thought that is so crazy you wouldn’t
even consider it. Twitter does *not* try to define what those targets and
subjects are as there is not reasonable way in which it can. So it’s not an
accident that these decisions are left up to the users to decide. I’m not
suggesting the JVM logging framework copy Twitter. I’m merely using it as an
example of an open and flexible logging system.
Again I think you are confusing log levels (verbosity) with loggers. Log levels
are not depicting information topics, or the actual source of the information,
log levels should be used to filter the amount of information about one topic.
Again, rightly or wrongly this is the way that loggers get used because
categorization is not part of the design.
If we leave the log levels out for a moment. I cant see the real difference
between using loggers and @/# to categorise the logged information. I only see
positive things ordering the information in a hierarchy where possible and
desirable.
This isn’t rallying against hierarchies as I see positive things in them as
well. That said, a topic pub/sub based system would not prevent you from
devising the scheme should that be appropriate where as a non-hierarchical
based system cannot be fitted on top of a hierarchical one. Since neither of us
know how logging will evolve in the future it seems to me that moving to the
more flexible scheme is making it more likely to be adaptive to what ever that
change looks like.
There is nothing in the JEP that forces development to add loggers in
hierarchy. It is just a possibility to be used where it makes sense.
I know Log4J is very well liked until you get bit in a$$ by it.. and I run into
projects on a regular basis that have gotten bitten very hard. I include an
entire section of my performance tuning course to the subject and I have to say
that a number of organizations have changed how they log as a result. BTW,
being in the majority just means you’re in the majority, it doesn’t mean the
majority is correct. I shan’t bore you with historical evidence to that point
;-)
Sure, you're probably right about some cases suffer from this design. Question
is if the JVM logging would be better off with something radically different
from the design I present in this JEP? We are not aiming to be non-intrusive
with this framework. There are other more viable solutions to that problem.
I believe the JVM would be better off with a different design which is why I’m
making arguments to at least explore the alternative to see what they might
look like. I’d also like to bring others into the discussion that have
experiences here and may not normally engage in discussions on JVM forums. For
example Neal Ford has some excellent talks w.r.t creating taxonomies for
systems. I posted a link to one of his talks (JFokus edition I believe) when
the JEP was first released. I don’t really want to call out other people
because they may not have the time at this moment to participate. However I
hope they do inject their expertise in this area because we’re going to have to
live with what comes out of these discussions for a very long time to come.
Agreed, the long term impact is the main reason for me to have this JEP
discussion in the open.
Agreed, I don’t believe this JEP should be in the business of specifying
payload.. but the text in the JEP would seem to prohibit it.
That should be fixed in the JEP text. It should say something like that in a
first step human readable data is the goal.
But why specify anything about payload at all? If you feel the need to add
things shouldn’t that be contained in a header that would be separate from the
payload?
The type of payload used when logging impacts the actual data types in
the API. In the current API we are implementing a scheme similar to
printf() since it is a well known, and liked way of formatting information.
The JEP tries to set up goals to be completed, so it has to put
restrictions on some things to be able to reach all the way. If needed
we could add support for binary data in the API, but I still haven't
seen any use case needing it.
Cheers
/Fredrik
