1. 程式人生 > >Java日誌框架解析及實戰分析

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 包加進去。

image

到這個時候一切看起來都很簡單,很美好。介面和實現做了良好的分離,在統一的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 來連線:

image

可以看到甚至 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實現,如果畫出橋接關係的圖來回事什麼樣子呢?

image

(圖中為了說明方便,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掉,防止日誌使用了其他實現。