More J2EE programmers know Apache's log4j than java.util.Logger. It's that famous. Having come across the usage of Log4j in several Java/J2EE applications, I kinda figured out that we all know that we should use Log4j, but we really don't know how to effectively use it. So I thought of sharing what I know. Here you go.
How to use Log4? In the rawest form, Log4j can be used as simple as below
- Create a log4j configuration file log4j.xml / log4j.properties in the classpath (source root folder if the java class loader doesn't pick it up) as below
<?xml version="1.0" encoding="UTF-8" ?> <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
<appender name="console" class="org.apache.log4j.ConsoleAppender">
<param name="Target" value="System.out"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%-5p %c{1} - %m%n"/>
</layout>
</appender>
<root>
<priority value ="debug" />
<appender-ref ref="console" />
</root>
</log4j:configuration>
- In your class, just get an instance and start logging as below
Logger barlogger = Logger.getLogger("com.myclass");
logger.warn("Hey this is a warning.");
So whats wrong with this ? Nothing much, except that our real world requirements are a little more complex. In a typical web application following the MVC pattern, we have multiple layers where we perform data access, or execute business logic, or marshal presentation layer information into POJOs, etc. In each of this layer, logging adequate information will simplify the diagnosis of potential issues, especially in applications where you have more calculations to be performed behind the screens. So lets have a look at some of the common issues we face in enterprise applications,
Lets say we have a custom pagination logic and we want to log some complex information like the one below
int currentPage = count / rows) - ((count - first) / rows) + 1;
logger.debug("(count / rows) - ((count - first) / rows) + 1 == ("+count +"/"+ rows+") - (("+count+" - "+first+") / "+rows+") + 1 =="+currentPage);
This would print an output, which would give you a good idea about the calculations behind the scenes, as below
DEBUG Log4jClient - (count / rows) - ((count - first) / rows) + 1 == (100/10) - ((100 - 0) / 10) + 1 ==1
We've got quite a handful of problems here.
- Java creates string literals for each and every + operator used here to concatenate the strings. So just for this one statement, we would have created more than 10 string literals
- Though we would like to have these information during the development stage, when moving to production such DEBUG level logs can quickly eat up the available memory on the server. So ideally we would switch to INFO level and hence Log4j wouldn't even log this. All this string literals we created are of no use.
- Though Log4j wouldn't log this information if the log level is set to INFO, the cost of verifying this implicitly is more. Hence Log4j provides methods like isTraceEnabled(), isDebugEnabled() and isInfoEnabled() which would let us know if these levels are enabled or not. So its prudent to use these methods before proceeding to format our message to be logged.
So looks like we haven't been logging all that efficients so far. What do we log, when we have a real problem? Like we hit an exception like NumberFormatException while parsing a string. One of the applications I came across, logged the exception like this
try{
...
}
catch (Exception e){
logger.error("Exception Occurred"+e.getMessage());
}
Thats very pretty, but unfortunately it missed the point. When you hit an exception, all you need is the stack trace to figure out the problem, which isn't logged here. Using e.printStackTrace() prints the stack trace on the console and not in the log file. So its not suitable for production. A better option is to use the overloaded Log4j methods debug(), info(), warn() or fatal() that also take Throwable as an argument. This would print the complete stack trace, albeit on the log file. Bingo. Thats exactly we need. Stack trace details and not on the console.
What I do to overcome the above issues, is to create a custom logger class that takes care of the above issues and let me log the stuff I want to. Lets create our magic custom layer over Log4j as below
package com.sankar.logger;
import org.apache.log4j.Logger;
public class MyLogger{
Logger logger;
public MyLogger(Class clazz){
logger = Logger.getLogger(clazz);
}
public void trace(Object ... obj){
if (logger.isTraceEnabled())
logger.trace(getString(obj));
}
public void debug(Object ... obj){
if (logger.isDebugEnabled())
logger.debug(getString(obj));
}
public void info(Object ... obj){
if (logger.isInfoEnabled())
logger.info(getString(obj));
}
public void warn(Object ... obj){
logger.warn(getString(obj));
}
public void error(Object ... obj){
logger.error(getString(obj));
}
public void fatal(Object ... obj){
logger.fatal(getString(obj));
}
public void exception(Exception e, Object ... obj){
logger.error(getString(obj),e);
}
private String getString(Object ... obj){
StringBuilder sb = new StringBuilder();
for (Object object: obj){
sb.append(object).append(" ");
}
return sb.toString();
}
}
And lets create a simple client
package com.sankar.logger;
public class Log4jClient {
private static MyLogger sLogger = new MyLogger(Log4jClient.class);
public static void main(String[] args) {
sLogger.debug("Hello World !");
int count = 100, rows = 10, first = 0;
int currentPage = (count / rows) - ((count - first) / rows) + 1;
sLogger.debug("(count / rows) - ((count - first) / rows) + 1 == (",count ,"/", rows,") - ((",count," - ",first,") / ",rows,") + 1 ==",currentPage);
Exception e=new Exception(); sLogger.exception(e, "Oops Sorry :("); }
}
The output is as below
DEBUG Log4jClient - Hello World !
DEBUG Log4jClient - (count / rows) - ((count - first) / rows) + 1 == ( 100 / 10 ) - (( 100 - 0 ) / 10 ) + 1 == 1
ERROR Log4jClient - Oops Sorry :(
java.lang.Exception
at com.sankar.logger.Log4jClient.main(Log4jClient.java:19)
So whats that we have done better here?
- Simple Interface - Our client code has only one line for logging the content without sacrificing any of the best practices
- The MyLogger implementation takes care of checking isTraceEnabled(), isDebugEnabled() and isInfoEnabled() before trying to concatenate the strings. So we save more time and memory by not trying to do stuff for the messages we are not gonna log
- The MyLogger trace, debug, info, warn, error and fatal methods take infinite number of Objects as parameters and concatenates them implicitly, if required. So I don't have to start littering the memory with String literals unnecessarily by using + operator to concatenate the string before logging.
- MyLogger concatenates the Object[] parameters using StringBuilder. StringBuilder is the fastest way to concatenate Strings than StringBuffer as StringBuilder is not synchronized. So no more String literals in the heap and I concatenate them faster too.
- MyLogger provides the exception() method, to log exceptions. It takes the exception object as the first parameter, followed by other objects. So you get the stack trace and also the convenience of sending a big message.
Is there a way to log messages more efficiently ? If you know, please provide your inputs in the comments section and I shall update this blog accordingly.
NOTE:
