Logging JEP

[Fredrik Arvidsson]

Hi Kirk

Please see my comments in-lined below.

This starts to become a wall of text. TL; DR; warning...

On 2014-05-18 19:57, Kirk Pepperdine wrote:
> Hi Fredrik,
>
> comments below…
>
> Regards,
> Kirk
>
>>> 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 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.
>> 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.
>
>> 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.
>> 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?
>>> 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.
>
>> I don't think Twitter is a good analogy in this case. If I got as much unwanted and unrelated noise/crap in my log output as on Twitter I would be a very unhappy user.
> No analogy works perfectly but there are aspects of the analogy that I do believe are valid. If I subscribe to listen anything you pump out, I see it. If I don’t want to see it any more, I can unsubscribe. Twitter hash tags are interesting in that twitter is not predefining them. Somehow I have to document and publish the fact that I’m publishing information out on an hashtag. One other aspect that I do like is limiting to 140 characters (which would do wonders to improve logging) but that is an aside and I don’t really want to get bogged down in this analogy if it doesn’t happen to work for you.
140 characters per line is an exciting idea. I agree it would improve 
the logging very much.
>>> I spoke to two people about logging while at GeeCon last week. The first was Peter Lawrey, the author of JChronicle. JChronicle is a messaging framework but Peter has written a Log4J adaptor for it. I’ve been begging him *not* to release it as I think it would comply obscure the excellent work that put into JChronicle in making it a truly high throughput low latency messaging. I think he’s been thinking about a better interface for it.
>> It would be very interesting to have feedback directly from Peter. I don't know the JChronicle product so I cant really comment. What I do know is that Log4J is a very liked and well used framework, much too big, dynamic and complex for our use. But there was probably a reason for Peter trying to provide his users with that functionality. People are using it, and they love it.
> 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 also spoke to Michael Feathers who gave the keynote where he focused on no error handling in an application. We both agreed on the egregious state of application logging. It’s so bad that I’m constantly running into applications where the primary bottleneck is in how logging has been implemented. One of the key problems is the use of this hierarchal log levels with no guidelines as to what should appear at each level. Thus to get any information out of the application, one must eat an entire elephant. It’s a deplorable situation.. and while one can blame developers I could also say that frameworks should guide developers to good decisions, not pull them away from them.
>> As I mentioned before I think we are addressing the 'Elephant' issue by using sub loggers. Again, and I'm not trying to be repetitive here, I think you confuse log levels as in verbosity with loggers(categories).
>> I am a bit confused about your comment that you would like to let each module decide how and what to log, and then in the above text you say 'log levels with no guidelines as to what should appear at each level'. How would your first proposal make this easier in any way? Putting the descision on how and what to log in the hands of tens (in worst case hundreds) of individual developers would not make logging better I think. It would make it even more sprawling and hard to use. We would get as many logging standards as there are developers multiplied with the number of modules using logging.
> Indeed but if you take on that problem this framework will only serve to make the problem worse. Log4J and ilk all use ideas that are old and I think disproven by a number. Unfortunately they currently have momentum and momentum is a difficult thing to reverse. Also re-implenting the past isn’t really driving the platform forward.
Old ideas are not necessarily bad. If it works, why try to mend it?
>>> Did I mention no, support for or mention of binary in the spec. I’ve nothing against text based logging.. except the fact that it’s often information sparse. You certainly should be promoting formats that are as information dense as it make sense for your environment/requirements and there is often nothing more information dense than a binary format.
>> This is an interesting note. I have not gotten this requirement from any of the many hotspot developers I interviewed during my information gathering.
>> Personally I am not sure this type of information dense logging should be a part of this JEP.
> 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.
>> There are other mechanisms already implemented that does that kind of stuff way better, like JEP-167 :)
> Certainly it would be interesting to see how to tie this JEP with 167 as I think there is a lot of synergy.
>
> Regards,
> Kirk
Cheers
/Fredrik