動態日誌級別：小功能，大用處

⚠️本文爲掘金社區首發簽約文章，未獲受權禁止轉載java

Log4j，Log4j2，Logback是當下主流的日誌框架，Slf4j則是新一代的日誌框架接口，其中Logback直接實現了Slf4j的接口，同時它也是SpringBoot的默認日誌框架。程序員

但從性能以及工程的角度上來看，Log4j2是事實標準，本文也是基於Log4j2來撰寫的。apache

爲何須要動態日誌級別

關於Log4j2的名詞小知識：markdown

配置方式：工業級項目通常都採用XML的配置方式

同步/異步：Log4j2支持同步/異步日誌兩種方式，如無特殊的場景須要，建議採用高性能的異步方式

Logger：Logger節點是用來單獨指定日誌的表現形式配置項，包括但不限於：日誌級別、關聯Appender、Name屬性等

Appender：Appender一般只負責將事件數據寫入目標目標目標，由Logger觸發指定的Appender執行。

做爲一個合格的程序員，你們對於日誌的重要性以及日誌框架的基本使用方法都瞭然於心。網絡

在絕大多數時候，日誌都是幫助咱們定位問題的利器，但全部事物都有兩面性，有時它也會成爲問題的導火索。app

接口莫名其妙變慢？

通常來講，接口的響應時間基本都花在網絡、DB層、IO層或者部分計算上，但我某一次排查B端線上問題時，居然發現是因爲打印日誌拖垮了整個接口。框架

因爲老系統的某個業務異常處理不合理，致使有大量的錯誤日誌輸出，進而形成當前線程阻塞，機器負載升高，整個接口的吞吐量下降。異步

定義這種莫名其妙的問題倒也簡單：ide

查看機器磁盤是否異常（磁盤佔用、文件大小）
經過Jstack命令檢查佔用較高的線程
觀察日誌輸出狀況（異常狀況下很是明顯）

PS：當時的處理方案是優化了日誌輸出，同時將同步日誌調整爲異步日誌工具

線上CPU飆贈

咱們在看日誌時都但願準確，乾淨，可複製至其餘工具進行分析，因此日誌通常都會這麼寫：

log.info("Method :: Kerwin.Demo, Params: {}, Result:{}", JSONUtil.toJsonStr(demo), JSONUtil.toJsonStr(demo));
複製代碼

這就涉及到了序列化操做，當此類日誌數量較多，接口調用次數較高時（每分鐘幾十萬的C端調用），CPU佔用就會很是明顯的升高，即便整個程序沒有任何問題。

因此咱們須要使用日誌框架的動態化調整日誌級別的能力，這樣一來咱們在編碼階段所留下的日誌也不須要在上線前刪除了，同時能夠更靈活的應對線上問題的排查和平常使用。

如何動態配置日誌級別

以Log4j2爲例，咱們可能會這樣配置根節點（ROOT Logger）

<Loggers>
    <AsyncRoot level="ERROR" includeLocation="true">
        <AppenderRef ref="INFO_LOG"/>
        <AppenderRef ref="ERROR_LOG"/>
    </AsyncRoot>
</Loggers>
複製代碼

使用如下代碼，並查看日誌文件

@Slf4j
public class LogTest {
    public static void main(String[] args) {
        log.info("This is a Demo...");
    }
}
複製代碼

由於我調整ROOT的日誌級別爲ERROR，所以無任何日誌輸出

利用Log4j2提供的能力，修改日誌級別，以下所示：

@Slf4j
public class LogTest {
    public static void main(String[] args) {
        log.info("This is a Demo... 111");
        Level level = Level.toLevel("info");
        LoggerContext context = (LoggerContext) LogManager.getContext(false);
        Configuration configuration = context.getConfiguration();
        configuration.getLoggerConfig("ROOT").setLevel(level);
        context.updateLoggers(configuration);
        log.info("This is a Demo... 222");
    }
}
複製代碼

結果以下所示：

很是容易的實現了修改日誌級別的能力，所以咱們在構建本身的應用或者系統時，可使用ZK進行動態化配置，也可使用HTTP或RPC接口留一個後門，以此來實現動態調整的能力。

如何配置指定類的日誌級別

上面的代碼演示瞭如何動態配置ROOT Logger節點，若是您在閱讀本文時能使用IDE，天然能看到

org.apache.logging.log4j.core.config.Configuration#getLoggers，該方法包括了每個自定義logger的配置參數，一樣可使用上述方式進行配置和修改。

代碼範例：

String packetLoggerName = "log.demo";
Level level = Level.toLevel("DEBUG");
LoggerContext context = (LoggerContext) LogManager.getContext(false);
Configuration configuration = context.getConfiguration();
for (Map.Entry<String, LoggerConfig> entry : configuration.getLoggers().entrySet()) {
    if (packetLoggerName.equals(entry.getKey())) {
        entry.getValue().setLevel(level);
    }
}

context.updateLoggers(configuration);
複製代碼

下圖則是咱們的日誌級別配置：

疑問：框架如何處理沒有Logger的類

先說結論：

每個Logger不必定都有其對應的配置
實際工做的Logger並不必定是其自己，如上文中的：log.demo.test.LogTestApp
Logger之間具備繼承性，即log.demo.test.LogTestApp在不做其餘額外配置的狀況下，會使用父級配置：log.demo，以此類推直到ROOT

使用如下配置及代碼，便可進行驗證：

