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

川长思鸟来 2023-10-03 08:41 5阅读 0赞

## 系列文章目录 ##

--------------------

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

### 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][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就有了属性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锁保证了打印日志的顺序性，同时也因为锁的问题导致并发能力下降，进而影响正常的业务流程的响应。所以，在线上系统中，我们尽量使用异步的方式打印日志。当然，异步的情况下也有弊端，即日志有丢失的可能，但这总比整个系统因日志打印而崩溃要好得多。

[https_blog.csdn.net_u013978512_article_details_117884148_spm_1001.2014.3001.5501]: https://blog.csdn.net/u013978512/article/details/117884148?spm=1001.2014.3001.5501