View RSS Feed

jlczuk

Java Logging - Practical Usage

Rate this Entry
by , 04-25-2012 at 04:53 PM (3824 Views)
Introduction
The intent of the post is not to delve into all the detail around setting up Java logging for an application. So you won't find any information here about Filters, Formatter and Handlers. For all those details, I invite you to visit Oracle's JavaTM Logging Technology documentation site and read the Overview.

When problems occur in complex Java applications, symptoms are generally detected as incorrect data or as exceptions. In the case of exceptions, we get stack traces to help us understand the root cause of the exception. But even there, all we get is the call stack starting with the originator of the exception. Often times, this provides insufficient information to determine what the true problem is and the necessary corrective action.

The general purpose of logging is to provide insight into the flow of control and information through a Java application. Logging provides historical context that augments the information found in exception stack traces. It is most beneficial in complex applications where there frameworks of classes are being used. Logging, also known as tracing in some circles, provides critical information that is often times needed when debugging complex Java applications, especially those associated with Web applications, where the flow of control among servlets generating web requests among multiple servers and interact with databases.

This article provides some practical pointers about applying Java logging and some things to consider that can impact the performance of applications.

An Example
This is a short example in which the use of <> is used to identify footnotes.
Java Code:
import java.util.logging.Level;
import java.util.logging.Logger;

public class LoggingExample {
    // <1>
    private static final String CLASS_NAME = LoggingExample.class.getCanonicalName();
    private static final String PKG_NAME = LoggingExample.class.getPackage().getName();
    private static Logger logger = Logger.getLogger(PKG_NAME);

    public void justOneMethod(String aParam)  {

        final String mname = "justOneMethod";
        logger.entering(CLASS_NAME, mname, aParam);  // <2>

        String someResult = "random result";
        
        // Pretend we did a bunch of stuff and need to log at different
        // levels as we move through the processing.
        if (logger.isLoggable(Level.INFO))  {  // <3>
            logger.log(Level.INFO, "Some informational logging.");
        }
        
        // There are several logging levels that range from INFO/WARNING/SEVERE 
        // to FINE/FINER/FINEST.  There are others as well, refer to the Level 
        // class to learn about them.
        if (logger.isLoggable(Level.FINEST))  {  // <3>
            logger.log(Level.FINEST, 
                String.format("Here's a lot of detail: %s %d %c", "detail1", 25, 'x'));
        }


        logger.exiting(CLASS_NAME, mname, someResult); // <2>
    }
}

  1. By adopting a convention of specifying the PKG_NAME and CLASS_NAME when logging, it facilitates a more uniform log which will be easier to read and interpret. By having each class define a logger instance in the same way, we adopt a coding convention that makes the implementation of logging within larger development teams more consistent.
  2. It is helpful when debugging to know when each method is entered and exited. Logging provides the ability to include input parameters and returned values or instance data in the entry/exit log records. Later on, we'll see how we can provide very detailed entry/exit traces depending on the trace level that is set in the application.
  3. This construct is known as a log guard. The purpose of it is to prevent Java from preparing to log when the log level required is not set. We will elaborate on this in the section of log guards.


Log Guards
Why do we need to use log guards when the Logger class already has methods like info(), warning(), finest(), etc, where the method itself determines if the appropriate log level has been set prior to creating the log record? The answer is because well constructed log records will have dynamically generated strings and because of the nature of logging, are always in high-frequency usage mainline paths. In complex applications, logging is everywhere and it can have a negative impact on application performance. Log guards provide the means to minimize the impact that string preparation performed by logging can have on application performance.

The String class' format method is an extremely powerful tool because it allows us to specify a pattern for the caller-supplied textual content of trace records. String formatting is not cheap though and it adds up when you do a lot of it. Consider the following example that does not use a log guard.
Java Code:
logger.finest(String.format("appname(%s) comp(%s) actual(%d)", app, component, interest);
When that statement is processed, Java will have to process the string formatting in order to prepare the parameter to be passed to the Logger.finest() method. Only then can the finest() method check the logging level to determine whether or not to actually write the log record. The string process had to be done even if the log level had been set to INFO.

By using a log guard, we prevent the unnecessary string formatting from occurring except when the logging level is set to the level required for that log record.

Detailed Entry/Exit LoggingIn the first example of this article, we demonstrated simple entry and exit logging whereby input and output parameters can be included in the log records. If the method in question had been either taken an object as an input parameter or returned an object, the logging of those could become expensive. This is because the tendency is to use toString() methods of such objects to facilitate logging.

In these cases, the use of log guards even with the entry and exit traces will help. If the logging level is FINEST, do the detailed entry/exit logging, otherwise, do the simple entry/exit logging. Here's an example of the justOneMethod method using this technique.

Java Code:
    public void justOneMethod(ComplexObject aParam)  {
        final String mname = "justOneMethod";
     
        // Only log the ComplexObject parameter's contents when logging
        // is set to FINEST.  
        if (logger.isLoggable(Level.FINEST)) { 
            logger.entering(CLASS_NAME, mname, aParam.toString());
        }
        else  {
            logger.entering(CLASS_NAME, mname);
        }
        
        ComplexObject result = aParam.doStuff();

        // Only log the result's contents when logging
        // is set to FINEST.  
        if (logger.isLoggable(Level.FINEST)) { 
            logger.exiting(CLASS_NAME, mname, result.toString());
        }
        else  {
            logger.exiting(CLASS_NAME, mname);
        }
    }

Conclusion
The capabilities provided by Java Logging are an important part of being able to support problem determination in large Java applications. If not used wisely, Java Logging can have a negative impact on application performance.

Submit "Java Logging - Practical Usage" to Facebook Submit "Java Logging - Practical Usage" to Digg Submit "Java Logging - Practical Usage" to del.icio.us Submit "Java Logging - Practical Usage" to StumbleUpon Submit "Java Logging - Practical Usage" to Google

Comments