438
京東網上商城
SLF4J 擴展（一）
SLF4J 擴展被打包在 slf4j-ext.jar裏，它隨著 SLF4J 一起發布。
主要內容包含如下幾部分：
性能分析器（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 >
<Marker>PROFILER</Marker>
<OnMatch>DENY</OnMatch>
</turboFilter>
<appender name="STDOUT"
>
<layout >
<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" >
<filter >
<level>ERROR</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
<layout >
<Pattern>%d{HH:mm:ss.SSS} %-5level %class{36}:%L %M - %msg%n</Pattern>
</layout>
</appender>
<appender name="log" >
<File>target/test.log</File>
<Append>false</Append>
<layout >
<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)最後更新：2017-05-19 17:02:05