基於slf4j日志MDC輸出格式的問題

Posted on by

slf4j日志MDC輸出格式

配置使用

// 自動配置模板
...
<Property name="layout">%d %p %X{traceId} [%t] %c{10}:%M:%L %m%n</Property>
...
<PatternLayout pattern="${layout}"/>
...
// 具體項目覆蓋配置的格式
<Property name="layout">%d %p [%t] %c{1.}:%M:%L %X{myTraceId} %m%n</Property>
MDC.put("myTraceId", myTraceId);
try {
    ...
} catch (Exception e) {
    ...
} finally {
    MDC.clear();
}

日志輸出效果發現是直接打印瞭myTraceId所對應的的值，而我們期望是這樣的格式{myTraceId=123}。

原因分析

查看格式化的實現類PatternLayout，內部通過PatternSelector匹配選擇器根據Pattern匹配選擇對應的轉換器進行格式化

默認使用MarkerPatternSelector實現，選擇器構造器中解析獲取各個匹配模式對應的格式化實現列表PatternFormatter

PatternFormatter實現的實例屬性LogEventPatternConverter抽象類對具體的日志內容進行格式化轉換，查看其實現類

直接查看MdcPatternConverter實現

構造器中按照逗號“，”切分MDC的key配置

// options, 對應配置中的key列表
private MdcPatternConverter(final String[] options) {
    super(options != null && options.length > 0 ? "MDC{" + options[0] + '}' : "MDC", "mdc");
    if (options != null && options.length > 0) {
        full = false;
        if (options[0].indexOf(',') > 0) {
            // 按照逗號切分key
            keys = options[0].split(",");
            for (int i = 0; i < keys.length; i++) {
                keys[i] = keys[i].trim();
            }
            key = null;
        } else {
            keys = null;
            key = options[0];
        }
    } else {
        full = true;
        key = null;
        keys = null;
    }
}
// 格式化
public void format(final LogEvent event, final StringBuilder toAppendTo) {
    final ReadOnlyStringMap contextData = event.getContextData();
    // if there is no additional options, we output every single
    // Key/Value pair for the MDC in a similar format to Hashtable.toString()
    // 如果沒有附加的屬性，我們輸出每一個單獨的MDC配置的key/value對，類似與Hashtable.toString()的格式
    if (full) {
        if (contextData == null || contextData.size() == 0) {
            toAppendTo.append("{}");
            return;
        }
        appendFully(contextData, toAppendTo);
    } else {
        if (keys != null) {
            if (contextData == null || contextData.size() == 0) {
                toAppendTo.append("{}");
                return;
            }
            // 存在附加屬性配置
            appendSelectedKeys(keys, contextData, toAppendTo);
        } else if (contextData != null){
            // otherwise they just want a single key output
            final Object value = contextData.getValue(key);
            if (value != null) {
                StringBuilders.appendValue(toAppendTo, value);
            }
        }
    }
}

我們配置瞭%X擴展即存在附加屬性配置

// 按照配置的MDC keys輸出，輸出格式為{key=value,key2=value2}
private static void appendSelectedKeys(final String[] keys, final ReadOnlyStringMap contextData, final StringBuilder sb) {
    // Print all the keys in the array that have a value.
    final int start = sb.length();
    sb.append('{');
    for (int i = 0; i < keys.length; i++) {
        final String theKey = keys[i];
        final Object value = contextData.getValue(theKey);
        if (value != null) { // !contextData.containskey(theKey)
            if (sb.length() - start > 1) {
                sb.append(", ");
            }
            sb.append(theKey).append('=');
            StringBuilders.appendValue(sb, value);
        }
    }
    sb.append('}');
}

問題定位後修改配置即可，修改配置後驗證格式符合我們的期望

<Property name="layout">%d %p [%t] %c{1.}:%M:%L %X{myTraceId,} %m%n</Property>

