Slf4j+Logback源码分析

发表于 | 更新于: | 分类于 | |

Slf4j源码分析

Slf4j（Simple Logging Facade for Java)是对不同日志框架的简单门面，允许用户自由选择具体的日志实现。

这张图来自Slf4j的官网，它明确展示了用户代码是架设在Slf4j API之上的，也就是屏蔽了用户代码对底层日志实现的依赖。因此，用户对于底层的日志框架变动是无感知的。 Slf4j的使用很简单： 
1
2
3
4
5
6
7
8
9
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class HelloWorld {
    public static void main(String[] args) {
        Logger logger = LoggerFactory.getLogger(HelloWorld.class);
        logger.info("Hello World");
    }
}
接下来我们深入源码（这里使用的是1.7.30版本的slf4j-api）。

Slf4j静态绑定

getLogger方法是所有使用的开始

1
2
3
4
5
6
7
8
public static Logger getLogger(Class<?> clazz) {
    Logger logger = getLogger(clazz.getName());
    if (DETECT_LOGGER_NAME_MISMATCH) {
        // 只有开启slf4j.detectLoggerNameMismatch才会执行，主要是判断调用的类和clazz是否匹配
        ...
    }
    return logger;
}

这里我们先从getLogger方法看起。

1
2
3
4
public static Logger getLogger(String name) {
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    return iLoggerFactory.getLogger(name);
}

显然getILoggerFactory才是重点。 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
public static ILoggerFactory getILoggerFactory() {
    if (INITIALIZATION_STATE == UNINITIALIZED) {
        synchronized (LoggerFactory.class) {
            if (INITIALIZATION_STATE == UNINITIALIZED) {
                INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                performInitialization();
            }
        }
    }
    switch (INITIALIZATION_STATE) {
    case SUCCESSFUL_INITIALIZATION:
        return StaticLoggerBinder.getSingleton().getLoggerFactory();
    case NOP_FALLBACK_INITIALIZATION:
        return NOP_FALLBACK_FACTORY;
    case FAILED_INITIALIZATION:
        throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
    case ONGOING_INITIALIZATION:
        // support re-entrant behavior.
        // See also http://jira.qos.ch/browse/SLF4J-97
        return SUBST_FACTORY;
    }
    throw new IllegalStateException("Unreachable code");
}

这里通过synchronized + volatile（INITIALIZATION_STATE的类型是static volatile int）保证了在多线程情况下，只有一个线程能够执行初始化操作。
这里再对LoggerFactory的状态展开讲讲：

  1. UNINITIALIZED：未初始化，也就是一开始的状态
  2. ONGOING_INITIALIZATION：正在初始化
  3. SUCCESSFUL_INITIALIZATION：初始化成功
  4. NOP_FALLBACK_INITIALIZATION：该状态返回的日志工厂为NOP_FALLBACK_FACTORY（类型是NOPLoggerFactory），其创建的日志是NOP_LOGGER，不执行日志操作。
  5. ONGOING_INITIALIZATION：表示还在初始化中，返回SUBST_FACTORY。该日志工厂创建的日志都是SubstituteLogger类型的，其日志操作实际上交由内部代理执行（在初始化完成前都以记录日志事件的形式保存至eventQueue中；初始化完成后，则执行空操作）。

至于什么时候会被置为这些状态，下文进行了详述。我们接着看performInitialization方法。

1
2
3
4
5
6
7
8
private final static void performInitialization() {
    // 静态绑定日志实现
    bind();
    if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
        // 成功初始化后，就开始进行版本检查：底层日志实现和Slf4j的版本是否兼容
        versionSanityCheck();
    }
}

bind方法最主要的目的就是将Slf4j和底层日志实现进行静态绑定。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
private final static void bind() {
    try {
        Set<URL> staticLoggerBinderPathSet = null;
        // 由于Android使用的Dex在设计上不能创建重复类，也就没有了“模糊绑定”的问题
        if (!isAndroid()) {
            // 获得资源org/slf4j/impl/StaticLoggerBinder.class，即找到所有可用的日志实现
            staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
            // 当可用日志实现多于1个时，进行System.err打印汇报信息
            reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
        }
        // 进行绑定
        StaticLoggerBinder.getSingleton();
        // 修改状态
        INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
        // 在多日志实现下，汇报最终绑定的日志实现
        reportActualBinding(staticLoggerBinderPathSet);
    } catch (NoClassDefFoundError ncde) {
        String msg = ncde.getMessage();
        if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
            INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
            Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
            Util.report("Defaulting to no-operation (NOP) logger implementation");
            Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details.");
        } else {
            failedBinding(ncde);
            throw ncde;
        }
    } catch (java.lang.NoSuchMethodError nsme) {
        String msg = nsme.getMessage();
        if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
            INITIALIZATION_STATE = FAILED_INITIALIZATION;
            Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");
            Util.report("Your binding is version 1.5.5 or earlier.");
            Util.report("Upgrade your binding to version 1.6.x.");
        }
        throw nsme;
    } catch (Exception e) {
        failedBinding(e);
        throw new IllegalStateException("Unexpected initialization failure", e);
    } finally {
        postBindCleanUp();
    }
}

