Closures: Lazy Logging

This post is about using the Java logging API. Even when not logging at all (because of the logging level of the logger), the eager evaluation semantics of Java can be sitting in the way of performance.

Consider the following logger test.

 import java.util.logging.Logger;
 import static java.util.logging.Level.SEVERE;
 
 public class LoggerTest {
  
  private Logger logger;
  
  public static void main(String[] args) {
   new LoggerTest().go();
  }
  
  private void sleep() {
   for(int i=0; i<10; i++) {
    try { Thread.sleep(100); System.out.print("."); }
    catch(Exception e) { }
   }
   System.out.println();
  }
  
  private String severeLog() { sleep(); return "severe"; }
  private String warningLog() { sleep(); return "warning"; }
  
  private void go() {
   logger = Logger.getLogger("LoggerTest");
   logger.setLevel(SEVERE);
   logger.severe(severeLog());
   logger.warning(warningLog());
  }
  
 }

Running the logger test illustrates that arguments are evaluated in an eager way.

 ..........
 Sep 4, 2008 12:07:32 PM LoggerTest go
 SEVERE: severe
 ..........

Closures offer an elegant lazy alternative. First, we replace strings with lazy strings (implementations of a LazyString interface with a no-arg method returning a string (the name of the method (evaluate) does not really matter)). Second, we wrap a lazy logger (which works with lazy strings) around a logger (which works with strings).

 package logging;
 
 public interface LazyString {
  
  public String evaluate();
  
 }
  
 package logging;
 
 import java.util.logging.Logger;
 import static java.util.logging.Level.SEVERE;
 import static java.util.logging.Level.WARNING;
 
 public class LazyLogger {
  
  private Logger logger;
  
  public LazyLogger(Logger logger) {
   this.logger = logger;
  }
  
  public void severe(LazyString lazyString) {
   if(logger.getLevel().equals(SEVERE)) {
    logger.severe(lazyString.evaluate());
   }
  }
  
  public void warning(LazyString lazyString) {
   if(logger.getLevel().equals(WARNING)) {
    logger.warning(lazyString.evaluate());
   }
  }
  
 }

The good news is that closures are automagically converted to instances of one method interface implementations. We can write a lazy logger test in almost the same way as the logger test.

 import java.util.logging.Logger;
 import static java.util.logging.Level.SEVERE;
 
 import logging.LazyString;
 import logging.LazyLogger;
 
 public class LazyLoggerTest {
  
  private LazyLogger lazyLogger;
  
  public static void main(String[] args) {
   new LazyLoggerTest().go();
  }
  
  private void sleep() {
   for(int i=0; i<10; i++) {
    try { Thread.sleep(100); System.out.print("."); }
    catch(Exception e) { }
   }
   System.out.println();
  }
  
  private LazyString severeLog = { => sleep(); "severe" };
  private LazyString warningLog = { => sleep(); "warning" };
  
  private void go() {
   Logger logger = Logger.getLogger("LazyLoggerTest");
   logger.setLevel(SEVERE);
   lazyLogger = new LazyLogger(logger);
   lazyLogger.severe(severeLog);
   lazyLogger.warning(warningLog);
  }
  
 }

Running the lazy logger test illustrates that arguments are evaluated in a lazy way.

 ..........
 Sep 4, 2008 12:07:34 PM LoggerTest go
 SEVERE: severe