Java日志框架解析及實戰分析

轉載自：
https://zhuanlan.zhihu.com/p/24272450
https://zhuanlan.zhihu.com/p/24275518

作為Java程序員，幸運的是，Java 擁有功能和性能都非常強大的日志庫；不幸的是，這樣的日志庫有不止一個——相信每個人都曾經迷失在JUL(Java Util Log), JCL(Commons Logging), Log4j, SLF4J, Logback，Log4j2 等等的迷宮中。在我見過的絕大多數項目中，都沒有能夠良好的配置和使用日志庫。
這篇文章先講述Java常見日志庫的歷史和關系，后續會講日志使用的最佳實踐。讓我們從頭(Java Util Log)開始說起吧。

Java Util Log

簡稱JUL，是JDK 中自帶的log功能。雖然是官方自帶的log lib，JUL的使用確不廣泛。主要原因:

1. JUL從JDK1.4 才開始加入(2002年)，當時各種第三方log lib已經被廣泛使用了
2. JUL早期存在性能問題，到JDK1.5上才有了不錯的進步，但現在和Logback/Log4j2相比還是有所不如
3. JUL的功能不如Logback/Log4j2等完善，比如Output Handler就沒有Logback/Log4j2的豐富，有時候需要自己來繼承定制，又比如默認沒有從ClassPath里加載配置文件的功能

Log4j 1.x

Log4j 是在 Logback 出現之前被廣泛使用的 Log Lib, 由 Gülcü 於2001年發布，后來成為Apache 基金會的頂級項目。Log4j 在設計上非常優秀，對后續的 Java Log 框架有長久而深遠的影響，也產生了Log4c, Log4s, Log4perl 等到其他語言的移植。Log4j 的短板在於性能，在Logback 和 Log4j2 出來之后，Log4j的使用也減少了。

Commons Logging

簡稱JCL，是Apache下面的項目。JCL 是一個Log Facade，只提供 Log API，不提供實現，然后有 Adapter 來使用 Log4j 或者 JUL 作為Log Implementation。

就像之前所說，JDK現在帶了自己的JUL，然后又有第三方的 Log4j 等日志庫存在，不同的項目可能各自使用了不同的日志庫。如果你的項目依賴的其他 lib 各自使用了不同的日志庫，你想控制日志行為，就需要針對每個日志庫都寫一個配置文件，是不是很酸爽?

然后這個時候 JCL 就出現了。在程序中日志創建和記錄都是用JCL中的接口，在真正運行時，會看當前ClassPath中有什么實現，如果有Log4j 就是用 Log4j, 如果啥都沒有就是用 JDK 的 JUL。

這樣，在你的項目中，還有第三方的項目中，大家記錄日志都使用 JCL 的接口，然后最終運行程序時，可以按照自己的需求(或者喜好)來選擇使用合適的Log Implementation。如果用Log4j, 就添加 Log4j 的jar包進去，然后寫一個 Log4j 的配置文件；如果喜歡用JUL，就只需要寫個 JUL 的配置文件。如果有其他的新的日志庫出現，也只需要它提供一個Adapter，運行的時候把這個日志庫的 jar 包加進去。

到這個時候一切看起來都很簡單，很美好。接口和實現做了良好的分離，在統一的JCL之下，不改變任何代碼，就可以通過配置就換用功能更強大，或者性能更好的日志庫實現。

這種簡單美好一直持續到SLF4J出現。

SLF4J/Logback

SLF4J(The Simple Logging Facade for Java) 和 Logback 也是Gülcü 創立的項目，其創立主要是為了提供更高性能的實現。其中，SLF4j 是類似於JCL 的Log Facade，Logback 是類似於Log4j 的 Log Implementation。

之前已經說過，Apache 有了個JCL，用來做各種Log lib統一的接口，如果 Gülcü 要搞一個更好的 Log 實現的話，直接寫一個實現就好了，為啥還要搞一個和SLF4J呢?

原因是Gülcü 認為 JCL 的 API 設計得不好，容易讓使用者寫出性能有問題的代碼。

比如在用 JCL 輸出一個 debug 級別的 log:

