Tuesday, January 8, 2013

Log4J vs. own ApplicationLogger

Very often I found that projects are using own layer of logging on top of Log4J. I understand that everyone wants to be independent however sometimes we need to ask our-self simple question: why?
Here you could find simple example & test how much you can achieve by not introducing that layer.
I'll compare two instances: Log4J and AppplicationLogger in "production like" scenario - means log is switch on on INFO level. And this is quite predictable calculation: how much time can we get by not calling separate methods...
Test:
 @Test
 public void loggerTest(){
  int TIMES = 1000000;
 [...]
  System.out.println("x");
  s1=System.currentTimeMillis();
  for (int i=0; i<TIMES; i++) {
   Log4JStandardMethod("666");
  }
  e1=System.currentTimeMillis();

  System.out.println("x");
  s2=System.currentTimeMillis();
  for (int i=0; i<TIMES; i++) {
   AppLoggerStandardMethod("666");
  }
  e2=System.currentTimeMillis();
[...]
 }

        void Log4JStandardMethod(String id) {
  if (log4J.isDebugEnabled()) log4J.debug("Just some addition: " + 13);
  
  if (log4J.isDebugEnabled()) log4J.debug("Details are:  " + id + 
    " System: " + id + "  date: " + 14);
  
  if (log4J.isDebugEnabled()) log4J.debug("Size of messages for: " + id + " is: " + 15);
  if (log4J.isDebugEnabled()) log4J.debug("Size of messages for: " + id + " is: " + 16);

 }

 void ApplicationLoggerStandardMethod(String id) {
  String strMethodName = "AppLoggerSimpleMethod";
  appLogger.logDebug("Just some addition: " + 13, strClassName, strMethodName);
  
  appLogger.logDebug("Details are:  " + id + 
    " System: " + id + "  date: " + 14, strClassName, strMethodName);
  
  appLogger.logDebug("Size of messages for: " + id + " is: " + 15, strClassName, strMethodName);
  appLogger.logDebug("Size of messages for: " + id + " is: " + 16, strClassName, strMethodName);
 }
  
I will skip definition how ApplicationLogger looks, just one method that we are interested in:
    /**
     * Method to log DEBUG level messages
     *
     * @param String strMsg
     * @param String strClassName
     * @param String strMethodName
     */
    public void logDebug(final String strMsg, final String strClassName,
        final String strMethodName) {

     if (!this.logger.isEnabledFor (Level.DEBUG))
      return;

        this.logger.log (Level.DEBUG, new StringBuffer ().append (strClassName)
                .append (strMethodName).append (strMsg));

    }

Output:
Log4J : 161 ms
ApplicationLogger: 1050 ms
 Difference in code is very small:
  • Log4J - there is method isDebugEnabled() before each debug line;
  • ApplicationLogger - we must put some additional params: information about method/class, and check for log level is done in Logger method 
Of course if you will introduce isDebugEnabled method in your ApplicationLogger - that will speed up solution, however you will finish with rewriting all Log4J methods.
Second thought is: if you want different formatting of your log ... I'm pretty sure you can do this by proper configuration of your logger.
See: http://logging.apache.org/log4j/
And new performance improvements to Log4J 2.x.

No comments:

Post a Comment

Web 3 - blockchain layers

Layers from a blockchain perspective. My plan is to write 5 articles:  1 Intro: Web 1.. 2.. 3.. 2 Layers in crypto.  [this one] 3 Applicatio...