Java日志記錄的事兒

一、java日志組件                                                                                 

   1、common-logging

      common-logging是apache提供的一個通用的日志接口。用戶可以自由選擇第三方的日志組件作為具體實現，像log4j，或者jdk自帶的logging， common-logging會通過動態查找的機制，在程序運行時自動找出真正使用的日志庫。但由於它使用了ClassLoader尋找和載入底層的日 志庫， 導致了象OSGI這樣的框架無法正常工作，由於其不同的插件使用自己的ClassLoader。 OSGI的這種機制保證了插件互相獨立，然而確使Apache Common-Logging無法工作。當然，common-logging內部有一個Simple logger的簡單實現，但是功能很弱。所以使用common-logging，通常都是配合着log4j來使用。使用它的好處就是，代碼依賴是common-logging而非log4j， 避免了和具體的日志方案直接耦合，在有必要時，可以更改日志實現的第三方庫。

import org.apache.commons.logging.Log;  
import org.apache.commons.logging.LogFactory;  
   
public class A {  
    private static Log logger = LogFactory.getLog(this.getClass());  
}

動態查找原理：Log 是一個接口聲明。LogFactory 的內部會去裝載具體的日志系統，並獲得實現該Log 接口的實現類。LogFactory 內部裝載日志系統的流程如下：

首先，尋找org.apache.commons.logging.LogFactory 屬性配置。

否則，利用JDK1.3 開始提供的service 發現機制，會掃描classpah 下的META-INF/services/org.apache.commons.logging.LogFactory文件，若找到則裝載里面的配置，使用里面的配置。

否則，從Classpath 里尋找commons-logging.properties ，找到則根據里面的配置加載。

否則，使用默認的配置：如果能找到Log4j 則默認使用log4j 實現，如果沒有則使用JDK14Logger 實現，再沒有則使用commons-logging 內部提供的SimpleLog 實現。

從上述加載流程來看，只要引入了log4j 並在classpath 配置了log4j.xml ，則commons-logging 就會使log4j 使用正常，而代碼里不需要依賴任何log4j 的代碼。

   2、slf4j

      slf4j全稱為Simple Logging Facade for JAVA，java簡單日志門面。類似於Apache Common-Logging，是對不同日志框架提供的一個門面封裝，可以在部署的時候不修改任何配置即可接入一種日志實現方案。但是，他在編譯時靜態綁定真正的Log庫。使用SLF4J時，如果你需要使用某一種日志實現，那么你必須選擇正確的SLF4J的jar包的集合（各種橋接包）。

import org.slf4j.Logger;  
import org.slf4j.LoggerFactory;  
   
public class A {  
    private static Log logger = LogFactory.getLog(this.getClass());  
}

slf4j靜態綁定原理：SLF4J 會在編譯時會綁定import org.slf4j.impl.StaticLoggerBinder; 該類里面實現對具體日志方案的綁定接入。任何一種基於slf4j 的實現都要有一個這個類。如：org.slf4j.slf4j-log4j12-1.5.6: 提供對 log4j 的一種適配實現。注意：如果有任意兩個實現slf4j 的包同時出現，那么就可能出現問題。

    slf4j 與 common-logging 比較

    common-logging通過動態查找的機制，在程序運行時自動找出真正使用的日志庫。由於它使用了ClassLoader尋找和載入底層的日志庫， 導致了象OSGI這樣的框架無法正常工作，因為OSGI的不同的插件使用自己的ClassLoader。 OSGI的這種機制保證了插件互相獨立，然而卻使Apache Common-Logging無法工作。

slf4j在編譯時靜態綁定真正的Log庫,因此可以再OSGI中使用。另外，SLF4J 支持參數化的log字符串，避免了之前為了減少字符串拼接的性能損耗而不得不寫的if(logger.isDebugEnable())，現在你可以直接寫：logger.debug(“current user is: {}”, user)。拼裝消息被推遲到了它能夠確定是不是要顯示這條消息的時候，但是獲取參數的代價並沒有幸免。  

Object[] params = {value1, value2, value3};
 
