177Logging Part 3 of 3

Author: Dr. Heinz M. KabutzDate: 2009-10-13Java Version: 5Category: Language

Abstract: After almost nine years of silence, we come back to bring the logging series to an end, looking at best practices and what performance measurements to log.

Welcome to the 177th issue of The Java(tm) Specialists' Newsletter, written en route home from Oslo. Last night, I plucked up the courage to order a plate of Lutefisk, mentioned in my deadlock concurrency law. The starter at that particular restaurant was absolutely fantastic, which even The Real Picky Gourmet would have approved of. This Lutefisk was as good as you were going to get anywhere. Eating Lutefisk is a bit like an African bush circumcision, just a bit more painful. Once it's done, you feel great joy that it won't happen again. Those of you who have never tried Lutefisk, you have to. You know the saying, "misery loves company"? As one of my Norwegian students said: Lutefisk isn't actually that bad ... it's worse.

We now issue JavaSpecialists.EU electronic course attendance certificates to those who completed our courses successfully. I really dislike paper certificates, as they get misplaced or damaged too easily. Instead, I will host them on my website as permanent links. This means, you can include a link in your CV and by clicking on your special student link, any potential employer can verify your student records. If you are missing a certificate, please contact me, stating the course that you attended.

javaspecialists.teachable.com: Please visit our new self-study course catalog to see how you can upskill your Java knowledge.

Logging Part 3 of 3

My first Java Specialist Newsletter was written nine years ago, with the topic of Java concurrency. It was sent to an initial set of 80 friends and colleagues. I would not give it an A for writing, but maybe a B for effort. Click here to read it. Later, I expanded this topic with the Secrets of Concurrency series. In the second article, I showed how we could initialize a collection in a single method call, like this:

    universityRegistration.addNames(new Vector(3)
      {{ add("Heinz"); add("John"); add("Anton"); }});

After that, I spent two newsletters looking at a topic that was very important in the system we were building: Logging. The first was about a TeeOutputStream that I had developed (Click here to read it) and the second about determining the line number of where we were logging (Click here to read that one).

Everybody likes to write a logging framework ...

Back in 1997, when I first programmed Java commercially, there were no logging frameworks. Our chief architect was assigned the task of designing an all-singing and all-dancing framework. Unfortunately he took too long to complete his work, so we each ended up writing our own. In a team of 5 developers, we had 6 completely different logging systems. One colleague streamed every single object to a file, thus capturing the complete state of the program. I don't think he ever wrote a reader for his binary log file though. I rerouted System.out to tee all output to a file and defined different logging levels.

Writing your own logging framework is the perfect coding crime. If you can convince your manager to put it on the project plan, you are guaranteed to have success. At the end of each day, you will go home feeling happy and satisfied. It will feel like you are doing something creative. You will get the intellectual stimulation without the risk of failure.

Even the Sun engineers fell into this trap. Prior to Java 4, we had a perfectly good logging framework in Log4J. However, instead of adopting this into the standard Java distribution, we ended up with java.util.logging. There are lots of Java logging frameworks available, even meta-logging frameworks like SLF4J and Jakarta Commons. These are supposed to abstract the logging frameworks so you can change the implementation without touching your code.

In this newsletter, I will not promote any single logging framework, but will rather talk in general about logging best practices. If you feel the need to tell me about XYZ logging framework that is better than ABC framework, please remember that everyone likes to write a logging framework ... :-)

Logging Levels

We can usually specify different levels of detail for our logging. In Log4J for example, we have six default levels, FATAL, ERROR, WARNING, INFO, DEBUG and TRACE. The usual best practice is to use FATAL and ERROR for messages that have to be shown in production to inform the user when something really terrible has happened that would affect the operation of the program. WARNING and INFO would be turned on during testing. DEBUG and TRACE is for the developers.

We sometimes find it difficult setting appropriate levels. We either judge our message as too important or too trivial. We might get the level wrong, like this: OutOfMemoryError? Ah, let's just log that as INFO. InterruptedException? Now that's FATAL.

Since it is tricky assigning the correct levels in our code, we should regularly do code reviews with specific emphasis on logging levels.

We should be able to adjust the log levels of our individual components at runtime without restarting our application. In the logging framework that I wrote back in 1997, I provided a GUI with JSliders for users to adjust the levels easily. However, during a customer visit, I noticed that they had simply enabled all the logging permanently. All that work of a fancy GUI for nothing! No wonder they were emailing me gigabyte log files.

Another customer uses logging as an audit trail of their system and they produced gigabytes of logging per day. All of this is kept and stored for years to come.

