| career | drupal | java | mac | mysql | perl | scala | uml | unix  

What this is

This file is included in the "Java Source Code Warehouse" project. The intent of this project is to help you "Learn Java by Example" TM.

Other links

The source code

//      Copyright 1996-1999, International Business Machines
//      Corporation. All Rights Reserved.

//      Copyright 2000, Ceki Gulcu. All Rights Reserved.

//      See the LICENCE file for the terms of distribution.

package org.apache.log4j.performance;

import org.apache.log4j.Category;
import org.apache.log4j.xml.DOMConfigurator;

import org.apache.log4j.NDC;
import org.apache.log4j.performance.NOPWriter;

   Measure the performance of logging.


Experimental results are listed below in units of micro-seconds. Measurements were done on a AMD Duron clocked at 800Mhz running Windows 2000 and Sun's 1.3 JDK.

Layout NullAppender FileAppender FileAppender (no flush) AsyncAppender (no flush)
SimpleLayout 4 21 16 33
PatternLayout "%p - %m%n" 4 21 16 32
PatternLayout "%-5p - %m%n" 4 NA NA NA
TTCCLayout/RELATIVE 10 37 31 45
PatternLayout "%r [%t] %-5p %c{2} %x - %m%n" 11 NA NA NA
PatternLayout "%r [%t] %-5p %.10c %x - %m%n" 11 NA NA NA
PatternLayout "%r [%t] %-5p %.20c %x - %m%n" 11 NA NA NA
PatternLayout "%r [%t] %-5p %c - %m%n" 9 36 29 45
TTCCLayout/ISO8601 25 58 51 71
PatternLayout "%d{ISO8601} [%t] %-5p %c %x - %m%n" 28 62 55 76
PatternLayout "%d{yyyy-MM-dd HH:mm:ss,SSS} [%t] %-5p %c %x - %m%n" 46 82 72 94
PatternLayout "%l - %m%n" 241 317 299 251
PatternLayout "%C.%M.%L - %m%n" 267 NA NA NA

The results of the measurements (should) show that:

  1. The PatternLayout perforance is very close to the performance of a dedicated layout of equivalent format.

  2. Format specifiers in conversion patterns have almost no impact on performance.

  3. Formating time and date information is costly. Using relative time has the least impact on performance. It is recommended that to use log4j specific date formatters such as the {@link org.apache.log4j.helpers.ISO8601DateFormat} instead of the standard {@link java.text.SimpleDateFormat} because of its poor performance. See the %d conversion character in {@link org.apache.log4j.PatternLayout}.

  4. Avoiding the flush operation at the end of each append results in a performance gain of 10 to 20 percent. However, there is safety tradeoff invloved in skipping flushing. Indeed, when flushing is skipped, then it is likely that the last few log events will not be recorded on disk when the application exits. This is a high price to pay even for a 20% performance gain.

  5. The AsyncAppender does not automatically increase performance. On the contrary, it significantly degrades performance. The performance tests done here very quickly fill up the bounded buffer of the AsyncAppender and there is cosiderable overhead in managing this bounded buffer.

    On the other hand, had we interleaved logging operations with long blocking and non CPU-intensive operations, such as I/O, network access, sleeping threads, then the AsyncAppender would have tremendously reduced the cost of logging in terms of overall application runtime.

    In a variant of this test, we have inserted a short sleep operation between every 10 log operations. When the total slept time is substracted, logging with the AsyncLogger takes no time at all. In other words, logging is done for "free".

  6. Extracting location information is comparatively slow. It implies at least a ten fold increase in logging time! It should be avoided unless performace is not a concern. It has been reported from a trusted source that logging with location information on AIX machines will kill your application's performance.
@author Ceki Gülcü */ public class Logging { static int runLength; static int delay = -1; /** A delay is applied after every burstLen log requests. The default value of this constant is 100. */ static int burstLen = 100; static int DELAY_MULT = 1000/burstLen; static Category cat = Category.getInstance("A0123456789.B0123456789.C0123456789"); static void Usage(String msg) { System.err.println(msg); System.err.println( "Usage: java "+Logging.class.getName()+" confFile runLength [delay] [burstLen]\n"+ " confFile is an XML configuration file and\n"+ " runLength (integer) is the length of test loop.\n"+ " delay is the time in millisecs to wait every bustLen log requests."); System.exit(1); } /** Usage: java org.apache.log4j.performance.Logging confFile runLength [delay] [burstLen]

confFile is an XML configuration file and runLength (integer) is the length of test loop, delay is the time in millisecs to sleep every bustLen log requests.

This application just prints the average time it took to log. */ public static void main(String argv[]) { if(argv.length == 2) init(argv[0], argv[1], null, null); else if( argv.length == 4) init(argv[0], argv[1], argv[2], argv[3]); else Usage("Wrong number of arguments."); NDC.push("some context"); double delta; String msg = "ABCDEGHIJKLMNOPQRSTUVWXYZabcdeghijklmnopqrstuvwxyz1234567890"; if(delay <= 0) delta = NoDelayLoop(cat, msg); else delta = DelayedLoop(cat, msg); System.out.print((int)delta); Category.shutdown(); } /** Program wide initialization method. */ static void init(String configFile, String runLengthStr, String delayStr, String burstLenStr) { try { runLength = Integer.parseInt(runLengthStr); if(delayStr != null) { delay = Integer.parseInt(delayStr); } if(delayStr != null) { burstLen = Integer.parseInt(burstLenStr); DELAY_MULT = 1000/burstLen; } } catch(java.lang.NumberFormatException e) { e.printStackTrace(); } DOMConfigurator.configure(configFile); } static double NoDelayLoop(Category category, String msg) { long before = System.currentTimeMillis(); for(int i = 0; i < runLength; i++) {; } return ((System.currentTimeMillis() - before)*1000.0)/runLength; } static double DelayedLoop(Category category, String msg) { long before = System.currentTimeMillis(); int j = 0; Thread currentThread = Thread.currentThread(); for(int i = 0; i < runLength; i++) {; if(j++ == burstLen) { j = 0; try{currentThread.sleep(delay);}catch(Exception e){} } } double actualTime = ((System.currentTimeMillis()-before)*1000.0/runLength); System.out.println("actual time: "+actualTime); return (actualTime - delay*DELAY_MULT); } }

... this post is sponsored by my books ...

#1 New Release!

FP Best Seller


new blog posts


Copyright 1998-2021 Alvin Alexander,
All Rights Reserved.

A percentage of advertising revenue from
pages under the /java/jwarehouse URI on this website is
paid back to open source projects.