logger.debug("first value: {}, second value: {} and third value: {}.", params);

   3、log4j

     Apache的一個開放源代碼項目，通過使用Log4j，我們可以控制日志信息輸送的目的地是控制台、文件、GUI組件、甚至是套接口服務 器、NT的事件記錄器、UNIX Syslog守護進程等；用戶也可以控制每一條日志的輸出格式；通過定義每一條日志信息的級別，用戶能夠更加細致地控制日志的生成過程。這些可以通過一個 配置文件來靈活地進行配置，而不需要修改程序代碼。

   4、logback

     Logback是由log4j創始人設計的又一個開源日記組件。logback當前分成三個模塊：logback-core,logback- classic和logback-access。logback-core是其它兩個模塊的基礎模塊。logback-classic是log4j的一個 改良版本。此外logback-classic完整實現SLF4J API使你可以很方便地更換成其它日記系統如log4j或JDK14 Logging。logback-access訪問模塊與Servlet容器集成提供通過Http來訪問日記的功能。

    Log4j 與 LogBack 比較

    LogBack作為一個通用可靠、快速靈活的日志框架，將作為Log4j的替代和SLF4J組成新的日志系統的完整實現。LOGBack聲稱具有極佳的性能，“ 某些關鍵操作，比如判定是否記錄一條日志語句的操作，其性能得到了顯著的提高。這個操作在LogBack中需要3納秒，而在Log4J中則需要30納秒。 LogBack創建記錄器（logger）的速度也更快：13微秒，而在Log4J中需要23微秒。更重要的是，它獲取已存在的記錄器只需94納秒，而 Log4J需要2234納秒，時間減少到了1/23。跟JUL相比的性能提高也是顯著的”。 另外，LOGBack的所有文檔是全面免費提供的，不象Log4J那樣只提供部分免費文檔而需要用戶去購買付費文檔。 

使用slf4j+logback的優勢：

• 支持按文件大小或基於時間的切分方式，可自定義命名模式
• 支持文件打包(觸發器方式）
• 支持OSGI環境

如果在單純的logging環境中，使用SLF4J意義不大。如果想在各種logger API中切換，SELF4J是理想選擇，另外在新的項目中，使用SLF4J+Logback是比較好的日志框架選型。

logback.xml的配置

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- log output to file -->
    <appender name="ROLLING"
        class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 按天回滾 daily -->
            <!-- log.dir 在maven profile里配置 -->
            <fileNamePattern>${ms.log.home}/ms-api-%d{yyyy-MM-dd}.log
            </fileNamePattern>
            <!-- 日志最大的歷史 7天 -->
            <maxHistory>7</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} [%file:%line] - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="API_QUERY_MONITOR"
        class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 按天回滾 daily -->
            <!-- log.dir 在maven profile里配置 -->
            <fileNamePattern>${ms.log.home}/ms-api-query-%d{yyyy-MM-dd}.log
            </fileNamePattern>
            <!-- 日志最大的歷史 7天 -->
            <maxHistory>2</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} [%file:%line] - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- log output to console -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36}[%file:%line] - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- Perf4J appenders -->
    <!-- This AsyncCoalescingStatisticsAppender groups StopWatch log messages 
        into GroupedTimingStatistics messages which it sends on the file appender 
        defined below -->

    <!-- This file appender is used to output aggregated performance statistics -->
    <appender name="perf4jFileAppender"
        class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>${ms.log.home}/ms-performance.log</File>
        <encoder>
            <!-- <Pattern>%date %-5level [%thread] %logger{36} [%file:%line] %msg%n 
                </Pattern> -->
            <Pattern>%date %-5level [%file:%line] %msg%n</Pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>${ms.log.home}/ms-performance.%d{yyyy-MM-dd}.log
            </FileNamePattern>
            <maxHistory>2</maxHistory>
        </rollingPolicy>
    </appender>

    <appender name="CoalescingStatistics"
        class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
        <param name="TimeSlice" value="60000" />
        <appender-ref ref="perf4jFileAppender" />
    </appender>


    <!-- Loggers -->
    <!-- The Perf4J logger. Note that org.perf4j.TimingLogger is the value of 
        the org.perf4j.StopWatch.DEFAULT_LOGGER_NAME constant. Also, note that additivity 
        is set to false, which is usually what is desired - this means that timing 
        statements will only be sent to this logger and NOT to upstream loggers. -->
    <logger name="org.perf4j.TimingLogger" additivity="false">
        <level value="INFO" />
        <appender-ref ref="CoalescingStatistics" />
    </logger>

    <logger name="com.wy.api.out.OutApi" level="debug">
        <appender-ref ref="ROLLING" />
    </logger>
    <logger name="com.wy.util.PlayerDataUtil" level="info">
        <appender-ref ref="ROLLING" />
    </logger>
    <logger name="com.wy.QueryServiceImpl" level="info">
        <appender-ref ref="REMOTE_QUERY_MONITOR" />
    </logger>
    <root level="info">
        <appender-ref ref="ROLLING" />
    </root>
</configuration>

 

二、如何記錄日志                                                                                  

1、日志級別

在記錄日志時，大家都會要選擇合理的日志級別、合理的控制日志內容。我們都知道debug級別日志在生產環境中是不會輸出到文件中的，但是也可能帶來不小的開銷。我們看下Log4j2.x性能文檔中一組對比：

logger.debug("Entry number: " + i + " is " +  String.valueOf(entry[i])); 
logger.debug("Entry number: {} is {}", i, entry[i]);