到这里，整个过程已经比较清楚了：

  1. 通过类加载加载资源org/slf4j/impl/StaticLoggerBinder.class，找到所有的日志实现。
  2. 当底层日志实现多于1个时，进行汇报。
  3. 执行静态绑定。需要注意的是，在具有多个日志实现时，JVM加载哪个StaticLoggerBinder是依赖于操作系统实现的。并且在JVM成功加载一个StaticLoggerBinder后，不会再加载其他实现（双亲委托模式保证下的类唯一性）。
  4. 修改状态为SUCCESSFUL_INITIALIZATION。
  5. 如果是多日志实现，汇报最终使用的日志实现。

这里也展示了之前几个状态的由来：

  1. 出现NoClassDefFoundError，可能有两种情况：
    1. 底层无日志实现可绑定，状态变为NOP_FALLBACK_INITIALIZATION。
    2. NoClassDefFoundError是由于其他类加载导致的，状态变为FAILED_INITIALIZATION。
  2. 出现NoSuchMethodError，可能有两种情况：
    1. StaticLoggerBinder无getSingleton方法，则表示绑定失败，状态变为FAILED_INITIALIZATION。
    2. NoSuchMethodError是由其他情况引起的，则抛出错误。
  3. 出现其他Exception，状态变为FAILED_INITIALIZATION，并抛出新的非法异常。
  4. 执行postBindCleanUp方法。

postBindCleanUp方法很重要，我们仔细看一下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
private static void postBindCleanUp() {
    // 修正之前的SubstituteLogger
    fixSubstituteLoggers();
    // 重放事件，并打印日志
    replayEvents();
    // 清空资源
    SUBST_FACTORY.clear();
}

private static void fixSubstituteLoggers() {
    synchronized (SUBST_FACTORY) {
        SUBST_FACTORY.postInitialization();
        for (SubstituteLogger substLogger : SUBST_FACTORY.getLoggers()) {
            Logger logger = getLogger(substLogger.getName());
            substLogger.setDelegate(logger);
        }
    }
}

postBindCleanUp方法主要做了这么几件事：

  1. 修正之前的SubstituteLogger。还记得SubstituteLogger怎么来的么？当一个线程执行初始化时（初始化未结束），另一个线程同时申请创建日志对象，就会返回SubstituteLogger。在初始化结束前，SubstituteLogger都只会把日志操作记录成日志事件，并投放到事件队列中去。那么修正的含义到底是什么呢？
    1. 将SUBST_FACTORY的postInitialization标记置为true。置为true之后，SUBST_FACTORY后续创建的SubstituteLogger，如果内部没有代理日志对象，那么对于所有的日志操作都执行空。
    2. 将SUBST_FACTORY现有的所有SubstituteLogger对象，都创建一个真正的日志对象，作为它们的代理。有了代理之后，所有对SubstituteLogger的日志操作都转给相应代理去实现。
  2. 之前说过SUBST_FACTORY创建的SubstituteLogger在初始化前都会把日志操作以事件存放到事件队列中。此时就是让事件队列中的所有事件回放，然后交给对应的代理日志对象进行真正的日志打印。
  3. 由于此时初始化已完成，后续使用不到SUBST_FACTORY，所以清空资源。

整个静态绑定的过程到这里也就结束了。

Slf4j占位符实现

翻了slf4j-api的源码，发现其中的Logger类对于debug、info等方法的调用是直接交给底层Logger实现去处理的。那么slf4j关于占位符的实现到底是在哪里呢？
通过对源码的反复阅读，我发现slf4j-api的确提供了对打印信息中占位符的处理（MessageFormatter类），但是slf4j-api中的Logger的确是直接将方法调用交给下层对象去实现的。其实真正的调用关系如图所示：