logger.debug("start process request, url:" + url);

這個有什么問題呢？一般生產環境 log 級別都會設到 info 或者以上，那這條 log 是不會被輸出的。然而不管會不會輸出，這其中都會做一個字符串連接操作，然后生產一個新的字符串。如果這條語句在循環或者被調用很多次的函數中，就會多做很多無用的字符串連接，影響性能。

所以 JCL 的最佳實踐推薦這么寫：

if (logger.isDebugEnabled()) {
    logger.debug("start process request, url:" + url);
}

然而開發者常常忽略這個問題或是覺得麻煩而不願意這么寫。所以SLF4J提供了新的API，方便開發者使用:

logger.debug("start process request, url:{}", url);

這樣的話，在不輸出 log 的時候避免了字符串拼接的開銷；在輸出的時候需要做一個字符串format，代價比手工拼接字符串大一些，但是可以接受。

而 Logback 則是作為 Log4j 的繼承者來開發的，提供了性能更好的實現，異步 logger，Filter等更多的特性。

現在事情變復雜了。我們有了兩個流行的 Log Facade，以及三個流行的 Log Implementation。Gülcü 是個追求完美的人，他決定讓這些Log之間都能夠方便的互相替換，所以做了各種 Adapter 和 Bridge 來連接:

可以看到甚至 Log4j 和 JUL 都可以橋接到SLF4J，再通過 SLF4J 適配到到 Logback!

在這里需要注意不能搞出循環的橋接，比如下面這些依賴就不能同時存在:

1. jcl-over-slf4j 和 slf4j-jcl
2. log4j-over-slf4j 和 slf4j-log4j12
3. jul-to-slf4j 和 slf4j-jdk14

總感覺事情在變得更麻煩呢！

Log4j2

現在有了更好的 SLF4J 和 Logback——你會想事情到這里總該了解了吧，讓他們慢慢取代JCL 和 Log4j 好了。

然而維護 Log4j 的人不這樣想，他們不想坐視用戶一點點被 SLF4J /Logback 蠶食，繼而搞出了 Log4j2。

Log4j2 和 Log4j1.x 並不兼容，設計上很大程度上模仿了 SLF4J/Logback，性能上也獲得了很大的提升。

Log4j2 也做了 Facade/Implementation 分離的設計，分成了 log4j-api 和 log4j-core。

現在好了，我們有了三個流行的Log 接口和四個流行的Log實現，如果畫出橋接關系的圖來回事什么樣子呢?

（圖中為了說明方便，log4j2-core實際包為log4j-core, log4j2-api實際包為log4j-api）

是不是感覺有點暈呢？同樣，在添加依賴的時候，要小心不要搞成循環依賴。

實際項目中的使用

1. 總是使用Log Facade，而不是具體Log Implementation

正如之前所說的，使用 Log Facade 可以方便的切換具體的日志實現。而且，如果依賴多個項目，使用了不同的Log Facade，還可以方便的通過 Adapter 轉接到同一個實現上。如果依賴項目使用了多個不同的日志實現，就麻煩的多了。

具體來說，現在推薦使用 Log4j-API 或者 SLF4j，不推薦繼續使用 JCL。

2. 只添加一個 Log Implementation依賴

毫無疑問，項目中應該只使用一個具體的 Log Implementation，建議使用 Logback 或者Log4j2。如果有依賴的項目中，使用的 Log Facade不支持直接使用當前的 Log Implementation，就添加合適的橋接器依賴。具體的橋接關系可以看上一篇文章的圖。

3. 具體的日志實現依賴應該設置為optional和使用runtime scope

在項目中，Log Implementation的依賴強烈建議設置為runtime scope，並且設置為optional。例如項目中使用了 SLF4J 作為 Log Facade，然后想使用 Log4j2 作為 Implementation，那么使用 maven 添加依賴的時候這樣設置:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>${log4j.version}</version>
    <scope>runtime</scope>
    <optional>true</optional>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>${log4j.version}</version>
    <scope>runtime</scope>
    <optional>true</optional>
</dependency>

