Logging revisited.

Hi, I am back again with my rant about logging as an inherent part of any application design and development. I am a big fan of strong basics, and in my humble opinion logging is one of those often overlooked but basic critical element of any enterprise grade application. I have written about this before here. This article was also reproduced at javalobby at this link. They are not really mandatory read to make sense of the current article, but it might help to give them a cursory look, to set context for this article.

In the first article, I introduced logging as a high benefit, low cost alternative to the omnipresent System.out.println(), that all java folks love so much. I had used log4j in that article. Log4j is a solid framework and delivers on it's promise. In all the years that I have used it, it has never let me down. I can whole heartedly recommend it. However, having said that, there are few alternatives also, which have been around in the market for a while and I am happy to say that at least one of them seem to be challenging log4j in it's own turf. I am talking about Logback.

It is certainly not new kid in the block - and that is one of the reasons I am suggesting you consider this for enterprise grade applications to start with. A quick look at Maven Central suggests that the first version was published way back in 2006. Between 2006 and 8-June2012 - which is when the latest version was pushed to Maven Central, there have been 46 versions. Compare this with log4j. The first version was pushed in Maven Central in 2005 and the last on 26 May 2012, and between these there have been a total of 14 different versions. I do not mean to use this data to compare these two frameworks. The only intent is to assure the reader that Logback have been around long enough and is current enough to be taken seriously.

Being around is one thing and making your mark is different. As far as ambition and intent goes, Logback makes it pretty clear that it intends to be successor of log4j - and says that in clear words at it's homepage. Of courser there is an exhaustive list of features / benefits that Logback claims over Log4j. You can read about them at this link. That's it really. The point of this article is that I am suggesting that while designing and developing a enterprise grade java based applications, look at logging a bit more carefully and also consider using Logback.

A few of the audience at this point, I am hoping, will like to roll up their sleeves, fire up their favorite editor and take Logback out for a spin. If you are one of them, then you and I have something in common. You might want to read on.

The very first thing that Logback promises is faster implementation (at this link). Really? I would like to check that claim.

I start by creating a vanilla java application using Maven. 

File: MavenCommands.bat

call mvn archetype:create ^
 -DarchetypeGroupId=org.apache.maven.archetypes ^
 -DgroupId=org.academy ^
 -DartifactId=logger

This unfortunately is preloaded with JUnit 3. I set up JUnit 4 and also add Contiperf, so that I could run the tests multiple times - something that would come in handy if I were to check performance.

File: /logger/pom.xml

[...]

                                                          
 UTF-8
        4.10         
        2.2.0
 [...]                           
                                                   

[...]
                         
                    
                           
 junit           
 junit     
 ${junit.version}
 test                
                                                         
     
                                
 org.databene         
 contiperf      
 ${contiperf.version} 
 test                     

Also, I like to explicitly control the java version that is being used to compile and execute my code.

File: /logger/pom.xml

[...]

2.0.2
1.7                                    

[...]

 
                                                        
 org.apache.maven.plugins                 
 maven-compiler-plugin              
 ${maven-compiler-plugin.version}         
                                              
  ${java.version}                        
  ${java.version}                        
                                             
 

Last of configurations - for the time being. Slap on surefire to run unit tests.

File: /logger/pom.xml

[...]

2.12                                

[...]

                         
                                                        
 org.apache.maven.plugins                 
 maven-surefire-plugin              
 ${maven-surefire-plugin.version}         
                                               
                                              
   org.apache.maven.surefire        
   surefire-junit47           
   ${maven-surefire-plugin.version} 
                                             
                                              
                                              
  -XX:-UseSplitVerifier
                                             
        

Please note, I have taken the pains of adding all these dependencies to this article with their versions, just to ensure that should you try this yourself, you know exactly what was the software configuration of my test. 

Now, let us finally add the unit tests.

File: /logger/src/test/java/org/academy/AppTest.java

public class AppTest {                                 
 private final static Logger logger = LoggerFactory 
   .getLogger(AppTest.class);                 
                                                       
 @Rule                                              
 public ContiPerfRule i = new ContiPerfRule();      
                                                       
 @Test                                              
 @PerfTest(invocations = 10, threads = 1)           
 @Required(max = 1200, average = 1000)              
 public void test() {                         
  for(int i = 0; i<10000 ; i++){          
   logger.debug("Hello {}", "world.");        
  }                                              
 }                                                  
}  

So, we have used the logger in my unit test but have not added an implementation of logger. What I intend to do is to add log4j (with slf4j) and logback (with inherent support of slf4j) one by one and run this simple test multiple times to compare performance.

To add log4j I used this setting.

File: /logger/pom.xml

                                
 org.slf4j            
 slf4j-api      
 ${slf4j.version}     
                               
                                
 org.slf4j            
 jcl-over-slf4j 
 ${slf4j.version}     
 runtime                  
                               
                                
 org.slf4j            
 slf4j-log4j12  
 ${slf4j.version}     
 runtime                  
 

and for logback I used this setting.

File: /logger/pom.xml

                                
 ch.qos.logback       
 logback-classic
 ${logback.version}   
   

with the following versions.

File: /logger/pom.xml

1.6.1    
1.0.6

For either of these logger framework to actually log anything you will have to add a file telling loggers what to log and where.

File: src/main/resources/log4j.properties

# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=DEBUG, A1

# configure A1 to spit out data in console
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout 
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c - %m%n

Finally, for the moment of truth. I ran the tests thrice with each framework i.e. logback and log4j. Essentially I log.debug() a string 1000,000 times in each test and timed them. And this is how the final figures came out.

Framework	1st run	2nd run	3rd run
Logback	0.375 seconds	0.375 seconds	0.406 seconds
Log4j	0.454 seconds	0.453 seconds	0.454 seconds

As far as this little experiment goes, Logback clearly performs faster than Log4j. Of course this is overly simplistic experiment and many valid scenarios have not been considered. For example, we have not really used vanilla log4j. We have used log4j in conjunction with the slf4j API, which is not quite the same thing. Also, being faster is not the only consideration. Log4j works asynchronously (read here and here) whereas as far as I know Logback does not. Logback has quite a few nifty features that Log4j does not.

So, in isolation this little code does not really prove anything. If at all, it brings me back to the first point that I made - Logback is a serious potential and worth a good look if you are designing / coding an enterprise grade java based application.

That is all for this article. Happy coding.

Want to read on? May I suggest ...

The first article of this series. 

10 tips for application logging.

How to exclude commons logging easily
A nice tip on boosting performance of  NOT logging.

If you want to get in touch, you can look me up at Linkedin or Google + .