上面兩條語句在日志輸出上的效果是一樣的，但是在關閉DEBUG日志時，它們的開銷就不一樣了，主要的影響在於字符串轉換和字符串拼接上，無論是否生效，前者都會將變量轉換為字符串並進行拼接，而后者則只會在需要時執行這些操作。Log4J官方的測試結論是兩者在性能上能相差兩個數量級。試想一下，如果某個對象的toString()方法里用了ToStringBuilder來反射輸出幾十個屬性時，這時能省下多少資源。

因此，某些仍在使用Apache Commons Logging（它們不支持{}模板的寫法）、Log4J 1.x或LogBack時，采用模版的方式。

2、日志內容

日志中一般都會記錄日期、線程名、類信息、MDC變量、日志消息等等，根據Takipi的測試，如果在日志中加入class，性能會急劇下降，比起LogBack的默認配置，吞吐量的降幅在6成左右。如果一定要打印類信息，可以考慮用類名來命名Logger。

在分布式系統中，一個請求可能會經過多個不同的子系統，這時最好生成一個UUID附在請求中，每個子系統在打印日志時都將該UUID放在MDC里，便於后續查詢相關的日志。

3、Appender

同步寫的Appender在高並發大流量的系統里多少有些力不從心，這時就該使用AsyncAppender了，同樣是使用LogBack：

在10線程並發下，輸出200字符的INFO日志，AsyncAppender的吞吐量最高能是FileAppender的3.7倍。在不丟失日志的情況下，同樣使用AsyncAppender，隊列長度對性能也會有一定影響。

如果使用Log4J 2.x，那么除了有AsyncAppender，還可以考慮性能更高的異步Logger，由於底層用了Disruptor，沒有鎖的開銷，性能更為驚人。根據Log4J 2.x的官方測試，同樣使用Log4J 2.x：

64線程下，異步Logger比異步Appender快12倍，比同步Logger快68倍。

同樣是異步，不同的庫之間也會有差異：

同等硬件環境下，Log4J 2.x全部使用異步Logger會比LogBack的AsyncAppender快12倍，比Log4J 1.x的異步Appender快19倍。

 

如果一定要用同步的Appender，那么可以考慮使用ConsoleAppender，然后將STDOUT重定向到文件里，這樣大約也能有10%左右的性能提升。

Log4J 2.x的異步Logger性能強悍，但也有不同的聲音，覺得這只是個看上去很優雅，只能當成一個玩具。關於這個問題，還是留給讀者自己來思考吧。

 

如何記錄線程名稱

往往日志中線程名稱大部分類似 “http-nio-8080-exec-3″，這個是線程池或者容器給它們取的。線程名稱是你日志中主要標記，你必須確保正確地使用它。這就意味着給線程取的名稱必須結合上下文，例如servlet的名稱或者任務此刻的意義，還有一些動態的上下文環境，例如一個用戶或消息ID。與logid有異曲同工之妙，下文中會有說明。

因此，代碼的入口處應該像下面這樣：

Thread.currentThread().setName(ProcessTask.class.getName() + “: “+ message.getID);

一個更高級的寫法是加載一個線程本地變量到當前線程中，並且配置一個自定義日志（appender），自動把這個變量加入到每一條日志記錄中

分布式標識

在分布式的服務中，當我們的一個服務執行，可能會跨越多個服務。一旦服務執行失敗了我們要知道是哪個環節出了問題。很多日志分析工具可以幫你進行日志歸類，前提是你日志中帶有它們可以用來做分類的唯一ID。（校對注：當A應用調用B應用接口時，而B應用的接口實現又需要調用應用C的接口時，一旦報錯很難定位這個請求到底是在調用哪個應用時報錯的？所以就使用一個唯一ID把這個請求鏈路串起來。）

這意味着每一個操作進入到你的系統中都應該有一個唯一的ID，用這個ID直到它執行完成。注意，那些持久化標示符，例如用戶的ID在這里可能不是很好的選擇，因為一個用戶可能有多個操作發生在同一個日志中，這會使得隔離出一個特定的操作流變得更難。UUID在這邊是一個很好的選擇，這個值可以被作為線程的名稱或者作為一個TLS-線程本地存儲。

捕獲外部調用

很多情況下，外部API調用失敗的原因是提供的入參是未預知的。把那些輸入參數現成的記錄在日志中是你修復代碼的關鍵。

這個點上你可能會選擇不記錄錯誤日志，但是必須記錄拋出的異常，這是對的。在這種情況下，只需要盡可能多的收集傳遞給調用的相關參數，並且把他們格式化到異常錯誤信息中。

只需要卻表異常被捕獲，並且和調用棧一起被高日志級別記錄。

try {
    return s3client.generatePresignedUrl(request);
} catch (Exception e) {
    String err = String.format(“Error generating request: %s bucket: %s key: %s. method: %s", request, bucket, path, method);
    log.error(err, e); //you can also throw a nested exception here with err instead.
}