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> + _______________________________________________ dev mailing list dev@slf4j.org http://www.slf4j.org/mailman/listinfo/dev
