apache log4j(3)-introduction(4)

Here is a sample configuration file that results in identical output as the previous BasicConfigurator based example.


# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=DEBUG, A1


# A1 is set to be a ConsoleAppender.
log4j.appender.A1=org.apache.log4j.ConsoleAppender


# A1 uses PatternLayout.
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n
Suppose we are no longer interested in seeing the output of any component belonging to the com.foo package. The following configuration file shows one possible way of achieving this.


log4j.rootLogger=DEBUG, A1
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout


# Print the date in ISO 8601 format
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c - %m%n


# Print only messages of level WARN or above in the package com.foo.
log4j.logger.com.foo=WARN
The output of MyApp configured with this file is shown below.


2000-09-07 14:07:41,508 [main] INFO  MyApp - Entering application.
2000-09-07 14:07:41,529 [main] INFO  MyApp - Exiting application.
As the logger com.foo.Bar does not have an assigned level, it inherits its level from com.foo, which was set to WARN in the configuration file. The log statement from the Bar.doIt method has the level DEBUG, lower than the logger level WARN. Consequently, doIt() method's log request is suppressed.


Here is another configuration file that uses multiple appenders.


log4j.rootLogger=debug, stdout, R


log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout


# Pattern to output the caller's file name and line number.
log4j.appender.stdout.layout.ConversionPattern=%5p [%t] (%F:%L) - %m%n


log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=example.log


log4j.appender.R.MaxFileSize=100KB
# Keep one backup file
log4j.appender.R.MaxBackupIndex=1


log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%p %t %c - %m%n
Calling the enhanced MyApp with the this configuration file will output the following on the console.


 INFO [main] (MyApp2.java:12) - Entering application.
DEBUG [main] (Bar.java:8) - Doing it again!
 INFO [main] (MyApp2.java:15) - Exiting application.
In addition, as the root logger has been allocated a second appender, output will also be directed to the example.log file. This file will be rolled over when it reaches 100KB. When roll-over occurs, the old version of example.log is automatically moved to example.log.1.


Note that to obtain these different logging behaviors we did not need to recompile code. We could just as easily have logged to a UNIX Syslog daemon, redirected all com.foo output to an NT Event logger, or forwarded logging events to a remote log4j server, which would log according to local server policy, for example by forwarding the log event to a second log4j server.


Default Initialization Procedure


The log4j library does not make any assumptions about its environment. In particular, there are no default log4j appenders. Under certain well-defined circumstances however, the static inializer of the Logger class will attempt to automatically configure log4j. The Java language guarantees that the static initializer of a class is called once and only once during the loading of a class into memory. It is important to remember that different classloaders may load distinct copies of the same class. These copies of the same class are considered as totally unrelated by the JVM.


The default initialization is very useful in environments where the exact entry point to the application depends on the runtime environment. For example, the same application can be used as a stand-alone application, as an applet, or as a servlet under the control of a web-server.


The exact default initialization algorithm is defined as follows:


Setting the log4j.defaultInitOverride system property to any other value then "false" will cause log4j to skip the default initialization procedure (this procedure).
Set the resource string variable to the value of the log4j.configuration system property. The preferred way to specify the default initialization file is through the log4j.configuration system property. In case the system property log4j.configuration is not defined, then set the string variable resource to its default value "log4j.properties".
Attempt to convert the resource variable to a URL.
If the resource variable cannot be converted to a URL, for example due to a MalformedURLException, then search for the resource from the classpath by calling org.apache.log4j.helpers.Loader.getResource(resource, Logger.class) which returns a URL. Note that the string "log4j.properties" constitutes a malformed URL.
See Loader.getResource(java.lang.String) for the list of searched locations.


If no URL could not be found, abort default initialization. Otherwise, configure log4j from the URL.
The PropertyConfigurator will be used to parse the URL to configure log4j unless the URL ends with the ".xml" extension, in which case the DOMConfigurator will be used. You can optionaly specify a custom configurator. The value of the log4j.configuratorClass system property is taken as the fully qualified class name of your custom configurator. The custom configurator you specify must implement the Configurator interface.


Example Configurations


Default Initialization under Tomcat


The default log4j initialization is particularly useful in web-server environments. Under Tomcat 3.x and 4.x, you should place the log4j.properties under the WEB-INF/classes directory of your web-applications. Log4j will find the properties file and initialize itself. This is easy to do and it works.


You can also choose to set the system property log4j.configuration before starting Tomcat. For Tomcat 3.x The TOMCAT_OPTS environment variable is used to set command line options. For Tomcat 4.0, set the CATALINA_OPTS environment variable instead of TOMCAT_OPTS.


Example 1


