How to evaluate the performance of a logger?

I'm doing a project about improving the performance of logs (specifically, log4j) in a Java framework. Now I have two loggers reading from a source and dumping the same logging information to two different files, I can control the source by either reading from a file, which has finite number of lines, or read from a source generator, which keeps generating information all the time (infinite number of lines).

Now I want to evaluate开发者_运维百科 the performance of the two loggers, i.e which one is faster given the same information to log. Would you have any ideas about how to do this? PS I thought I would need a thread to count the lines of the files, but I'm not sure how. Any assistance is greatly appreciated.

Log4J is the current standard not only in open source development. It claims to be fast and flexible: speed first, flexibility second. But there are some pitfalls when it comes to the crunch.

The costs of a log request consists of a method invocation and an integer comparison. This is typically about 1-20ns (depending on your processor) per call. However, this does not include the “hidden” costs of parameter construction.

A simple example:

logger.debug("Value: " + x*y);

Regardless of whether the message will actually be logged or not, the parameter construction will cause additional costs. These costs of parameter construction can be quite high and depend on the size of the parameters involved.

To avoid the parameter construction costs:

if(logger.isDebugEnabled() {
  logger.debug("Value: " + x*y);
}

This will not incur the cost of parameter construction if debugging is disabled. On the other hand, if the logger is debug-enabled, it will incur twice the cost of evaluating whether the logger is enabled or not: once in debugEnabled and once in debug. This is an insignificant overhead because evaluating a logger takes about 1% of the time it takes to actually log.

So if speed is a real issue, you should double-check your logging statements for “hidden” costs.

Resources: http://logging.apache.org/log4j/1.2/manual.html

The only questions which really matters are:

• Which devices are you logging to? (Most important)

• Whether the logging is performed in the current thread or the background thread?

• Is the format pattern the same?

• Are message which are not logged not created. e.g. it doesn't build messages it won't print.

• Are you using Strings to build messages or a lower level text building? (only matters if the rest are optimal)

If you print the same number of lines in each case, the count is less important than the total time taken.

Here is a simple test

Logger log = Logger.getAnonymousLogger();
int runs = 100 * 1000;
long start = System.nanoTime();
for(int i=0;i< runs;i++)
    log.info("Hello World! "+i);
long time = System.nanoTime() - start;
System.out.printf("Average log time was %,d ns%n", time/runs);

To IDE GUI prints

Average log time was 109,270 ns

To DOS window prints

Average log time was 354,015 ns

Writing to a file only

Handler handler = new FileHandler("test.log", 1024 * 1024, 10);

Logger log = Logger.getAnonymousLogger();
log.setUseParentHandlers(false);
log.addHandler(handler);

prints

Average log time was 29,688 ns

With NO devices

Average log time was 1,002 ns

This is typical with all the loggers, the device is the most critical factor.

I had to tackle this problem at work; I wrote an implementation of SLF4J and was testing it against Log4J. I created a harness that would pump a fixed number of messages (n) through the logger on a fixed number of threads (t). I tested measured execution time of various combinations of (n,t) over several trials and examined median, mean, and p90 values of the aggregate results. I also swapped the implementation of SLF4J in our app between Log4J and my implementation and ran the application through pre-existing perf tests to see the impact in our application.

My advice:

1. Exercise each logger in a test harness that simulates your application.
2. If practical, exercise each logger in your application under simulated load (ie, using replay or generated data).