Despite some users wanting to know absolutely everything that happens in an application, we should still set up different levels for our components. We might need to turn down the amount of logging noise when we tune performance.

Silent Operation

In Java, when we dynamically create a log message, this is done before the logger is called. Thus in the following code, the dynamic string is always created, even if logging is turned off. In addition, the fooCalls field is incremented, even if we are not interested in counting the method calls. It is impossible for this code to run completely silently.

import java.util.concurrent.atomic.*;
import java.util.logging.*;

public class MyComponent {
  private static final Logger log =
      Logger.getLogger(MyComponent.class.getName());

  private AtomicInteger fooCalls = new AtomicInteger();

  public void foo() {
    log.info("Number of calls to foo(): " +
        fooCalls.incrementAndGet());
  }

  public static void main(String[] args) {
    MyComponent mc = new MyComponent();
    mc.foo();
    mc.foo();
    mc.foo();

    log.setLevel(Level.SEVERE);

    testPerformance(mc);
    testPerformance(mc);
    testPerformance(mc);
  }

  private static void testPerformance(MyComponent mc) {
    long time = System.currentTimeMillis();
    for (int i = 0; i < 10 * 1000 * 1000; i++) {
      mc.foo();
    }
    time = System.currentTimeMillis() - time;
    System.out.println("time = " + time);
  }
}

The output of my program is as follows on my MacBook Pro:

    Oct 10, 2009 4:04:33 PM MyComponent foo
    INFO: Number of calls to foo(): 1
    Oct 10, 2009 4:04:33 PM MyComponent foo
    INFO: Number of calls to foo(): 2
    Oct 10, 2009 4:04:33 PM MyComponent foo
    INFO: Number of calls to foo(): 3
    time = 2352
    time = 2224
    time = 2229

We can improve the performance of silent logging by using code guards. Instead of first constructing the String and then passing it into the log method, we can first check whether the INFO level is in fact enabled:

import java.util.concurrent.atomic.*;
import java.util.logging.*;

public class MyComponentFast {
  private static final Logger log =
      Logger.getLogger(MyComponentFast.class.getName());

  private AtomicInteger fooCalls = new AtomicInteger();

  public void foo() {
    if (log.isLoggable(Level.INFO)) {
      log.info("Number of calls to foo(): " +
          fooCalls.incrementAndGet());
    }
  }

  public static void main(String[] args) {
    MyComponentFast mc = new MyComponentFast();
    mc.foo();
    mc.foo();
    mc.foo();

    log.setLevel(Level.SEVERE);

    testPerformance(mc);
    testPerformance(mc);
    testPerformance(mc);
  }

  private static void testPerformance(MyComponentFast mc) {
    long time = System.currentTimeMillis();
    for (int i = 0; i < 10 * 1000 * 1000; i++) {
      mc.foo();
    }
    time = System.currentTimeMillis() - time;
    System.out.println("time = " + time);
  }
}

This executes a lot faster, as the Strings do not have to be constructed:

    Oct 10, 2009 4:10:14 PM MyComponent foo
    INFO: Number of calls to foo(): 1
    Oct 10, 2009 4:10:14 PM MyComponent foo
    INFO: Number of calls to foo(): 2
    Oct 10, 2009 4:10:14 PM MyComponent foo
    INFO: Number of calls to foo(): 3
    time = 40
    time = 31
    time = 20

Quite a difference in performance! There are various schemes to avoid using code guards. For example, we could use a log method that accepts varargs, like this:

    public static void log(Level level, Object... args) {
      if (log.isLoggable(level)) {
        StringBuilder sb = new StringBuilder();
        for (Object arg : args) {
          sb.append(arg);
        }
        log.log(level, sb.toString());
      }
    }

This can improve things a bit. We could also have a number of methods with an increasing number of parameters, with varargs for the case where we need even more parameters. Something like this:

  private static void log(Level level, Object arg0) {
    if (log.isLoggable(level)) {
      String s = "" + arg0;
      log.log(level, s);
    }
  }

  private static void log(Level level, Object arg0, Object arg1) {
    if (log.isLoggable(level)) {
      String s = "" + arg0 + arg1;
      log.log(level, s);
    }
  }

  private static void log(Level level, Object arg0,
                          Object arg1, Object arg2) {
    if (log.isLoggable(level)) {
      String s = "" + arg0 + arg1 + arg2;
      log.log(level, s);
    }
  }

  // etc.

As you can see, I am falling into the trap myself, where I want to enhance and improve the existing logging framework.