The Unix shell command


   export TOMCAT_OPTS="-Dlog4j.configuration=foobar.txt"
tells log4j to use the file foobar.txt as the default configuration file. This file should be place under the WEB-INF/classes directory of your web-application. The file will be read using the PropertyConfigurator. Each web-application will use a different default configuration file because each file is relative to a web-application.
Example 2


The Unix shell command


   export TOMCAT_OPTS="-Dlog4j.debug -Dlog4j.configuration=foobar.xml"
tells log4j to output log4j-internal debugging information and to use the file foobar.xml as the default configuration file. This file should be place under the WEB-INF/classes directory of your web-application. Since the file ends with a .xml extension, it will read using the DOMConfigurator. Each web-application will use a different default configuration file because each file is relative to a web-application.
Example 3


The Windows shell command


   set TOMCAT_OPTS=-Dlog4j.configuration=foobar.lcf -Dlog4j.configuratorClass=com.foo.BarConfigurator
tells log4j to use the file foobar.lcf as the default configuration file. This file should be place under the WEB-INF/classes directory of your web-application. Due to the definition of the log4j.configuratorClass system property, the file will be read using the com.foo.BarConfigurator custom configurator. Each web-application will use a different default configuration file because each file is relative to a web-application.
Example 4


The Windows shell command


   set TOMCAT_OPTS=-Dlog4j.configuration=file:/c:/foobar.lcf
tells log4j to use the file c:\foobar.lcf as the default configuration file. The configuration file is fully specified by the URL file:/c:/foobar.lcf. Thus, the same configuration file will be used for all web-applications.
Different web-applications will load the log4j classes through their respective classloaderss. Thus, each image of the log4j environment will act independetly and without any mutual synchronization. For example, FileAppenders defined exactly the same way in multiple web-application configurations will all attempt to write the same file. The results are likely to be less than satisfactory. You must make sure that log4j configurations of different web-applications do not use the same underlying system resource.


Initialization servlet


It is also possible to use a special servlet for log4j initialization. Here is an example,


package com.foo;


import org.apache.log4j.PropertyConfigurator;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.PrintWriter;
import java.io.IOException;


public class Log4jInit extends HttpServlet {


  public
  void init() {
    String prefix =  getServletContext().getRealPath("/");
    String file = getInitParameter("log4j-init-file");
    // if the log4j-init-file is not set, then no point in trying
    if(file != null) {
      PropertyConfigurator.configure(prefix+file);
    }
  }


  public
  void doGet(HttpServletRequest req, HttpServletResponse res) {
  }
}
Define the following servlet in the web.xml file for your web-application.


  <servlet>
    <servlet-name>log4j-init</servlet-name>
    <servlet-class>com.foo.Log4jInit</servlet-class>


    <init-param>
      <param-name>log4j-init-file</param-name>
      <param-value>WEB-INF/classes/log4j.lcf</param-value>
    </init-param>


    <load-on-startup>1</load-on-startup>
  </servlet>
Writing an initialization servlet is the most flexible way for initializing log4j. There are no constraints on the code you can place in the init() method of the servlet.


Nested Diagnostic Contexts


Most real-world systems have to deal with multiple clients simultaneously. In a typical multithreaded implementation of such a system, different threads will handle different clients. Logging is especially well suited to trace and debug complex distributed applications. A common approach to differentiate the logging output of one client from another is to instantiate a new separate logger for each client. This promotes the proliferation of loggers and increases the management overhead of logging.


A lighter technique is to uniquely stamp each log request initiated from the same client interaction. Neil Harrison described this method in the book "Patterns for Logging Diagnostic Messages," in Pattern Languages of Program Design 3, edited by R. Martin, D. Riehle, and F. Buschmann (Addison-Wesley, 1997).


To uniquely stamp each request, the user pushes contextual information into the NDC, the abbreviation of Nested Diagnostic Context. The NDC class is shown below.


  public class NDC {
    // Used when printing the diagnostic
    public static String get();


    // Remove the top of the context from the NDC.
    public static String pop();


    // Add diagnostic context for the current thread.
    public static void push(String message);


    // Remove the diagnostic context for this thread.
    public static void remove();
  }
The NDC is managed per thread as a stack of contextual information. Note that all methods of the org.apache.log4j.NDC class are static. Assuming that NDC printing is turned on, every time a log request is made, the appropriate log4j component will include the entire NDC stack for the current thread in the log output. This is done without the intervention of the user, who is responsible only for placing the correct information in the NDC by using the push and pop methods at a few well-defined points in the code. In contrast, the per-client logger approach commands extensive changes in the code.