小結一下：MDC配置的key，日志會按照逗號切分出keys列表，如果keys列表小於等於1則直接輸出一個單獨的value值。如果大於1則按照map的格式輸出，即：{key1=value1,key2=value2}

slf4j輸出日志的語法

slf4j輸出log的語法

1. 直接拼接字符串

用字符串拼接的構造方式輸出log，字符串消息還是會被求值，存在類型轉換和字符串連接的性能消耗。例：

int index = 1;
logger.info("這是第"+index+"條數據");
logger.info("這是第"+String.valueOf(index)+"條數據");

輸出結果：

1

2. 使用SLF4J的格式化功能

這種用法不存在上面提到的缺點。SLF4J使用自己的格式化語法{}，同時提供瞭適合不同參數個數的方法重載：

logger.debug(String format, Object param); //支持一個參數
logger.debug(String format, Object param1, Object param2); //支持兩個參數
logger.debug(String format, Object… param); //任意數量參數，構造參數數組具有一定的性能損耗

例：

int index1=1;int index2=2;i
logger.info("這是第{}條數據",index1);
logger.info("這是第{}、{}條數據",index1,index2);

輸出：

2

3. 格式化占位符的轉義

連續的{}才被認為是格式化占位符

例：

logger.info("{1,2} 這是第{}條數據",index2);
logger.info("{1,2} 這是第{{}}條數據",index2);

輸出：

3

用”\”轉義{}占位符

例：

/**用”\”轉義{}占位符*/
logger.info("\\{} 這是第{}條數據 ",index2);
/**用“\”本身轉義“{}”中的”\”*/
logger.info("\\\\{} 這是第{}條數據 ",index3);

輸出：

4

4. log前做條件判斷

isDebugEnabled()的方法在debug disabled的情況下不存在構造字符串參數的性能消耗，但是如果debug enabled，debug是否被enabled將會被求值兩次：

  • 一次是isDebugEnabled(),
  • 一次是debug()本身(該影響較小，因為求值logger狀態花費的時間比真正log一條語句花費的時間的1%都還要小)。

例：

if(logger.isDebugEnabled()){
			logger.info("這是第{}條數據 ",index2);
}

輸出：

5

5、打印異常堆棧

logger.error("Failed to format {}", s, e);

slf4j總結

slf4j是Java的一種Log Api，類似Apache Commons Logging 。

官網介紹：http://www.slf4j.org/.

在SLF4J中，不需要進行字符串拼接，不會導致使用臨時字符串帶來的消耗。

相反，我們使用帶占位符的模板消息來記錄日志信息，並提供實際值作為參數。可以使用帶參數版的日志方法，也可以通過Object數組傳入。在為日志信息產生最終的字符串之前，該方法會檢查是否開啟瞭特定的日志級別，這不僅降低瞭內存占用，而且預先減少瞭執行字符串拼接所消耗的CPU時間。

log.debug("Found {} records matching filter: '{}'", records, filter);//slf4j
log.debug("Found " + records + " records matching filter: '" + filter + "'");//log4j

可以看出SLF4J的優點有：

更簡略易讀；

在日志級別不夠時，少瞭字符串拼接的開銷，不會調用對象（records/filter）的toString方法。通過使用日志記錄方法，直到你使用到的時候，才會去構造日志信息（字符串），這就同時提高瞭內存和CPU的使用率。

Slf4j在1.6.0之後，更是支持瞭異常堆棧的打印，作為最後一個參數傳入即可，基本滿足瞭日志的常見打印場景。

在你的開源庫或者私有庫中使用SLF4J，可以使它獨立於任何的日志實現，這就意味著不需要管理多個庫和多個日志文件。

SLF4J提供瞭占位日志記錄，通過移除對isDebugEnabled(), isInfoEnabled()等等的檢查提高瞭代碼的可讀性。

以上為個人經驗，希望能給大傢一個參考，也希望大傢多多支持WalkonNet。

推薦閱讀：