設為optional，依賴不會傳遞，這樣如果你是個lib項目，然后別的項目使用了你這個lib，不會被引入不想要的Log Implementation 依賴；

Scope設置為runtime，是為了防止開發人員在項目中直接使用Log Implementation中的類，而不適用Log Facade中的類。

4. 如果有必要, 排除依賴的第三方庫中的Log Impementation依賴

這是很常見的一個問題，第三方庫的開發者未必會把具體的日志實現或者橋接器的依賴設置為optional，然后你的項目繼承了這些依賴——具體的日志實現未必是你想使用的，比如他依賴了Log4j，你想使用Logback，這時就很尷尬。另外，如果不同的第三方依賴使用了不同的橋接器和Log實現，也極容易形成環。

這種情況下，推薦的處理方法，是使用exclude來排除所有的這些Log實現和橋接器的依賴，只保留第三方庫里面對Log Facade的依賴。

比如阿里的JStorm就沒有很好的處理這個問題，依賴jstorm會引入對Logback和log4j-over-slf4j的依賴，如果你想在自己的項目中使用Log4j或其他Log實現的話，就需要加上excludes:

<dependency>
    <groupId>com.alibaba.jstorm</groupId>
    <artifactId>jstorm-core</artifactId>
    <version>2.1.1</version>
    <exclusions>
        <exclusion>
            <groupId>org.slf4j</groupId>
            <artifactId>log4j-over-slf4j</artifactId>
        </exclusion>
        <exclusion>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
        </exclusion>
    </exclusions>
</dependency>

5. 避免為不會輸出的log付出代價

Log庫都可以靈活的設置輸出界別，所以每一條程序中的log，都是有可能不會被輸出的。這時候要注意不要額外的付出代價。

先看兩個有問題的寫法：

logger.debug("start process request, url: " + url);
logger.debug("receive request: {}", toJson(request));

第一條是直接做了字符串拼接，所以即使日志級別高於debug也會做一個字符串連接操作；第二條雖然用了SLF4J/Log4j2 中的懶求值方式來避免不必要的字符串拼接開銷，但是toJson()這個函數卻是都會被調用並且開銷更大。

推薦的寫法如下:

logger.debug("start process request, url:{}", url); // SLF4J/LOG4J2
logger.debug("receive request: {}", () -> toJson(request)); // LOG4J2
logger.debug(() -> "receive request: " + toJson(request)); // LOG4J2
if (logger.isDebugEnabled()) { // SLF4J/LOG4J2
    logger.debug("receive request: " + toJson(request)); 
}

6. 日志格式中最好不要使用行號，函數名等字段

原因是，為了獲取語句所在的函數名，或者行號，log庫的實現都是獲取當前的stacktrace，然后分析取出這些信息，而獲取stacktrace的代價是很昂貴的。如果有很多的日志輸出，就會占用大量的CPU。在沒有特殊需要的情況下，建議不要在日志中輸出這些這些字段。

最后， log中不要輸出稀奇古怪的字符！

部分開發人員為了方便看到自己的log，會在log語句中加上醒目的前綴，比如:

logger.debug("========================start process request=============");

雖然對於自己來說是方便了，但是如果所有人都這樣來做的話，那log輸出就沒法看了！正確的做法是使用grep 來看只自己關心的日志。

實戰示例

日志中不注意exclude的話，經常會報這種錯：

SLF4J: Found binding in [jar:file:/home/work/bin/miui-ad-schedule-web/miui-ad-schedule-web-1.0-SNAPSHOT.jar!/BOOT-INF/lib/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/work/bin/miui-ad-schedule-web/miui-ad-schedule-web-1.0-SNAPSHOT.jar!/BOOT-INF/lib/log4j-slf4j-impl-2.7.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]

這幾行日志是說，有多個slf4j的實現，最后選擇了org.slf4j.impl.Log4jLoggerFactory。我們可以看到，實際上是slf4j-log4j12 和 log4j-slf4j-impl 這兩條路都走通了，看上面的圖，可以知道，分別對應的是log4j2 和log4j。

實際項目中選擇的是log4j2+ slf4j的組合，所以最好把log4j這條線exclude掉，防止日志使用了其他實現。