SLF4J extensions

SLF4J extensions are packaged within slf4j-ext.jar which ships with SLF4J.

Profilers

What is a profiler?

According to wikipedia, profiling is the investigation of a program's behavior using information gathered as the program runs, i.e. it is a form of dynamic program analysis, as opposed to static code analysis. The usual goal of performance analysis is to determine which parts of a program to optimize for speed or memory usage.

SLF4J profilers, a.k.a. poor man's profilers, will help the developer gather performance data. Essentially, a profiler consists of one or more stopwatches. Stopwatches are driven (started/stopped) by statements in the source code. An example should make the point clearer.

Basic example

Example: Using the profiler: BasicProfilerDemo 
[omitted]
32  public class BasicProfilerDemo {
33  
34    public static void main(String[] args) {
35      // create a profiler called "BASIC"
36      Profiler profiler = new Profiler("BASIC");
37      profiler.start("A");
38      doA();
39  
40      profiler.start("B");
41      doB();
42      
43      profiler.start("OTHER");
44      doOther();
45      profiler.stop().print();
46    }
[omitted]

Running the above example will output the following output.

+ Profiler [BASIC] |-- elapsed time [A] 220.487 milliseconds. |-- elapsed time [B] 2499.866 milliseconds. |-- elapsed time [OTHER] 3300.745 milliseconds. |-- Total [BASIC] 6022.568 milliseconds.

Instantiating a profiler starts a global stopwatch. Each call to the start() method starts a new and named stopwatch. In addition to starting a named stopwatch, the start() method also causes the previous stopwatch to stop. Thus, the call to profiler.start("A") starts a stopwatch named "A". The subsequent call to profiler.start("B") starts stopwatch "B" and simultaneously stops the stopwatch named "A". Invoking the stop() on a profiler stops the last stopwatch as well as the global stopwatch which was started when the profiler was instantiated.

Profiler nesting

Profilers can also be nested. By nesting profilers, it is possible to measure a task which itself has subtasks that need to be timed and measured.

Starting a nested profiler will stop any previously started stopwatch or nested profiler associated with the parent profiler.

Often times, the subtask is implemented by a different class as the class hosting the parent profiler. Using the ProfilerRegistry is a convenient way of passing a nested profiler to an object outside the current object. Each thread has its own profiler registry which can be retrieved by invoking the getThreadContextInstance() method.

Example: NestedProfilerDemo 
33  public class NestedProfilerDemo {
34    
35    public static void main(String[] args) {
36      // create a profiler called "DEMO"
37      Profiler profiler = new Profiler("DEMO");
38      
39      // register this profiler in the thread context's profiler registry
40      ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
41      profiler.registerWith(profilerRegistry);
42      
43      // start a stopwatch called "RANDOM"
44      profiler.start("RANDOM");
45      RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator();
46      int n = 1000*1000;
47      int[] randomArray = riaGenerator.generate(n);
48      
49      // create and start a nested profiler called "SORT_AND_PRUNE"
50      // By virtue of its parent-child relationship with the "DEMO"
51      // profiler, and the previous registration of the parent profiler, 
52      // this nested profiler will be automatically registered
53      // with the thread context's profiler registry
54      profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);
55      
56      SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
57      pruner.sortAndPruneComposites();
58      
59      // stop and print the "DEMO" printer
60      profiler.stop().print();
61    }
62  }

Here is the relevant excerpt from the SortAndPruneComposites class. 

[omitted]
6   public class SortAndPruneComposites {
7   
8     static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
9     
10    final int[] originalArray;
11    final int originalArrayLength;
12    
13    public SortAndPruneComposites(int[] randomArray) {
14      this.originalArray = randomArray;
15      this.originalArrayLength = randomArray.length;
16     
17    }
18    
19    public int[] sortAndPruneComposites() {
20      // retrieve previously registered profiler named "SORT_AND_PRUNE"
21      ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
22      Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);
23  
24      // start a new stopwatch called SORT
25      sortProfiler.start("SORT");
26      int[] sortedArray = sort();
27      // start a new stopwatch called PRUNE_COMPOSITES
28      sortProfiler.start("PRUNE_COMPOSITES");
29      int result[] = pruneComposites(sortedArray);
30      
31      return result;
32    }
[omitted]

On a Dual-Core Intel CPU clocked at 3.2 GHz, running the ProfilerDemo application yields the following output:

+ Profiler [DEMO] |-- elapsed time [RANDOM] 70.524 milliseconds. |---+ Profiler [SORT_AND_PRUNE] |-- elapsed time [SORT] 665.281 milliseconds. |-- elapsed time [PRUNE_COMPOSITES] 5695.515 milliseconds. |-- Subtotal [SORT_AND_PRUNE] 6360.866 milliseconds. |-- elapsed time [SORT_AND_PRUNE] 6360.866 milliseconds. |-- Total [DEMO] 6433.922 milliseconds.