To illustrate this point, let us take the example of a servlet delivering content to numerous clients. The servlet can build the NDC at the very beginning of the request before executing other code. The contextual information can be the client's host name and other information inherent to the request, typically information contained in cookies. Hence, even if the servlet is serving multiple clients simultaneously, the logs initiated by the same code, i.e. belonging to the same logger, can still be distinguished because each client request will have a different NDC stack. Contrast this with the complexity of passing a freshly instantiated logger to all code exercised during the client's request.


Nevertheless, some sophisticated applications, such as virtual hosting web servers, must log differently depending on the virtual host context and also depending on the software component issuing the request. Recent log4j releases support multiple hierarchy trees. This enhancement allows each virtual host to possess its own copy of the logger hierarchy.


Performance


One of the often-cited arguments against logging is its computational cost. This is a legitimate concern as even moderately sized applications can generate thousands of log requests. Much effort was spent measuring and tweaking logging performance. Log4j claims to be fast and flexible: speed first, flexibility second.


The user should be aware of the following performance issues.


Logging performance when logging is turned off.
When logging is turned off entirely or just for a set of levels, the cost of a log request consists of a method invocation plus an integer comparison. On a 233 MHz Pentium II machine this cost is typically in the 5 to 50 nanosecond range.


However, The method invocation involves the "hidden" cost of parameter construction.


For example, for some logger cat, writing,


     logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
    
incurs the cost of constructing the message parameter, i.e. converting both integer i and entry[i] to a String, and concatenating intermediate strings, regardless of whether the message will be logged or not. This cost of parameter construction can be quite high and it depends on the size of the parameters involved.
To avoid the parameter construction cost write:


      if(logger.isDebugEnabled() {
        logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));
      }
   
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.


In log4j, logging requests are made to instances of the Logger class. Logger is a class and not an interface. This measurably reduces the cost of method invocation at the cost of some flexibility.


Certain users resort to preprocessing or compile-time techniques to compile out all log statements. This leads to perfect performance efficiency with respect to logging. However, since the resulting application binary does not contain any log statements, logging cannot be turned on for that binary. In my opinion this is a disproportionate price to pay in exchange for a small performance gain.


The performance of deciding whether to log or not to log when logging is turned on.
This is essentially the performance of walking the logger hierarchy. When logging is turned on, log4j still needs to compare the level of the log request with the level of the request logger. However, loggers may not have an assigned level; they can inherit them from the logger hierarchy. Thus, before inheriting a level, the logger may need to search its ancestors.


There has been a serious effort to make this hierarchy walk to be as fast as possible. For example, child loggers link only to their existing ancestors. In the BasicConfigurator example shown earlier, the logger named com.foo.Bar is linked directly to the root logger, thereby circumventing the nonexistent com or com.foo loggers. This significantly improves the speed of the walk, especially in "sparse" hierarchies.


The typical cost of walking the hierarchy is typically 3 times slower than when logging is turned off entirely.


Actually outputting log messages
This is the cost of formatting the log output and sending it to its target destination. Here again, a serious effort was made to make layouts (formatters) perform as quickly as possible. The same is true for appenders. The typical cost of actually logging is about 100 to 300 microseconds.


See org.apache.log4.performance.Logging for actual figures.
Although log4j has many features, its first design goal was speed. Some log4j components have been rewritten many times to improve performance. Nevertheless, contributors frequently come up with new optimizations. You should be pleased to know that when configured with the SimpleLayout performance tests have shown log4j to log as quickly as System.out.println.


Conclusions


Log4j is a popular logging package written in Java. One of its distinctive features is the notion of inheritance in loggers. Using a logger hierarchy it is possible to control which log statements are output at arbitrary granularity. This helps reduce the volume of logged output and minimize the cost of logging.


One of the advantages of the log4j API is its manageability. Once the log statements have been inserted into the code, they can be controlled with configuration files. They can be selectively enabled or disabled, and sent to different and multiple output targets in user-chosen formats. The log4j package is designed so that log statements can remain in shipped code without incurring a heavy performance cost.


Acknowledgments


Many thanks to N. Asokan for reviewing the article. He is also one of the originators of the logger concept. I am indebted to Nelson Minar for encouraging me to write this article. He has also made many useful suggestions and corrections to this article. Log4j is the result of a collective effort. My special thanks go to all the authors who have contributed to the project. Without exception, the best features in the package have all originated in the user community.
Copyright ? 1999-2012 Apache Software Foundation. Licensed under the Apache Software License, Version 2.0.Apache Extras Companion for Apache log4j, Apache log4j, Apache, the Apache feather logo, the Apache Logging Services project logo, the log4j logo, and the Built by Maven logo are trademarks of The Apache Software Foundation. Oracle and Java are registered trademarks of Oracle and/or its affiliates. Other names may be trademarks of their respective owners.