[slf4j-dev] svn commit: r1199 - slf4j/trunk/slf4j-site/src/site/pages
ceki at slf4j.org
ceki at slf4j.org
Thu Oct 16 17:27:03 CEST 2008
Author: ceki
Date: Thu Oct 16 17:27:03 2008
New Revision: 1199
Modified:
slf4j/trunk/slf4j-site/src/site/pages/extensions.html
Log:
- mostly indentation changes
Otherwise,
- added a reference to XLogger javadocs
- added a reference to XLoggerFactory javadocs
- explicitly was spelled as explicitely
Modified: slf4j/trunk/slf4j-site/src/site/pages/extensions.html
==============================================================================
--- slf4j/trunk/slf4j-site/src/site/pages/extensions.html (original)
+++ slf4j/trunk/slf4j-site/src/site/pages/extensions.html Thu Oct 16 17:27:03 2008
@@ -1,542 +1,569 @@
-<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/2000/REC-xhtml1-20000126/DTD/xhtml1-transitional.dtd">
-<html xmlns="http://www.w3.org/1999/xhtml">
-<head>
-<meta http-equiv="content-type" content="text/html; charset=iso-8859-1" />
-<title>SLF4J extensions</title>
-
-<link rel="stylesheet" type="text/css" media="screen" href="css/site.css" />
-</head>
-<body>
- <script>
-prefix='';
-</script>
-
-<script src="templates/header.js"></script>
-<div id="left">
- <script src="templates/left.js"></script>
-</div>
-<div id="content">
-
- <h1>SLF4J extensions</h1>
-
- <p>SLF4J extensions are packaged within <em>slf4j-ext.jar</em>
- which ships with SLF4J.</p>
-
- <h2>Profilers</h2>
-
- <h3>What is a profiler?</h3>
-
- <p>According to wikipedia, <a
- href="http://en.wikipedia.org/wiki/Profiler_%28computer_science%29">profiling</a>
- 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.
- </p>
-
- <p>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 <em>source code</em>. An
- example should make the point clearer.
- </p>
-
- <h3>Basic example</h3>
-
-
- <em>Example: Using the profiler: <a
- href="xref-test/org/slf4j/profiler/BasicProfilerDemo.html">BasicProfilerDemo</a></em>
-
- <p class="source">[omitted]
-32 public class BasicProfilerDemo {
-33
-34 public static void main(String[] args) {
-35 // create a profiler called "BASIC"
-36 <b>Profiler profiler = new Profiler("BASIC");</b>
-37 <b>profiler.start("A");</b>
-38 doA();
-39
-40 <b>profiler.start("B");</b>
-41 doB();
-42
-43 <b>profiler.start("OTHER");</b>
-44 doOther();
-45 <b>profiler.stop().print();</b>
-46 }
-[omitted]</p>
-
-
- <p>Running the above example will output the following output.</p>
-
- <p class="source">+ 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.</p>
-
- <p>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
- <code>profiler.start("A")</code> starts a stopwatch named "A". The
- subsequent call to <code>profiler.start("B")</code> starts
- stopwatch "B" and simultaneously stops the stopwatch named
- "A". Invoking the <code>stop()</code> on a profiler method stops
- the last stopwatch as well as the global stopwatch which was
- started when the profiler was instantiated.
- </p>
-
-
- <h3>Profiler nesting</h3>
-
- <p>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.
- </p>
-
- <p>Starting a nested profiler will stop any previously started
- stopwatch or nested profiler associated with the parent profiler.
- </p>
-
- <p>Often times, the subtask is implemented by a different class as
- the class hosting the parent profiler. Using the
- <code>ProfilerRegistry</code> 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 <code>getThreadContextInstance()</code> method.
- </p>
-
- <em>Example: <a
- href="xref-test/org/slf4j/profiler/NestedProfilerDemo.html">NestedProfilerDemo</a>
- </em>
-
- <p class="source">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 <b>ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();</b>
-41 <b>profiler.registerWith(profilerRegistry);</b>
-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 <b>profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);</b>
-55
-56 SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
-57 pruner.sortAndPruneComposites();
-58
-59 // stop and print the "DEMO" printer
-60 profiler.stop().print();
-61 }
-62 }</p>
-
- <p>Here is the relevant excerpt from the <a
- href="xref-test/org/slf4j/profiler/SortAndPruneComposites.html">SortAndPruneComposites</a>
- class.
- </p>
-
- <p class="source">[omitted]
-6 public class SortAndPruneComposites {
-7
-8 static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
-9
-10 final int[] originalArray;
-11 final int originalArrrayLength;
-12
-13 public SortAndPruneComposites(int[] randomArray) {
-14 this.originalArray = randomArray;
-15 this.originalArrrayLength = randomArray.length;
-16
-17 }
-18
-19 public int[] sortAndPruneComposites() {
-20 // retrieve previously registered profiler named "SORT_AND_PRUNE"
-21 ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
-22 <b>Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);</b>
-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] </p>
-
-
- <p>On a Dual-Core Intel CPU clocked at 3.2 GHz, running the
- <code>ProfilerDemo</code> application yields the following output:</p>
-
- <p class="source">+ 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.</p>
-
- <p>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.
- </p>
-
- <p>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.
- </p>
-
- <h3>Printing using a logger</h3>
-
- <p> Invoking <code>profiler.print</code> 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.
- </p>
-
- <p>After you have associated a logger with a profiler, you would
- invoke the <code>log()</code> method instead of <code>print()</code>
- previously, as the next example illustrates.
- </p>
-
- <em>Profiler with a logger: <a
- href="xref-test/org/slf4j/profiler/NestedProfilerDemo2.html">NestedProfilerDemo2</a>
- </em>
-
- <p class="source">[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 <b>profiler.setLogger(logger);</b>
-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().<b>log()</b>;
-41 }
-42 } </p>
-
- <p>The output generated by this example will depend on the logging
- environment, but should be very similar to the output generated by
- the previous <code>NestedProfilerDemo</code> example.
- </p>
-
- <p>The log() method logs at level DEBUG using a marker named
- "PROFILER".</p>
-
- <p>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.
- </p>
-
-
- <em>logback configuration disabling logging from profilers, and only
- profilers</em>
-
- <p class="source"><configuration>
-
- <b><turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
- <Marker>PROFILER</Marker>
- <OnMatch>DENY</OnMatch>
- </turboFilter></b>
-
- <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> </p>
- <h2>Extended Logger</h2>
-
- <p>
- 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
- <ul>
- <li>aid in problem diagnosis in development without requiring a debug session</li>
- <li>aid in problem diagnosis in production where no debugging is possible</li>
- <li>help educate new deveopers in learning the application.</li>
- </ul>
- </p>
- <p>
- The two most used methods are the entry() and exit() methods. entry() should be placed at the
- beginning of methods, except perhaps ofr 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.
- </p>
- <p>
- 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.
- </p>
- <p>
- The throwing() method can be used by an application when it is throwing an exception that is
- unlikely to be handled, such as a RuntimeExcpetion. This will insure 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.
- </p>
- <p>
- The catching() method can be used by an application when it catches an Exception that it is not
- going to rethrow, either explicitely 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.
- </p>
- <p>
- 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.
- </p>
- <p>
- The following example shows a simple application using these methods in a fairly typcial manner. The
- throwing() is not present since no Exceptions are explicitely thrown and not handled.
- </p>
-<p class="source">
- 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;
- }
- }
-</p>
- <p>
- This test application uses the preceding service to generate logging events.
- </p>
-<p class="source">
-package com.test;
-
-public class App
-{
- public static void main( String[] args )
- {
- TestService service = new TestService();
- service.retrieveMessage();
- service.retrieveMessage();
- service.exampleException();
- }
-}
-</p>
- <p>
- 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.
- </p>
-<p class="source">
-<?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>
-</p>
- <p>
- Here is the output that results from the Java classes and configuration above.
- </p>
-<p class="source">
- 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
-</p>
- <p>
- Simply changing the root logger level to DEBUG in the example above will reduce the output
- considerably.
- </p>
-<p class="source">
- 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)
-</p>
-</div>
-</body>
-</html>
-
-
-impersonating Raplh Goers for testing email notifications
-impersonating Raplh Goers for testing email notifications
-impersonating Raplh Goers for testing email notifications
+<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/2000/REC-xhtml1-20000126/DTD/xhtml1-transitional.dtd">
+<html xmlns="http://www.w3.org/1999/xhtml">
+<head>
+<meta http-equiv="content-type" content="text/html; charset=iso-8859-1" />
+<title>SLF4J extensions</title>
+
+<link rel="stylesheet" type="text/css" media="screen" href="css/site.css" />
+</head>
+<body>
+ <script>
+prefix='';
+</script>
+
+<script src="templates/header.js"></script>
+<div id="left">
+ <script src="templates/left.js"></script>
+</div>
+<div id="content">
+
+ <h1>SLF4J extensions</h1>
+
+ <p>SLF4J extensions are packaged within <em>slf4j-ext.jar</em>
+ which ships with SLF4J.</p>
+
+ <h2>Profilers</h2>
+
+ <h3>What is a profiler?</h3>
+
+ <p>According to wikipedia, <a
+ href="http://en.wikipedia.org/wiki/Profiler_%28computer_science%29">profiling</a>
+ 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.
+ </p>
+
+ <p>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 <em>source code</em>. An
+ example should make the point clearer.
+ </p>
+
+ <h3>Basic example</h3>
+
+
+ <em>Example: Using the profiler: <a
+ href="xref-test/org/slf4j/profiler/BasicProfilerDemo.html">BasicProfilerDemo</a></em>
+
+ <p class="source">[omitted]
+32 public class BasicProfilerDemo {
+33
+34 public static void main(String[] args) {
+35 // create a profiler called "BASIC"
+36 <b>Profiler profiler = new Profiler("BASIC");</b>
+37 <b>profiler.start("A");</b>
+38 doA();
+39
+40 <b>profiler.start("B");</b>
+41 doB();
+42
+43 <b>profiler.start("OTHER");</b>
+44 doOther();
+45 <b>profiler.stop().print();</b>
+46 }
+[omitted]</p>
+
+
+ <p>Running the above example will output the following output.</p>
+
+ <p class="source">+ 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.</p>
+
+ <p>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
+ <code>profiler.start("A")</code> starts a stopwatch named "A". The
+ subsequent call to <code>profiler.start("B")</code> starts
+ stopwatch "B" and simultaneously stops the stopwatch named
+ "A". Invoking the <code>stop()</code> on a profiler method stops
+ the last stopwatch as well as the global stopwatch which was
+ started when the profiler was instantiated.
+ </p>
+
+
+ <h3>Profiler nesting</h3>
+
+ <p>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.
+ </p>
+
+ <p>Starting a nested profiler will stop any previously started
+ stopwatch or nested profiler associated with the parent profiler.
+ </p>
+
+ <p>Often times, the subtask is implemented by a different class as
+ the class hosting the parent profiler. Using the
+ <code>ProfilerRegistry</code> 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 <code>getThreadContextInstance()</code> method.
+ </p>
+
+ <em>Example: <a
+ href="xref-test/org/slf4j/profiler/NestedProfilerDemo.html">NestedProfilerDemo</a>
+ </em>
+
+ <p class="source">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 <b>ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();</b>
+41 <b>profiler.registerWith(profilerRegistry);</b>
+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 <b>profiler.startNested(SortAndPruneComposites.NESTED_PROFILER_NAME);</b>
+55
+56 SortAndPruneComposites pruner = new SortAndPruneComposites(randomArray);
+57 pruner.sortAndPruneComposites();
+58
+59 // stop and print the "DEMO" printer
+60 profiler.stop().print();
+61 }
+62 }</p>
+
+ <p>Here is the relevant excerpt from the <a
+ href="xref-test/org/slf4j/profiler/SortAndPruneComposites.html">SortAndPruneComposites</a>
+ class.
+ </p>
+
+ <p class="source">[omitted]
+6 public class SortAndPruneComposites {
+7
+8 static String NESTED_PROFILER_NAME = "SORT_AND_PRUNE";
+9
+10 final int[] originalArray;
+11 final int originalArrrayLength;
+12
+13 public SortAndPruneComposites(int[] randomArray) {
+14 this.originalArray = randomArray;
+15 this.originalArrrayLength = randomArray.length;
+16
+17 }
+18
+19 public int[] sortAndPruneComposites() {
+20 // retrieve previously registered profiler named "SORT_AND_PRUNE"
+21 ProfilerRegistry profilerRegistry = ProfilerRegistry.getThreadContextInstance();
+22 <b>Profiler sortProfiler = profilerRegistry.get(NESTED_PROFILER_NAME);</b>
+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] </p>
+
+
+ <p>On a Dual-Core Intel CPU clocked at 3.2 GHz, running the
+ <code>ProfilerDemo</code> application yields the following output:</p>
+
+ <p class="source">+ 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.</p>
+
+ <p>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.
+ </p>
+
+ <p>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.
+ </p>
+
+ <h3>Printing using a logger</h3>
+
+ <p> Invoking <code>profiler.print</code> 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.
+ </p>
+
+ <p>After you have associated a logger with a profiler, you would
+ invoke the <code>log()</code> method instead of <code>print()</code>
+ previously, as the next example illustrates.
+ </p>
+
+ <em>Profiler with a logger: <a
+ href="xref-test/org/slf4j/profiler/NestedProfilerDemo2.html">NestedProfilerDemo2</a>
+ </em>
+
+ <p class="source">[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 <b>profiler.setLogger(logger);</b>
+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().<b>log()</b>;
+41 }
+42 } </p>
+
+ <p>The output generated by this example will depend on the logging
+ environment, but should be very similar to the output generated by
+ the previous <code>NestedProfilerDemo</code> example.
+ </p>
+
+ <p>The log() method logs at level DEBUG using a marker named
+ "PROFILER".</p>
+
+ <p>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.
+ </p>
+
+
+ <em>logback configuration disabling logging from profilers, and only
+ profilers</em>
+
+ <p class="source"><configuration>
+
+ <b><turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
+ <Marker>PROFILER</Marker>
+ <OnMatch>DENY</OnMatch>
+ </turboFilter></b>
+
+ <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> </p>
+
+ <h2>Extended Logger</h2>
+
+ <p>The <a
+ href="apidocs/org/slf4j/ext/XLogger.html"><code>XLogger</code></a>
+ 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
+ </p>
+
+ <ul>
+ <li>aid in problem diagnosis in development without requiring a
+ debug session</li>
+
+ <li>aid in problem diagnosis in production where no debugging is
+ possible</li>
+
+ <li>help educate new deveopers in learning the application.</li>
+ </ul>
+
+
+ <p>The two most used methods are the <code>entry()</code> and
+ <code>exit()</code> methods. <code>entry()</code> should be placed
+ at the beginning of methods, except perhaps for simple getters and
+ setters. <code>entry()</code> can be called passing from 0 to 4
+ parameters. Typically these will be parameters passed to the
+ method. The <code>entry()</code> method logs with a level of TRACE
+ and uses a <code>Marker</code> with a name of "ENTER" which is also
+ a "FLOW" Marker.
+ </p>
+
+ <p>The <code>exit()</code> method should be placed before any
+ return statement or as the last statement of methods without a
+ return. <code>exit()</code> can be called with or without a
+ parameter. Typically, methods that return void will use
+ <code>exit()</code> while methods that return an Object will use
+ exit(Object obj). The <code>entry()</code> method logs with a
+ level of TRACE and uses a Marker with a name of "EXIT" which is
+ also a "FLOW" Marker.
+ </p>
+
+ <p>The throwing() method can be used by an application when it is
+ throwing an exception that is unlikely to be handled, such as a
+ RuntimeExcpetion. This will insure 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.
+ </p>
+
+ <p>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.
+ </p>
+
+ <p>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.
+ </p>
+
+ <p>Note thar XLogger instances are obrained to through the
+ <a
+ href="apidocs/org/slf4j/ext/XLoggerFactory.html"><code>XLoggerFactory</code></a>
+ utility class.</p>
+
+ <p>The following example shows a simple application using these
+ methods in a fairly typcial manner. The <code>throwing()</code>
+ method is not present since no Exceptions are explicitly thrown and
+ not handled.
+ </p>
+
+<p class="source">
+ 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;
+ }
+ }
+</p>
+
+ <p>
+ This test application uses the preceding service to generate
+ logging events.
+ </p>
+
+<p class="source">
+package com.test;
+
+public class App
+{
+ public static void main( String[] args )
+ {
+ TestService service = new TestService();
+ service.retrieveMessage();
+ service.retrieveMessage();
+ service.exampleException();
+ }
+}
+</p>
+ <p>
+ 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.
+ </p>
+<p class="source">
+<?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>
+</p>
+ <p>
+ Here is the output that results from the Java classes and configuration above.
+ </p>
+<p class="source">
+ 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
+</p>
+ <p>
+ Simply changing the root logger level to DEBUG in the example above will reduce the output
+ considerably.
+ </p>
+<p class="source">
+ 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)
+</p>
+</div>
+</body>
+</html>
+
More information about the slf4j-dev
mailing list