From the above, we learn that generating 1'000'000 random integers takes 70 ms, sorting them 665 ms, and pruning the composite (non-prime) integers 5695 ms, for a grand total of 6433 ms. Given that pruning composites takes most of the CPU effort, any future optimizations efforts would be directed at the pruning part.

With just a few well-placed profiler calls we were able to identify hot-spots in our application. Also note that passing a profiler to a target class could be achieved by registering it in a profiler registry and then retrieving it in the target class.

Printing using a logger

Invoking profiler.print will always print the output on the console. If you wish to leave the profiler code in production, then you probably need more control over the output destination. This can be accomplished by associating a logger of your choice with a profiler.

After you have associated a logger with a profiler, you would invoke the log() method instead of print() previously, as the next example illustrates.

Profiler with a logger: NestedProfilerDemo2 
[omitted]
17  public class NestedProfilerDemo2 {
18  
19    static Logger logger = LoggerFactory.getLogger(NestedProfilerDemo2.class);
20    
21    public static void main(String[] args) {
22      Profiler profiler = new Profiler("DEMO");
23      // associate a logger with the profiler
24      profiler.setLogger(logger);
25      
26      ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
27      profiler.registerWith(profilerRegistry);
28      
29      profiler.start("RANDOM");
30      RandomIntegerArrayGenerator riaGenerator = new RandomIntegerArrayGenerator();
31      int n = 10*1000;
32      int[] randomArray = riaGenerator.generate(n);
33      
34      profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);
35      
36      SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
37      pruner.sortAndPruneComposites();
38      
39      // stop and log
40      profiler.stop().log();
41    }
42  }

The output generated by this example will depend on the logging environment, but should be very similar to the output generated by the previous NestedProfilerDemo example.

The log() method logs at level DEBUG using a marker named "PROFILER".

If your logging system supports markers, e.g. logback, you could specifically enable or disable output generated by SLF4J profilers. Here is logback configuration file disabling output for any logging event bearing the "PROFILER" marker, even if the logger used by the profiler is enabled for the debug level.

logback configuration disabling logging from profilers, and only profilers 
<configuration>

  <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>PROFILER</Marker>
    <OnMatch>DENY</OnMatch>
  </turboFilter>
    
  <appender name="STDOUT"
    class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%-5level %logger{36} - %msg%n</Pattern>
    </layout>
  </appender>

  <root>
    <level value="DEBUG" />
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

MDCStrLookup

StrLookup is a class defined in Apache Commons Lang. It is used in conjunction with the StrSubstitutor class to allow Strings to have tokens in the Strings dynamically replaced at run time. There are many cases where it is desirable to merge the values for keys in the SLF4J MDC into Strings. MDCStrLookup makes this possible.

Apache Commons Configuration provides a ConfigurationInterpolator class. This class allows new StrLookups to be registered and the values can then be used to merge with both the configuration of Commons Configuration as well as the configuration files it manages.

StrLookup obviously has a dependency on Commons Lang. The Maven pom.xml for slf4j-ext lists this dependency as optional so that those wishing to use other extensions are not required to unnecessarily package the commons lang jar. Therefore, when using MDCStrLookup the dependency for commons-lang must be explicitly declared along with slf4j-ext.

Extended Logger

The XLogger class provides a few extra logging methods that are quite useful for following the execution path of applications. These methods generate logging events that can be filtered separately from other debug logging. Liberal use of these methods is encouraged as the output has been found to

The two most used methods are the entry() and exit() methods. entry() should be placed at the beginning of methods, except perhaps for simple getters and setters. entry() can be called passing from 0 to 4 parameters. Typically these will be parameters passed to the method. The entry() method logs with a level of TRACE and uses a Marker with a name of "ENTER" which is also a "FLOW" Marker.

The exit() method should be placed before any return statement or as the last statement of methods without a return. exit() can be called with or without a parameter. Typically, methods that return void will use exit() while methods that return an Object will use exit(Object obj). The entry() method logs with a level of TRACE and uses a Marker with a name of "EXIT" which is also a "FLOW" Marker.

The throwing() method can be used by an application when it is throwing an exception that is unlikely to be handled, such as a RuntimeException. This will ensure that proper diagnostics are available if needed. The logging event generated will have a level of ERROR and will have an associated Marker with a name of "THROWING" which is also an "EXCEPTION" Marker.

The catching() method can be used by an application when it catches an Exception that it is not going to rethrow, either explicitly or attached to another Exception. The logging event generated will have a level of ERROR and will have an associated Marker with a name of "CATCHING" which is also an "EXCEPTION" Marker.

By using these extended methods applications that standardize on SLF4J can be assured that they will be able to perform diagnostic logging in a standardized manner.

Note that XLogger instances are obtained to through the XLoggerFactory utility class.

The following example shows a simple application using these methods in a fairly typical manner. The throwing() method is not present since no Exceptions are explicitly thrown and not handled. 

package com.test;

import org.slf4j.ext.XLogger;
import org.slf4j.ext.XLoggerFactory;