Logging and Performance

There are two aspects to performance and logging. Firstly, there is the performance information that we should be logging. Secondly, there is the performance aspect of the logging itself.

Whenever we do any operation that could take some time to complete, we should log the time it took. For example, every database query should automatically be logged, together with the time it took to execute it. When we do a SELECT, we should also measure how long it took to retrieve the dataset. Whenever we call a method that goes into the WAITING or TIMED_WAITING state, which you can recognize by the InterruptedException being declared, we should log the time it took to return.

We should log queue lengths, which will help tune the system. For example, in a thread pool, if the runnable queue gets too long, you know that you need more threads or cores to execute the work. You also then know that you might see an OutOfMemoryError. Objects that hang around longer than they should are called loitering objects. Non-english students usually give me a puzzled look, until I say the loitering objects are like a bunch of teenager hanging around at the train station. Eventually they mature and go away.

Another useful performance metric to measure and log in our systems is throughput.

I usually have a performance health status thread that logs information such as queue lengths, wait times and throughput once a minute. This way, by looking at the last values, I can quickly see if the system is not behaving as expected.

Secondly, we need to be careful that our logging does not become a bottleneck in itself. Right from the start, I used code guards in my own logging system. When you turn off logging, it should be completely silent, without creating any objects.

One of the other 6 logging frameworks printed out the current date to the console. It just created a new Date() object and prepended that to the message. You can experience the performance by running the code below:

import java.util.*;

public class PrintingDate {
  public static void main(String[] args) {
    long time = System.currentTimeMillis();
    for (int i = 0; i < 10000; i++) {
      System.out.println(new Date() + " log message");
    }
    time = System.currentTimeMillis() - time;
    System.out.println("time = " + time);
  }
}

The PrintingDate code took approximately 500ms to run on my machine. When we replace it with a call to System.currentTimeMillis(), as in PrintingDateFast, we get down to about 300ms:

public class PrintingDateFast {
  public static void main(String[] args) {
    long time = System.currentTimeMillis();
    for (int i = 0; i < 10000; i++) {
      System.out.println(System.currentTimeMillis() + " log message");
    }
    time = System.currentTimeMillis() - time;
    System.out.println("time = " + time);
  }
}

When my colleague changed his logging code to format the date manually, his entire module ran twice as fast!

Useful Views

One of the best way to view very large logs, in 10s of gigabyte of size, is to first filter the file. I use the simple unix grep utility to either include or exclude certain lines. However, the grep utility only works well when every log entry fits onto one line. This can be challenging when we want to display objects that traditionally span several lines. A good trick here is to collapse the object onto a single line and then expand it again for display purposes. For example, here is a Layout for Log4J that can be used to collapse lines with "|>>" instead of a newline character. For readability, it is trivial to then replace those characters with \n again.

import org.apache.log4j.*;
import org.apache.log4j.spi.*;

import java.io.*;

public class MultipleLineLayout extends Layout {
  public String format(LoggingEvent event) {
    Object o = event.getMessage();
    if (o instanceof Throwable) {
      return format((Throwable) o);
    }
    return format(String.valueOf(event.getMessage()));
  }

  private String format(Throwable t) {
    StringWriter out = new StringWriter();
    PrintWriter pw = new PrintWriter(out);
    t.printStackTrace(pw);
    pw.close();
    return format(out.toString());
  }

  private String format(String s) {
    return s.
        replaceAll("\r", ""). // remove Windows carriage returns
        replaceAll("\n*$", ""). // remove trailing newline chars
        replaceAll("\n", " |>> ") // replace newline with |>>
        + "\n";
  }

  public boolean ignoresThrowable() {
    return false;
  }

  public void activateOptions() {
    // not necessary
  }
}

In our test class we log an exception in a deep stack, caused by a recursive function. We also pass in a String that spans several lines. All objects are collapsed into single lines.

import org.apache.log4j.*;

import java.io.*;

public class LayoutTest {
  private static Logger logger = Logger.getLogger("test");
  public static void openFile(int level) {
    if (level == 0) {
      logger.fatal(new IOException("Disk is corrupted"));
      return;
    }
    openFile(level-1);
  }
  public static void main(String[] args) {
    logger.addAppender(new ConsoleAppender(
        new MultipleLineLayout()
    ));

    openFile(0);
    openFile(10);
    logger.warn("Watch\n" +
        "out\n" +
        "for\n\r" +
        "the\n" +
        "Lutefisk!\n" +
        "\n");
  }
}

