Logging in general
7 views
Skip to first unread message
Ewald Horn
Jul 9, 2012, 4:55:16 AM7/9/12
to CTJUG-Tech
Hi.
Quick question regarding logging and effort around making it more
effective and less intrusive.
I'm working on older code bases where LOG4J is being used as a logger.
It works great, but I believe there are some performance penalties
hidden in the usage pattern. This is of course difficult to prove on a
single machine without writing extensive test cases, but I have the
following coding pattern:
For ALL logging statements that are run at DEBUG level, and that
concatenate a String object, I put a wrapper (isDebugEnabled()) around
them to avoid the String concatenation where possible. This makes
sense as it's a common practice when using LOG4J. Same obviously goes
for INFO level events, with the isInfoEnabled() method. From what I
can tell from small JUnit tests, this does seem to make a difference
over many iterations that simulate the behaviour of a server
application.
Now I'm looking at a code base where the developers have cleverly
written a bunch of logging statements using the ERROR level logging
feature, for example, logger.error("The current user is : " + USER_ID
+ " " + USER_NAME) - just an example, not actual code. The idea is
that they only want this information if ERROR level logging is
enabled, which I fully understand. Surely these should be wrapped in a
isEnabledFor() call as well though, as they will still incur the same
penalties that a DEBUG or INFO level logging call will have. This is
easy to verify by just examining the source code for LOG4J.
Has anyone done any real checking regarding this? I know there are
other logging frameworks, but I can't motivate a switch to a new
logger, but I think a revisit of the current logging statements are in
order as these String concatenations must surely add up to something
expensive over the lifetime of an application? Or is it a case of too
much effort for too little gain? I'm wondering if it's worth the
effort to start the long debate about this, and to fight for the time
to update hundreds of logging statements. A case study or two would go
a long way towards building a convincing argument that this is a
better standard in the long run.
Best regards,
Ewald
Quick question regarding logging and effort around making it more
effective and less intrusive.
I'm working on older code bases where LOG4J is being used as a logger.
It works great, but I believe there are some performance penalties
hidden in the usage pattern. This is of course difficult to prove on a
single machine without writing extensive test cases, but I have the
following coding pattern:
For ALL logging statements that are run at DEBUG level, and that
concatenate a String object, I put a wrapper (isDebugEnabled()) around
them to avoid the String concatenation where possible. This makes
sense as it's a common practice when using LOG4J. Same obviously goes
for INFO level events, with the isInfoEnabled() method. From what I
can tell from small JUnit tests, this does seem to make a difference
over many iterations that simulate the behaviour of a server
application.
Now I'm looking at a code base where the developers have cleverly
written a bunch of logging statements using the ERROR level logging
feature, for example, logger.error("The current user is : " + USER_ID
+ " " + USER_NAME) - just an example, not actual code. The idea is
that they only want this information if ERROR level logging is
enabled, which I fully understand. Surely these should be wrapped in a
isEnabledFor() call as well though, as they will still incur the same
penalties that a DEBUG or INFO level logging call will have. This is
easy to verify by just examining the source code for LOG4J.
Has anyone done any real checking regarding this? I know there are
other logging frameworks, but I can't motivate a switch to a new
logger, but I think a revisit of the current logging statements are in
order as these String concatenations must surely add up to something
expensive over the lifetime of an application? Or is it a case of too
much effort for too little gain? I'm wondering if it's worth the
effort to start the long debate about this, and to fight for the time
to update hundreds of logging statements. A case study or two would go
a long way towards building a convincing argument that this is a
better standard in the long run.
Best regards,
Ewald
Chris
Jul 9, 2012, 5:26:39 AM7/9/12
to ctjug...@googlegroups.com
I think it is highly unlikely that you would ever want to set the logging level to FATAL on a live server, or even to anything below the level of INFO. So for debugging I think it is worth the extra check of isDebugEnabled() as the String manipulation is costly.
IMO I'm not convinced it is worth doing this for ERROR level logging though as I don't know why you would not want this level of logging in a live application.
As far as using another logging framework, logback appears to be the new log4j (http://logback.qos.ch/reasonsToSwitch.html). AFAIK Log4j has been inactive for quite a while.
Like you say in your mail, I'm not sure its worth the change of framework unless the cost benefits out way the cost of changing so much old code. If performance is an issue, a POC could persuade the powers that be, that a framework change is needed.
Cheers
Chris
IMO I'm not convinced it is worth doing this for ERROR level logging though as I don't know why you would not want this level of logging in a live application.
As far as using another logging framework, logback appears to be the new log4j (http://logback.qos.ch/reasonsToSwitch.html). AFAIK Log4j has been inactive for quite a while.
Like you say in your mail, I'm not sure its worth the change of framework unless the cost benefits out way the cost of changing so much old code. If performance is an issue, a POC could persuade the powers that be, that a framework change is needed.
Cheers
Chris
--
You received this message because you are subscribed to the Google Groups "CTJUG Tech" group.
To post to this group, send email to CTJUG...@googlegroups.com
To unsubscribe from this group, send email to CTJUG-Tech+...@googlegroups.com
For more options, visit this group at http://groups.google.com/group/CTJUG-Tech?hl=en
For Cape Town Java User Group home page see http://www.ctjug.org.za/
For jobs see http://jobs.gamatam.com/
Dr Heinz M. Kabutz
Jul 9, 2012, 5:39:37 AM7/9/12
to ctjug...@googlegroups.com
The String is first constructed and then passed into the log() method.
So yeah, you should use code guards (if (log.isDebugEnabled()) etc.)
when you write logging statements.
Regards
Heinz
--
Dr Heinz M. Kabutz (PhD CompSci)
Author of "The Java(tm) Specialists' Newsletter"
Sun Java Champion
IEEE Certified Software Development Professional
http://www.javaspecialists.eu
Tel: +30 69 75 595 262
Skype: kabutz
So yeah, you should use code guards (if (log.isDebugEnabled()) etc.)
when you write logging statements.
Regards
Heinz
--
Dr Heinz M. Kabutz (PhD CompSci)
Author of "The Java(tm) Specialists' Newsletter"
Sun Java Champion
IEEE Certified Software Development Professional
http://www.javaspecialists.eu
Tel: +30 69 75 595 262
Skype: kabutz
Michael Wiles
Jul 9, 2012, 5:42:42 AM7/9/12
to ctjug...@googlegroups.com
And it's probably good practice to have a blanket policy of _always_ have the code guard. Regardless of the logging level. Once you get passed 3 people in your team you want to simplify code conventions.
The other problem is that when you change something from error to info or something people might not realise they need to put the if in and so you might get some logging statements which are not wrapped. You want to avoid that.
--
You received this message because you are subscribed to the Google Groups "CTJUG Tech" group.
To post to this group, send email to CTJUG...@googlegroups.com
To unsubscribe from this group, send email to CTJUG-Tech+unsubscribe@googlegroups.com
For more options, visit this group at http://groups.google.com/group/CTJUG-Tech?hl=en
For Cape Town Java User Group home page see http://www.ctjug.org.za/
For jobs see http://jobs.gamatam.com/
Ewald Horn
Jul 9, 2012, 5:50:32 AM7/9/12
to ctjug...@googlegroups.com
Hi.
Thank you for the replies, I figured I might be the only one pedantic
about it and am relieved to see it's not the case.
I'll do some tests and post the results if meaningful.
Best regards,
Ewald
Thank you for the replies, I figured I might be the only one pedantic
about it and am relieved to see it's not the case.
I'll do some tests and post the results if meaningful.
Best regards,
Ewald
Reply all
Reply to author
Forward
0 new messages