Efficient Logging in Java

Logging is very important part of any programming language. It gives important information to developers to understand the program behavior. Its almost next to impossible to debug issues without logs. So logs are very important but logging itself is overhead for any program. It shares valuable CPU time, consume program memory, perform I/O operations. So Logs are necessary evils. 

Various logging framework provide various techniques to reduce these overhead. Common techniques to improve performance

• Configuration Techniques
• Set default logging level to Severe
• On demand enable Logging for specific module
• Programming Techniques
• Use discretion while putting log level for evey log
• Check log level before processing logging command

Recently I come across some other ways to improve logging efficiency. I tried to run few tests around them. Here is test case result:

Test Code using "java.util.logging.Logger"

	package learn.java.logger;
	import java.util.logging.Level;
	import java.util.logging.Logger;
	public class LearnJavaLogging {
	private static final Logger logger = Logger.getLogger(LearnJavaLogging.class.getName());
	public static void main(String[] args){
	logger.log(Level.SEVERE, "Case 1: Start time : {0}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	logger.log(Level.FINE, "Entry number: {0} is ", i);
	}
	logger.log(Level.SEVERE, "Case 1: End time : {0}", System.currentTimeMillis());
	logger.log(Level.SEVERE, "Case 2: Start time : {0}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	if(logger.isLoggable(Level.FINE)){
	logger.log(Level.FINE, "Entry number: {0} is ", i);
	}
	}
	logger.log(Level.SEVERE, "Case 2: End time : {0}", System.currentTimeMillis());
	logger.log(Level.SEVERE, "Case 3: Start time : {0}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	logger.log(Level.FINE, "Entry number: " + i + " is ");
	}
	logger.log(Level.SEVERE, "Case 3: End time : {0}", System.currentTimeMillis());
	logger.log(Level.SEVERE, "Case 4: Start time : {0}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	logger.log(Level.FINE, "Static Log");
	}
	logger.log(Level.SEVERE, "Case 4: End time : {0}", System.currentTimeMillis());
	logger.log(Level.SEVERE, "Case 5: Start time : {0}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	if(logger.isLoggable(Level.FINE)){
	logger.log(Level.FINE, "Static Log");
	}
	}
	logger.log(Level.SEVERE, "Case 5: End time : {0}", System.currentTimeMillis());
	}
	}

view raw LearnApacheLogging.java hosted with ❤ by GitHub

Test Results "java.util.logging.Logger"

	23:36:44.427 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: Start time : 1355249204421
	23:36:44.449 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: End time : 1355249204449
	23:36:44.450 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: Start time : 1355249204450
	23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: End time : 1355249204455
	23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: Start time : 1355249204455
	23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: End time : 1355249204505
	23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: Start time : 1355249204505
	23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: End time : 1355249204506
	23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: Start time : 1355249204506
	23:36:44.507 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: End time : 1355249204507

view raw Output-Apache-Logger hosted with ❤ by GitHub

Test Results "java.util.logging.Logger"

	SEVERE: Case 1: Start time : 1,355,176,462,009
	SEVERE: Case 1: End time : 1,355,176,462,101
	SEVERE: Case 2: Start time : 1,355,176,462,102
	SEVERE: Case 2: End time : 1,355,176,462,105
	SEVERE: Case 3: Start time : 1,355,176,462,106
	SEVERE: Case 3: End time : 1,355,176,462,160
	SEVERE: Case 4: Start time : 1,355,176,462,160
	SEVERE: Case 4: End time : 1,355,176,462,162
	SEVERE: Case 5: Start time : 1,355,176,462,163
	SEVERE: Case 5: End time : 1,355,176,462,164

view raw output-apacheLogger hosted with ❤ by GitHub

Test Code using "org.apache.logging.log4j.Logger"

	package learn.java.logger;
	import org.apache.logging.log4j.LogManager;
	import org.apache.logging.log4j.Logger;
	public class LearnApacheLogging {
	private static final Logger logger = LogManager.getLogger(LearnApacheLogging.class.getName());
	public static void main(String[] args){
	logger.fatal("Case 1: Start time : {}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	logger.debug("Entry number: {} is ", i);
	}
	logger.fatal("Case 1: End time : {}", System.currentTimeMillis());
	logger.fatal("Case 2: Start time : {}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	if(logger.isDebugEnabled()){
	logger.debug("Entry number: {} is ", i);
	}
	}
	logger.fatal("Case 2: End time : {}", System.currentTimeMillis());
	logger.fatal("Case 3: Start time : {}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	logger.debug("Entry number: " + i + " is ");
	}
	logger.fatal("Case 3: End time : {}", System.currentTimeMillis());
	logger.fatal("Case 4: Start time : {}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	logger.debug("Static Log");
	}
	logger.fatal("Case 4: End time : {}", System.currentTimeMillis());
	logger.fatal("Case 5: Start time : {}", System.currentTimeMillis());
	for (int i = 0; i < 100000; i++) {
	if(logger.isDebugEnabled()){
	logger.debug("Static Log");
	}
	}
	logger.fatal("Case 5: End time : {}", System.currentTimeMillis());
	}
	}

view raw LearnApacheLogging.java hosted with ❤ by GitHub

Test Results "org.apache.logging.log4j.Logger"

	23:36:44.427 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: Start time : 1355249204421
	23:36:44.449 [main] FATAL learn.java.logger.LearnApacheLogging - Case 1: End time : 1355249204449
	23:36:44.450 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: Start time : 1355249204450
	23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 2: End time : 1355249204455
	23:36:44.455 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: Start time : 1355249204455
	23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 3: End time : 1355249204505
	23:36:44.505 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: Start time : 1355249204505
	23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 4: End time : 1355249204506
	23:36:44.506 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: Start time : 1355249204506
	23:36:44.507 [main] FATAL learn.java.logger.LearnApacheLogging - Case 5: End time : 1355249204507

view raw Output-Apache-Logger hosted with ❤ by GitHub

Conclusion: 

1. Apache Logger is more efficient in logging than java default logger.
2. String concatenation technique in less efficient than new placeholder technique. [But for log4j placeholder technique is available in  log4j 2.0 only.]
3. Its very efficient to check log level before logging command for dynamic logs [The logs which require string concatenation or placing values in placeholders ]
4. Its inefficient to check log level before logging command for simple/static logs.

Reference:
http://logging.apache.org/log4j/2.x/performance.html