The output is something like this, each log output is on a single line though.

    java.io.IOException: Disk is corrupted |>> at LayoutTest.op
    enFile(LayoutTest.java:9) |>> at LayoutTest.main(LayoutTest
    .java:19)

    java.io.IOException: Disk is corrupted |>> at LayoutTest.op
    enFile(LayoutTest.java:9) |>> at LayoutTest.openFile(Layout
    Test.java:12) |>> at LayoutTest.openFile(LayoutTest.java:12
    ) |>> at LayoutTest.openFile(LayoutTest.java:12) |>> at Lay
    outTest.openFile(LayoutTest.java:12) |>> at LayoutTest.open
    File(LayoutTest.java:12) |>> at LayoutTest.openFile(LayoutT
    est.java:12) |>> at LayoutTest.openFile(LayoutTest.java:12)
     |>> at LayoutTest.openFile(LayoutTest.java:12) |>> at Layo
    utTest.openFile(LayoutTest.java:12) |>> at LayoutTest.openF
    ile(LayoutTest.java:12) |>> at LayoutTest.main(LayoutTest.j
    ava:20)

    Watch |>> out |>> for |>> the |>> Lutefisk!

If we replace the " |>> " with a newline character again, we get back to the original output. We could do this with the unix sed and grep commands:

grep Exception logfile | sed 's/ |\>\> /&\
/g'

I can now see all the exceptions that occurred in the logfile, but nicely formatted:

java.io.IOException: Disk is corrupted
        at LayoutTest.openFile(LayoutTest.java:9)
        at LayoutTest.main(LayoutTest.java:19)
java.io.IOException: Disk is corrupted
        at LayoutTest.openFile(LayoutTest.java:9)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.openFile(LayoutTest.java:12)
        at LayoutTest.main(LayoutTest.java:20)

When we log from several threads, we should also log a unique thread identifer as part of our message, so that we can filter by thread id. Unfortunately there is no way to get a unique thread id in Java, so you will have to generate that yourself. The JavaDoc explicitly states with Thread.getId(), When a thread is terminated, this thread ID may be reused. You definitely do not want this behaviour if you have a long-running application that uses threads.

For example, we could print a unique thread descriptor that will be easy to filter on. Just search for the unique thread id, such as utid={3}.

import java.util.concurrent.atomic.*;

/**
 * Idea based on JavaDoc in java.lang.ThreadLocal, except that
 * this code is correct (I think) ;-)
 */
public class ThreadDescriptor {
  private static final AtomicInteger uniqueId =
      new AtomicInteger(0);
  private static final ThreadLocal<String> descriptor
      = new ThreadLocal<String>() {
    protected String initialValue() {
      return Thread.currentThread().getName() + "_utid={" +
          uniqueId.getAndIncrement() + "}";
    }
  };
  public static String get() {
    return descriptor.get();
  }
}

The output of our test code could be different every time we call it, depending on the order that the scheduler assigns CPU cycles to each thread.

import java.util.concurrent.*;

public class ThreadDescriptorTest {
  public static void main(String[] args) {
    Runnable task = new Runnable() {
      public void run() {
        System.out.println(ThreadDescriptor.get());
      }
    };
    new Thread(task, "MyThread").start();
    System.out.println(ThreadDescriptor.get());
    ExecutorService pool = Executors.newCachedThreadPool();
    pool.submit(task);
    pool.submit(task);
    pool.submit(task);
    pool.shutdown();
  }
}

For example, the output could be as follows:

    MyThread_utid={1}
    main_utid={0}
    pool-1-thread-1_utid={2}
    pool-1-thread-2_utid={3}
    pool-1-thread-3_utid={4}

Asynchronous Logging

Logging can easily become a botleneck in a real system if the application is reasonably chatty. Instead of writing the log directly to the output, we could also write the messages into a queue and then write them asynchronously. When we first thought of this about in 1997, we were very excited until we realised that our systems were permanently busy, so the queue was always full. In addition, when the system crashed severely, the last messages were still in the queue and were thus not written out to the log.

Perhaps an idea would be to use a MappedByteBuffer to write the log output? That way, you can be guaranteed that the log is written, even if the process is killed. The MappedByteBuffer then effectively becomes the asynchronous logger. Try get that onto your project plan?

This newsletter has become much longer than I thought, which goes to prove that everyone likes to write a logging framework.

Kind regards

Heinz

Comments

We are always happy to receive comments from our readers. Feel free to send me a comment via email or discuss the newsletter in our JavaSpecialists Slack Channel (Get an invite here)

Related Articles

Browse the Newsletter Archive