以slf4j和log4j的搭配为例，其实slf4j-api中的Logger只是对下层适配器的引用（在slf4j-log4j12.jar中)，而适配器的底层才是真正的底层Logger（在log4j.jar中）。而对于占位符的操作其实是由适配器进行处理，也就是说Slf4j API中的消息，在Adaption Layer中对占位符进行消除和替换，再把替换后的消息交给Underlying logging framework。当然Slf4j和Logback的组合没有中间的适配器层，即表示logback本身就能对占位符进行处理。 下面的MessageFormatter.arrayFormat方法是对含有占位符的字符串的真正处理过程。其实就是将占位符{}展开为后续的参数，由StringBuilder进行拼接。 
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray, Throwable throwable) {
    if (messagePattern == null) {
        return new FormattingTuple(null, argArray, throwable);
    }
    if (argArray == null) {
        return new FormattingTuple(messagePattern);
    }

    int i = 0;
    int j;
    // use string builder for better multicore performance
    StringBuilder sbuf = new StringBuilder(messagePattern.length() + 50);

    int L;
    for (L = 0; L < argArray.length; L++) {

        j = messagePattern.indexOf(DELIM_STR, i);

        if (j == -1) {
            // no more variables
            if (i == 0) { // this is a simple string
                return new FormattingTuple(messagePattern, argArray, throwable);
            } else { // add the tail string which contains no variables and return
                // the result.
                sbuf.append(messagePattern, i, messagePattern.length());
                return new FormattingTuple(sbuf.toString(), argArray, throwable);
            }
        } else {
            if (isEscapedDelimeter(messagePattern, j)) {
                if (!isDoubleEscaped(messagePattern, j)) {
                    L--; // DELIM_START was escaped, thus should not be incremented
                    sbuf.append(messagePattern, i, j - 1);
                    sbuf.append(DELIM_START);
                    i = j + 1;
                } else {
                    // The escape character preceding the delimiter start is
                    // itself escaped: "abc x:\\{}"
                    // we have to consume one backward slash
                    sbuf.append(messagePattern, i, j - 1);
                    deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
                    i = j + 2;
                }
            } else {
                // normal case
                sbuf.append(messagePattern, i, j);
                deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
                i = j + 2;
            }
        }
    }
    // append the characters following the last {} pair.
    sbuf.append(messagePattern, i, messagePattern.length());
    return new FormattingTuple(sbuf.toString(), argArray, throwable);
}
其实Slf4j受欢迎也有占位符的原因。因为之前的日志打印，如果要打印多字符串的话，其方式如下： 
log.info("hello " + "world!")

使用+号进行拼接，首先当字符串很多的时候，就需要一大串+，很不美观，而使用StringBuilder进行占位符的填充更加优雅。并且在夹杂大部分debug日志（生产环境下日志级别设为INFO）的场景下，性能高于直接拼接。

Logback源码分析

既然说了Slf4j，那顺便把Logback说了吧。以下源码版本为1.1.7，并且代码段之间不一定连续（仅按照调用顺序截取了一部分）。

创建Logger

常见的创建方法如下：

private static Logger log = LoggerFactory.getLogger(xxx.class);

然后进入：

1
2
3
4
5
6
public static Logger getLogger(String name) {
    // 之前讲过
    ILoggerFactory iLoggerFactory = getILoggerFactory();
    // 主要是以下方法
    return iLoggerFactory.getLogger(name);
}

之后的代码位于logback-classic-1.1.7.jar里，主要是.分隔符依次创建父Logger，直到完整名称的Logger创建出来为止。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
public final Logger getLogger(final String name) {
    if (name == null) {
        throw new IllegalArgumentException("name argument cannot be null");
    }
    // 如果是name == "ROOT"，则直接返回根Logger
    if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
        return root;
    }
    int i = 0;
    Logger logger = root;
    // 查看缓存中是否已经存在对应的Logger
    Logger childLogger = (Logger) loggerCache.get(name);
    if (childLogger != null) {
        return childLogger;
    }
    String childName;
    while (true) {
        int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
        if (h == -1) {
            childName = name;
        } else {
            childName = name.substring(0, h);
        }
        // 由于logback中Logger是以父子关系进行组织的，所以从根Logger开始查找
        // com.twd的父Logger为com
        i = h + 1;
        synchronized (logger) {
            childLogger = logger.getChildByName(childName);
            if (childLogger == null) {
                // 若所要创造的Logger的父Logger不存在，创建并缓存
                childLogger = logger.createChildByName(childName);
                loggerCache.put(childName, childLogger);
                incSize();
            }
        }
        logger = childLogger;
        if (h == -1) {
            return childLogger;
        }
    }
}

