SLF4J 扩展（一）

SLF4J 扩展被打包在 slf4j-ext.jar里，它随着 SLF4J 一起发布。

主要内容包含如下几部分：

• 性能分析器（Profiler）
• MDCStrLookup
• 扩展日志（Extended logger）
• 事件日志（Event Logging）
• 通过Java 代理（agent）来添加日志

性能分析器（Profiler）

什么是性能分析器？

根据维基百科（Wikipedia）介绍，性能分析（Profiling）
是通过搜集程序时的信息，来对程序行为进行一种研究分析活动，相对于静态的代码分析来说，这是一种动态的程序分析。

性能分析一般是为了确定对程序中哪块部分的运行速度或者内存使用进行优化。

SLF4J 性能分析器，可以说是一种弱分析器，将帮助开发人员搜集性能数据。本质上来讲，性能分析器就是由一个或者多个秒表（stopwatches）组成的。秒表由源码中的语句来驱动开始或者结束。一个示例也许将这点解释得更明了。

基本示例

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    }

运行上面的示例将输出如下内容：

+ 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.

实例化一个性能分析器就启动了一个全局秒表。每次调用 start() 方法将启动一个新的被命名了的秒表。除了启动一个命名了的秒表， start() 方法还将引起上一个秒表停止。因此，调用 profiler.start("A")时，启动了一个被命名为 A 的秒表。随后，调用 profiler.start("B") 将启动秒表 B，并且同时将停止秒表 A。在一个性能分析器实例上调用 stop()，将停止最后一个秒表和伴随分析器实例化而启动起来的全局秒表。

分析器嵌套

分析器也可以嵌套。通过嵌套的分析器，不仅可以测量一个任务的耗时，还可以测量需要策略的子任务的耗时。

启动嵌套的分析器将停止以前所有已经启动的秒表或者关联到上级分析器。

通常情况下，子任务会被不同的类来实现，并且托管着上级分析器。使用 ProfilerRegistry 是
一种方便地将嵌套分析器从当前对象传递到其他对象的方式。每一个线程都有自己的分析器注册表
（profiler registry），可以通过调用 getThreadContextInstance() 方法来获取。

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  }

这是引用的相关类：SortAndPruneComposites。

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    }

在双核并且主频为 3.2G 赫兹的 Intel CPU 上，运行这个 ProfilerDemo 产生如下输出：

+ 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.

从上面的例子中，我们可以得出产生 1 000 000 个随机整数需要消耗 70 毫秒，排序需要 665 毫秒，裁剪 5695 毫秒，总计耗时 6433 毫秒。从这里输出可以看出，裁剪计算占用了最多的 CPU 时间，将来任何优化都将直接在裁剪部分进行。

通过放置一些恰当的分析器调用，我们就可以识别出我们程序中的热点。同时，我们也应该注意到，为了将一个分析器传递到目标类，我们可以通过将分析器注册到注册表，然后就可以在目标类中获取出来。

使用日志输出

调用 profiler.print() 将在控制台中打印出结果。如果你想在生成环境中也保留分析器，那么
你也许需要控制输出目的地。你可以通过将一个分析器关联到你选择的一个日志上来完成。

当你将一个分析器和一个日志进行关联后，你只需要通过调用 log() 来代替上面调用 print()，
下面是演示示例：

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  }

上面例子的输出依赖日志环境，但是和上面的 NestedProfilerDemo 例子的输出很类似。

log() 方法在 DEBUG 基本输出，并且使用 PROFILER 作为标记。

如果你的日志系统支持标记（marker），例如 logback，你可以明确地启用或者禁用 SLF4J 分析器
输出。下面是 logback 配置文件，禁用任何匹配 PROFILER 标记的日志，即使 DEBUG 级别
的日志可以输出。

<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 是一个定义在 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）

XLogger 类提供了一些额外的日志方法，执行路径后的程序非常有用。这些方法产生日志事件，可
以从其他的调试日志中过滤出来。鼓励使用这些方法，输出可以

• 在开发环境下，有助于在没有调试会话时诊断问题。
• 在生成环境下，即使没有调试，诊断问题也成为可能。
• 帮助培训新的开发人员学习应用。

最常用的是 entry() 和 exit() 方法。entry() 应该放在方法的开始部分，除了简单的 Getter
和 Setter 方法。entry() 可以通过 0 到 4 个参数来调用。代表性的一种情况是，它们是传递
给这个方法的参数。entry() 方法使用 TRACE 级别的日志，并且使用一个名字为 ENTER 的标记，
这也是一个 FLOW 标记。

exit() 方法应该放置在任何返回语句之前，或者没有返回的方法的最后一句。exit() 可以通过
一个或者零个参数来调用。具有代表性的是，如果方法返回为 void，则使用 exit()；如果返
回一个对象，则使用 exit(Object obj)。entry() 方法使用 TRACE 基本的日志，并且使用
一个名字为 EXIT 的标记，这也是一个 FLOW 标记。

throwing() 方法可以用于处理程序抛出而又不可能处理异常，例如 RuntimeException。这
可以明显确保适当诊断信息是可用的，如果需要的话。这个日志事件发生将使用 ERROR 基本的日志，
并且和命名为 THROWING 的标记关联，这也是一个 EXCEPTION 标记

catching() 方法可以被程序用于它捕获一个异常，而且又不想再次抛出，可以是明确的 Exception
或者其他异常。这个日志事件发生将使用 ERROR 基本的日志，并且和命名为 CATCHING 的标
记关联，这也是一个 EXCEPTION 标记

通过使用这些扩展方法，规范了 SLF4J 的使用，程序可以确信，它们可以以一种标准的方式来展示诊断日志。

注意，XLogger 实例可以通过 XLoggerFactory 工具类来获得。

接下来的例子演示了一个简单程序以相当典型的方式使用这些方法。 throwing() 方法没有展示，
这是因为没有异常要并且抛出并且不处理。

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;
  }
}

这些测试应用使用了前面的服务来产生日志事件。

package com.test;

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

下面的配置将所有的输出路由到 target/test.log。提供给 FileAppender 的模式，包含了类名，
行号以及方法名。在模式中包含这些内容对于日志的值来说是非常关键的。

<?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>

下面是上面 Java 类以及配置文件的输出结果。

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

在上面的例子中，只需要简单地将 root 日志的级别修改为 DEBUG，将大幅减少输出内容。

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)

转载自  并发编程网 - ifeve.com