Logback can hurt your startup time

What’s the difference between this:

public class Main {
  public static void main(String[] args) {
    long start = System.currentTimeMillis();
    new WebServer().start();
    long end = System.currentTimeMillis();
    System.out.println(end - start);
  }
}

Output:
23:08:57.096 INFO  net.codestory.http.WebServer - Server started on port 8080
389

And that:

public class Main {
  public static void main(String[] args) {
    long start = System.currentTimeMillis();
    new WebServer().start();
    long end = System.currentTimeMillis();
    System.out.println(end - start);
  }
}

Output:
130
[main] INFO net.codestory.http.WebServer - Server started on port 8080

Exactly! The second program starts three times faster! And I didn’t have to change or add a single line of code!

Let me tell you the whole story

I was trying to reduce the startup time of my Web Server. Because, you know, I thought starting up in 300ms was lame. So I ran my sample code with good old -verbose:class jvm parameter. Turns out the jvm had to load 1626 classes to start the server. Out of which, 240 are ch.qos.logback.* classes. And lot’s of xml related classes are loaded. I can swear I don’t do xml. Not me!

What if the simple fact of parsing a logback.xml was the reason for my web server being so slow to start?

Let’s delete logback.xml file. Easy! 1247 classes are loaded now. That’s 379 classes to parse an xml file… I won’t comment much on that although there would be much to write about. More important, the startup time went from 389ms down to 217ms. And the logs are still there in the console.

Now what if I don’t use logback at all but use slf4j-simple.jar instead?

Now, 1040 classes are loaded and the startup time is down to 130ms. That’s better!

As a plus side, I’m free to use whichever slower implementation of slf4j in production. But during development, every 100ms is important.

6 thoughts on “Logback can hurt your startup time”

  1. Have you tried with log4j2 ? All in all, there is no reason to use slf4j, you are not embedding tomcat in another application, right ?

    1. Hi Emmanuel. I haven’t tried log4j2. I fact I don’t care too much about logs in that case but a library I embedded uses slf4j, so I needed to provide n implementation to avoid error messages at startup. Turns out it took months to realise that doing that I hurt my startup time bad.

      1. The problem with slf4j-simple is that it sends all the logs to system.err… :

        “Simple implementation of Logger that sends all enabled log messages, for all defined loggers, to the console (System.err).”

        You certainly don’t want to use this in production.

  2. Very interesting findings. The only think I hate about slf4j-simple is that it does not display DEBUG messages which might be useful in development. May be there is some space for a slf4j-not-too-simple-but-blazing-fast-on-startup library.

  3. FYI, SimpleLogger can be configured to log on System.out instead of System.err via system properties.

    As for logback start up time, I think that resolving the local host name might be responsible for the delay more than the class load time. In any case, I agree that 200 ms to load the logback config file may be somewhat excessive.

Comments are closed.