简单概括下创建的过程：

  1. 查看是否是根Logger，是的话直接返回
  2. 查看缓存中是否有对应Logger存在，存在则直接返回。
  3. 按照类全限定名依次创建Logger，例如com.twd.LogTest从根Logger开始的从属关系为ROOT -> com -> com.twd -> com.twd.LogTest，并且父Logger的日志级别会继承给子Logger。

使用Logger打印日志

通过语句log.info("hello world")进行展开。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                final Throwable t) {
    // 得到Turbo Filter的过滤结果
    // 注意：Turbo Filter的作用域跟logback上下文的作用域一致，跟Append内部的过滤器不一样
    final FilterReply decision = loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);
    // 根据Turbo Filter的过滤结果判断是否往下走
    if (decision == FilterReply.NEUTRAL) {
        if (effectiveLevelInt > level.levelInt) {
            return;
        }
    } else if (decision == FilterReply.DENY) {
        return;
    }
    // 创建LoggingEvent并添加到Appender中
    buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
}

接着开始创建日志事件，然后调用相关Appender。

1
2
3
4
5
6
private void buildLoggingEventAndAppend(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                final Throwable t) {
    LoggingEvent le = new LoggingEvent(localFQCN, this, level, msg, t, params);
    le.setMarker(marker);
    callAppenders(le);
}

然后继续往下debug：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
// 唤醒与该Logger关联的Appender
public void callAppenders(ILoggingEvent event) {
    int writes = 0;
    // 依次从当前Logger到根Logger进行查找，找到所有关联的Appender
    // 所以使用的时候，当前Logger到根Logger的所有Logger关联的Appender尽量别重复，不然日志会打印多遍
    for (Logger l = this; l != null; l = l.parent) {
        // 进行添加
        writes += l.appendLoopOnAppenders(event);
        // 如果该链路上某个Logger声明了additivity="false"，那么不再往上添加Appender
        if (!l.additive) {
            break;
        }
    }
    // No appenders in hierarchy
    if (writes == 0) {
        loggerContext.noAppenderDefinedWarning(this);
    }
}

具体的Appender添加LoggerEvent的代码如下：

1
2
3
4
5
6
7
8
9
public int appendLoopOnAppenders(E e) {
    int size = 0;
    for (Appender<E> appender : appenderList) {
        // 真正的核心方法
        appender.doAppend(e);
        size++;
    }
    return size;
}

终于到达核心部分：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
public void doAppend(E eventObject) {
    // 这里的guard是ThreadLocal变量，用于防止重复调用
    if (Boolean.TRUE.equals(guard.get())) {
        return;
    }

    try {
        guard.set(Boolean.TRUE);
        if (!this.started) {
            if (statusRepeatCount++ < ALLOWED_REPEATS) {
                addStatus(new WarnStatus("Attempted to append to non started appender [" + name + "].", this));
            }
            return;
        }
        // 这里才是通过Appender的Regular Filter进行过滤
        if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
            return;
        }
        // 然后开始打印日志
        this.append(eventObject);
    } catch (Exception e) {
        if (exceptionCount++ < ALLOWED_REPEATS) {
            addError("Appender [" + name + "] failed to append.", e);
        }
    } finally {
        guard.set(Boolean.FALSE);
    }
}

继续往下n步：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
protected void subAppend(E event) {
    if (!isStarted()) {
        return;
    }
    try {
        // this step avoids LBCLASSIC-139
        if (event instanceof DeferredProcessingAware) {
            // 获得相关属性，消息格式、线程信息、映射调试上下文
            ((DeferredProcessingAware) event).prepareForDeferredProcessing();
        }
        // 这里防止多线程调用Appender输出日志，即一个Appender同一时刻只能写一个LoggingEvent
        lock.lock();
        try {
            // 输出日志
            writeOut(event);
        } finally {
            lock.unlock();
        }
    } catch (IOException ioe) {
        this.started = false;
        addStatus(new ErrorStatus("IO failure in appender", this, ioe));
    }
}

小结

目前描述的仅是Logback的同步日志功能。该功能中，Logback在用户线程中进行打印。当然Logback也支持异步日志打印（有丢失日志的风险），如果有感兴趣的朋友，也可以去了解下。
Logback的逻辑也比较简单：

  1. 创建Logger
    1. 若需要创建的Logger已存在Logger池中，那么直接拿出来。
    2. 若不存在，则创建Logger，并存储在池中。
  2. 同步打印日志
    1. 先经过LoggerContext（全局对象）的Turbo Filter的过滤，根据结果判断是否继续。
    2. 生成LoggerEvent
    3. 从当前Logger到根Logger自底向上查找，将event添加到所有关联的Appender。
    4. Appender执行日志打印（此处进行同步），保证每个Appender的日志输出是串行化的。