import java.util.Random;

public class TestService {
  private XLogger logger = XLoggerFactory.getXLogger(TestService.class
      .getName());

  private String[] messages = new String[] { "Hello, World",
      "Goodbye Cruel World", "You had me at hello" };

  private Random rand = new Random(1);

  public String retrieveMessage() {
    logger.entry();

    String testMsg = getMessage(getKey());

    logger.exit(testMsg);
    return testMsg;
  }

  public void exampleException() {
    logger.entry();
    try {
      String msg = messages[messages.length];
      logger.error("An exception should have been thrown");
    } catch (Exception ex) {
      logger.catching(ex);
    }
    logger.exit();
  }

  public String getMessage(int key) {
    logger.entry(key);

    String value = messages[key];

    logger.exit(value);
    return value;
  }

  private int getKey() {
    logger.entry();
    int key = rand.nextInt(messages.length);
    logger.exit(key);
    return key;
  }
}

This test application uses the preceding service to generate logging events. 

package com.test;

public class App {
  public static void main( String[] args )    {
    TestService service = new TestService();
    service.retrieveMessage();
    service.retrieveMessage();
    service.exampleException();
  }
}

The configuration below will cause all output to be routed to target/test.log. The pattern for the FileAppender includes the class name, line number and method name. Including these in the pattern are critical for the log to be of value. 

<?xml version='1.0' encoding='UTF-8'?>
<configuration>
  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
      <level>ERROR</level>
      <onMatch>ACCEPT</onMatch>
      <onMismatch>DENY</onMismatch>
    </filter>
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern>
    </layout>
  </appender>
  <appender name="log" class="ch.qos.logback.core.FileAppender">
    <File>target/test.log</File>
    <Append>false</Append>
    <layout class="ch.qos.logback.classic.PatternLayout">
      <Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern>
    </layout>
  </appender>

  <root>
    <level value="trace" />
    <appender-ref ref="log" />
  </root>
</configuration>

Here is the output that results from the Java classes and configuration above.

00:07:57.725 TRACE com.test.TestService:22 retrieveMessage - entry 00:07:57.738 TRACE com.test.TestService:57 getKey - entry 00:07:57.739 TRACE com.test.TestService:59 getKey - exit with (0) 00:07:57.741 TRACE com.test.TestService:47 getMessage - entry with (0) 00:07:57.741 TRACE com.test.TestService:51 getMessage - exit with (Hello, World) 00:07:57.742 TRACE com.test.TestService:26 retrieveMessage - exit with (Hello, World) 00:07:57.742 TRACE com.test.TestService:22 retrieveMessage - entry 00:07:57.742 TRACE com.test.TestService:57 getKey - entry 00:07:57.743 TRACE com.test.TestService:59 getKey - exit with (1) 00:07:57.745 TRACE com.test.TestService:47 getMessage - entry with (1) 00:07:57.745 TRACE com.test.TestService:51 getMessage - exit with (Goodbye Cruel World) 00:07:57.746 TRACE com.test.TestService:26 retrieveMessage - exit with (Goodbye Cruel World) 00:07:57.746 TRACE com.test.TestService:32 exampleException - entry 00:07:57.750 ERROR com.test.TestService:40 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3 at com.test.TestService.exampleException(TestService.java:35) at com.test.AppTest.testApp(AppTest.java:39) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at junit.framework.TestCase.runTest(TestCase.java:154) at junit.framework.TestCase.runBare(TestCase.java:127) at junit.framework.TestResult$1.protect(TestResult.java:106) at junit.framework.TestResult.runProtected(TestResult.java:124) at junit.framework.TestResult.run(TestResult.java:109) at junit.framework.TestCase.run(TestCase.java:118) at junit.framework.TestSuite.runTest(TestSuite.java:208) at junit.framework.TestSuite.run(TestSuite.java:203) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) at org.apache.maven.surefire.Surefire.run(Surefire.java:177) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997) 00:07:57.750 TRACE com.test.TestService:42 exampleException - exit

Simply changing the root logger level to DEBUG in the example above will reduce the output considerably.

00:28:06.004 ERROR com.test.TestService:40 exampleException - catching java.lang.ArrayIndexOutOfBoundsException: 3 at com.test.TestService.exampleException(TestService.java:35) at com.test.AppTest.testApp(AppTest.java:39) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at junit.framework.TestCase.runTest(TestCase.java:154) at junit.framework.TestCase.runBare(TestCase.java:127) at junit.framework.TestResult$1.protect(TestResult.java:106) at junit.framework.TestResult.runProtected(TestResult.java:124) at junit.framework.TestResult.run(TestResult.java:109) at junit.framework.TestCase.run(TestCase.java:118) at junit.framework.TestSuite.runTest(TestSuite.java:208) at junit.framework.TestSuite.run(TestSuite.java:203) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140) at org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127) at org.apache.maven.surefire.Surefire.run(Surefire.java:177) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:585) at org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:338) at org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:997)