五、logback同步打印日志源码分析

系列文章目录

---

        前面的文章讲了日志的初始化过程，而第一篇文章中我们聊到了日志同步打印的时候，出现了拖慢系统响应的现象。本篇文章我们就聊聊日志打印的过程，并剖析出拖慢系统响应的原因。

1、日志打印过程概览

       上篇文章我们讲了，log系统主要有大组件-------Logger、Appender、Layout。Logger可类比原料厂，主要用于生产日志事件相关的信息，如日志级别、message、时间戳等；Layout可类比为加工厂，主要是对Logger生成的事件进行格式化，形成预期格式的日志字符串；Appender可类比为货车，主要是将Logger加工好的字符串以流的形式发送到目的地，如console、磁盘文件等。

LoggerBack打印日志的步骤：

1.日志记录：业务方调用Logger对象的info/debug等方法，进行日志记录

2.日志过滤：Logger首先在内部进行日志等级过滤，低于配置的日志等级，将直接返回

3.事件构建：Logger根据info/debug等方法传入的参数，构建LoggingEvent对象

4.事件通知：从子类到父类遍历Logger树，对每个Logger调用appendLoopOnAppenders

5.遍历输出：遍历Logger内每个Appender进行输出

2、日志打印过程源码分析

public void warn(String format, Object arg) {
        filterAndLog_1(FQCN, null, Level.WARN, format, arg, null);
    }

当调用log.info()、warn()、error()等方法的时候，内部都是调的同一个方法filterAndLog_1，会把相应的log级别传进去

 public static final int ERROR_INT = 40000;
    public static final int WARN_INT = 30000;
    public static final int INFO_INT = 20000;
    public static final int DEBUG_INT = 10000;
    public static final int TRACE_INT = 5000;

不同的级别，就是对应的数值不同，可以看到error>warn>info>debug>trace.

private void filterAndLog_1(final String localFQCN, final Marker marker, final Level level, final String msg, final Object param, final Throwable t) {

        final FilterReply decision = loggerContext.getTurboFilterChainDecision_1(marker, this, level, msg, param, t);

        if (decision == FilterReply.NEUTRAL) {
            if (effectiveLevelInt > level.levelInt) {
                return;
            }
        } else if (decision == FilterReply.DENY) {
            return;
        }

        buildLoggingEventAndAppend(localFQCN, marker, level, msg, new Object[] { param }, t);
    }

日志是否需要打印，就是在这个方法进行判断的。effectiveLeveInt值是初始化的时候设置的日志级别，如果传入的日志级别小于effectiveLeveInt，那么就直接return。这里就解释了，比如我们的系统日志级别设置的info，那么debug和trace日志就不会打印。

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);
    }

这个方法就是我们前一节介绍的logger的作用，logger就是原料厂，在这个方法里生成了日志事件，包含了该条日志必须的一些信息。

public void callAppenders(ILoggingEvent event) {
        int writes = 0;
        for (Logger l = this; l != null; l = l.parent) {
            writes += l.appendLoopOnAppenders(event);
            if (!l.additive) {
                break;
            }
        }
        // No appenders in hierarchy
        if (writes == 0) {
            loggerContext.noAppenderDefinedWarning(this);
        }
    }

这个方法很关键，在https://blog.csdn.net/u013978512/article/details/117884148?spm=1001.2014.3001.5501这篇文章中我们讲了，每一个logger都会有父logger（这里的“父”不是类继承关系，而是logger内部有个parent属性，代表其父logger），默认顶级祖师爷logger是root。这个方法中，从logger自身开始往上找parent，然后逐个遍历调appendLoopOnAppenders方法。

private int appendLoopOnAppenders(ILoggingEvent event) {
        if (aai != null) {
            return aai.appendLoopOnAppenders(event);
        } else {
            return 0;
        }
    }

<logger name="bizLogger" level="INFO" additivity="false">
        <appender-ref ref="BIZ_LOG"/>
    </logger>

如果在配置文件里配置了如上的配置，那么对应的该logger就有了属性aai，这样在调appendLoopOnAppenders方法的时候就会执行，并且该配置中配置了additivity为false，所以，执行了这个appender方法后，就跳出for循环了。如果没有配置相应的logger，那么for循环遍历到最后，会执行到root的appendLoopOnAppenders方法。

public int appendLoopOnAppenders(E e) {
        int size = 0;
        final Appender<E>[] appenderArray = appenderList.asTypedArray();
        final int len = appenderArray.length;
        for (int i = 0; i < len; i++) {
            appenderArray[i].doAppend(e);
            size++;
        }
        return size;
    }

这里是调用所有的appender的deAppend方法。

public void doAppend(E eventObject) {
        // WARNING: The guard check MUST be the first statement in the
        // doAppend() method.

        // prevent re-entry.
        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;
            }

            if (getFilterChainDecision(eventObject) == FilterReply.DENY) {
                return;
            }

            // ok, we now invoke derived class' implementation of append
            this.append(eventObject);

        } catch (Exception e) {
            if (exceptionCount++ < ALLOWED_REPEATS) {
                addError("Appender [" + name + "] failed to append.", e);
            }
        } finally {
            guard.set(Boolean.FALSE);
        }
    }

protected void append(E eventObject) {
        if (!isStarted()) {
            return;
        }

        subAppend(eventObject);
    }

protected void subAppend(E event) {
        if (!isStarted()) {
            return;
        }
        try {
            // this step avoids LBCLASSIC-139
            if (event instanceof DeferredProcessingAware) {
                ((DeferredProcessingAware) event).prepareForDeferredProcessing();
            }
            // the synchronization prevents the OutputStream from being closed while we
            // are writing. It also prevents multiple threads from entering the same
            // converter. Converters assume that they are in a synchronized block.
            // lock.lock();

            byte[] byteArray = this.encoder.encode(event);
            writeBytes(byteArray);

        } catch (IOException ioe) {
            // as soon as an exception occurs, move to non-started state
            // and add a single ErrorStatus to the SM.
            this.started = false;
            addStatus(new ErrorStatus("IO failure in appender", this, ioe));
        }
    }

private void writeBytes(byte[] byteArray) throws IOException {
        if(byteArray == null || byteArray.length == 0)
            return;
        
        lock.lock();
        try {
            this.outputStream.write(byteArray);
            if (immediateFlush) {
                this.outputStream.flush();
            }
        } finally {
            lock.unlock();
        }
    }

以上是doAppend的底层代码。关键看最后一个代码，在write的时候，加了一把锁。第一篇文章中我们说到，同步打印日志的时候，在高并发的情况下会拖慢系统，原因就在这里。

3、总结

       通过同步打印的源码，可以看到，在发送日志数据流的时候，通过AQS锁保证了打印日志的顺序性，同时也因为锁的问题导致并发能力下降，进而影响正常的业务流程的响应。所以，在线上系统中，我们尽量使用异步的方式打印日志。当然，异步的情况下也有弊端，即日志有丢失的可能，但这总比整个系统因日志打印而崩溃要好得多。