<Loggers>
     <AsyncRoot level="INFO" includeLocation="true">
         <AppenderRef ref="Console"/>
     </AsyncRoot>

     <logger name="log.demo" level="ERROR">
         <AppenderRef ref="ERROR_LOG"/>
     </logger>
</Loggers>
複製代碼

@Slf4j
public class LogTestApp {
    public static void main(String[] args) {
        System.out.println(log.getName());
    }
}

// 輸出結果
// log.demo.test.LogTestApp
複製代碼

經過觀察配置文件，咱們能夠很明顯的發現，整個日誌框架其實是不存在：log.demo.test.LogTestApp 這個Logger的，那它究竟是如何工做的呢？

核心代碼分析以下：

private static final Logger log = LoggerFactory.getLogger(LogTestApp.class);
複製代碼

經過工廠的方式建立一路跟源碼，能夠發現類：AbstractConfiguration

@Override
public LoggerConfig getLoggerConfig(final String loggerName) {
    LoggerConfig loggerConfig = loggerConfigs.get(loggerName);
    if (loggerConfig != null) {
        return loggerConfig;
    }
    String substr = loggerName;
    while ((substr = NameUtil.getSubName(substr)) != null) {
        loggerConfig = loggerConfigs.get(substr);
        if (loggerConfig != null) {
            return loggerConfig;
        }
    }
    return root;
}
複製代碼

該方法的做用就是給每個類的Logger綁定實際的執行者，其中NameUtil.getSubName()方法即獲取當前類的全路徑的上一層，經過循環遍歷找到最近（所謂最近即以包名爲界限，由子向父級遞推）的Logger。

瞭解完以上的特性，咱們也就有了問題的答案。

按需配置父級Logger

隨着工程化的推動，系統代碼的層次性很是明顯，以我司爲例，主要分爲：Dao、Service、Business、Api這四層，其中核心業務通常都放在Business層，因此在通常狀況下出問題也都發生Business層，咱們能夠配置如下Logger，動態調整全部的Business的日誌級別，以達到更加精準的控制：

<Loggers>
    <logger name="com.jd.o2o.business" level="INFO">
        <!-- INFO_LOG -->
    </logger>
</Loggers>
複製代碼

同理，若是須要關注DB層的話，也能夠配置父級Logger來監控DB層的日誌。

動態生成Logger

其實從上文中動態調整日誌級別就能夠發現一些端倪，既然日誌框架支持動態刷新配置，那麼它必定支持動態新增配置（即便當前版本不支持，也只是還沒有開發）。

經過閱讀源碼，能夠看出如下方法能夠知足咱們的要求：

org.apache.logging.log4j.core.config.Configuration#addLogger

PS：我的不建議使用該種方式，由於編碼相對繁瑣，且過於靈活反而致使問題很差排查

疑問：莫名其妙的輸出

有時候咱們也會遇到這種問題：某一個Logger我想讓它打ERROR日誌，只輸出到ERROR文件，結果它輸出到了INFO、ERROR，這是爲何？

這實際上是日誌框架的設計問題，核心代碼以下所示：

private void processLogEvent(final LogEvent event, final LoggerConfigPredicate predicate) {
    event.setIncludeLocation(isIncludeLocation());
    if (predicate.allow(this)) {
    	callAppenders(event);
    }
    logParent(event, predicate);
}
複製代碼

日誌事件在打印時，會傳遞給全部的Appenders，最後它還會向父級Logger傳遞日誌事件，這也就致使咱們明明只配置了ERROR，結果卻輸出到了INFO和ERROR。

觀察以下代碼便可找到解決辦法：

// 核心代碼
private void logParent(final LogEvent event, final LoggerConfigPredicate predicate) {
    if (additive && parent != null) {
        parent.log(event, predicate);
    }
}

// 解決辦法 additivity置爲false
<logger name="log.demo" level="INFO" additivity="false"></logger>
複製代碼

打印日誌的小技巧

在日誌使用中除了正確的打印以外也存在一些小Tips，好比：

方案一：

log.info("This is a Demo, Request:{}", JSONUtil.toJsonStr(new LogTest()));
複製代碼

方案二：

if (log.isInfoEnabled()) {
    log.info("This is a Demo, Request:{}", JSONUtil.toJsonStr(new LogTest()));
}
複製代碼

以上兩種方式你會選擇哪種呢？其實對比就能看出來，必定會選擇方案二，由於它能夠避免沒必要要的序列化。

總結

大部分時間日誌都是程序員的好朋友，但一些微妙的狀況它反而會成爲致命的風險，因此咱們須要熟悉它的配置，瞭解它的原理。

那麼如何用好日誌框架呢，下面是幾點建議：

使用Slf4j的進行橋接，避免直接使用某一個特定日誌框架
合理設置RootLogger及其子Logger，能夠將系統依賴的框架級日誌分別輸出至指定的文件中，便於問題的排查
合理利用動態日誌級別的能力，隨時調整線上日誌級別
減小日誌中的序列化行爲，在使用低級別日誌時須要判斷當前日誌級別是否開啓，避免沒必要要的序列化
如無特殊場景要求，儘可能使用高吞吐的異步日誌

若是以爲這篇內容對你有幫助的話：

固然要點贊支持一下啦~
另外，能夠搜索並關注公衆號「是Kerwin啊」，一塊兒在技術的路上走下去吧~ 😋