业务开发中,少不了打印日志,常用的日志框架有commons logging/log4j/logback/log4j2等,同步日志方面logback性能略微胜出,而异步日志方面log4j2性能突出。今天我们就聊聊Logback。

SLF4J

说到logback,必会提及slf4j。slf4j的全称是:The Simple Logging Facade for Java,是java的一个日志门面,堪称Facade设计模式的最佳代言人!slf4j制定了一套标准接口,从而实现在【日志】这个领域里一统江湖。主要做两件事:

  1. 实现了Logger获取的通用api:LoggreFactory.getLogger(),该方法基本上确定了获取Logger的基础套路,约定了实现slf4j的日志框架需要实现org.slf4j.impl.StaticLoggerBinder,完成与slf4j的集成。
  2. 定义了ILoggerFactory,Logger等系列接口,该接口由具体日志框架实现。

这种通用API使得我们在切换日志框架时显得非常轻松,仅仅需要改一下依赖的jar包,而不需要修改任何日志相关的代码。slf4J抽象了统一的日志接口,而logback等是具体的日志框架,其原生实现了slf4j。而其它日志框架(log4j/commons logging等)需要通过适配,才能实现与slf4j的集成。

LoggerFactory.getLogger()

在slf4j的标准里,获取Logger通过LoggerFactory.getLogger(),这里的LoggerFactory是slf4j实现的,我们进入源码:

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

该方法主要做两件事,一是获取(创建)ILoggerFactory,二是通过ILoggerFactory获取(创建)Logger对象

LoggerContext初始化

在logback里,实现ILoggerFactory的是LoggerContext,该类是logback的核心所在,有点类似于spring的ApplicationContext。来看看它的主要成员:

final Logger root;
    private int size;
    private int noAppenderWarning = 0;
    final private List<LoggerContextListener> loggerContextListenerList = new ArrayList<LoggerContextListener>();
    private Map<String, Logger> loggerCache;
    private LoggerContextVO loggerContextRemoteView;
    private final TurboFilterList turboFilterList = new TurboFilterList();
    private boolean packagingDataEnabled = DEFAULT_PACKAGING_DATA;
    private int maxCallerDataDepth = ClassicConstants.DEFAULT_MAX_CALLEDER_DATA_DEPTH;
    int resetCount = 0;
    private List<String> frameworkPackages;

其中最核心的是:
loggerCache:维护着已创建好的Logger对象实例,
root:根Logger,没错,就是那个配置文件里的那个所对应的Logger
通过这个定义大概可以看出,LoggerContext具备管理Logger的能力,回过头来看getILoggerFactory()的实现:

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

SLF4J定义了LoggerFactory的几个状态,在这几个状态下,会返回不同的ILoggerFactory:

状态

状态描述

对应的ILoggerFactory

说明

SUCCESSFUL_INITIALIZATION

初始化成功

LoggerContext

由具体日志框架(logback)实现

FAILED_INITIALIZATION

初始化失败

抛出异常

NOP_FALLBACK_INITIALIZATION

不作为

NOPLoggerFactory

SLF4J实现,不对日志做任务处理

ONGOING_INITIALIZATION

初始化中

SubstituteLoggerFactory

SLF4J实现,用于生产可被代替的Logger

其中ONGOING_INITIALIZATION是个有趣的状态,在这个状态下,会返回一个SUBST_FACTORY,这是个SubstituteLoggerFactory,用于生产SubstituteLogger(同样实现了Logger接口),这种类型Logger不是正式的Logger,其持有一个正式Logger的引用,该引用在初始化为null,等到正式的LoggerFactory(即LoggerContext)初始化成功之后,框架会将正式Logger的引用赋值给SubstituteLogger,得益于这种设计,业务系统的启动速度不会受到Logback自身初始化的丝毫影响。
接着来看performInitialization():

private final static void performInitialization() {
        bind();
        if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
            versionSanityCheck();
        }
    }

来到bind(),这个方法很重要,基本上可以窥探整个初始化流程。主要做以下几件事:

private final static void bind() {
        try {
        	//1:查找并获取StaticLoggerBinder的类路径
            Set<URL> staticLoggerBinderPathSet = null;
            if (!isAndroid()) {
                staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
                reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
            }
            //2:初始化
            StaticLoggerBinder.getSingleton();
            //3:标记初始化完成
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            //4:告诉客户:真实绑定了哪个StaticLoggerBinder
            reportActualBinding(staticLoggerBinderPathSet);
            //5:修正SubstituteLogger,将真正的Logger赋值给SubstituteLogger
            fixSubstituteLoggers();
            //6:对SubstituteLogger所记录的SubstituteLoggerEvent做真正的记录
            replayEvents();
            //7:SubstituteLoggerFactory已完成使命,清空
            SUBST_FACTORY.clear();
        } 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);
        }
    }

SLF4J先找到可能的StaticLoggerBinder,然后调用第1个StaticLoggerBinder的getSingleton()方法. StaticLoggerBinder使用单例模式,其对象的实例化过程就是logback 的初始化过程。这里不一一贴出代码,大概过程如下:
1. 查找logback配置文件 ,以logback1.2.3为例,优先找logback.groovy,logback-text.xml次之,最后找logback.xml
2. 使用sax解释并加载配置,将每个元素解释为一个SaxEvent对象,然后交给EventPlayer进行事件播放(即配置解释),最后根据元素的路径(ElementPath)会匹配到一个以上的Action(元素与Action的对象关系维护在JoranConfigurator中),而Action执行最终的解释,并最终生成Logger,Appender,Encodor,Layout等序列对象。
如AppenderAction负责解释元素,生成Appender对象,LoggerAction对象负责解释元素,生成Logger对象等。下面以LoggerAction为例进行分析:

public void begin(InterpretationContext ec, String name, Attributes attributes) {
        // Let us forget about previous errors (in this object)
        inError = false;
        logger = null;

        LoggerContext loggerContext = (LoggerContext) this.context;
		//拿<logger>中的name属性
        String loggerName = ec.subst(attributes.getValue(NAME_ATTRIBUTE));
		//name不能为空
        if (OptionHelper.isEmpty(loggerName)) {
            inError = true;
            String aroundLine = getLineColStr(ec);
            String errorMsg = "No 'name' attribute in element " + name + ", around " + aroundLine;
            addError(errorMsg);
            return;
        }
		//通过LoggerContext.getLogger()
        logger = loggerContext.getLogger(loggerName);
		//解释并设置level属性
        String levelStr = ec.subst(attributes.getValue(LEVEL_ATTRIBUTE));

        if (!OptionHelper.isEmpty(levelStr)) {
            if (ActionConst.INHERITED.equalsIgnoreCase(levelStr) || ActionConst.NULL.equalsIgnoreCase(levelStr)) {
                addInfo("Setting level of logger [" + loggerName + "] to null, i.e. INHERITED");
                logger.setLevel(null);
            } else {
                Level level = Level.toLevel(levelStr);
                addInfo("Setting level of logger [" + loggerName + "] to " + level);
                logger.setLevel(level);
            }
        }
		//解释并设置additive属性
        String additivityStr = ec.subst(attributes.getValue(ActionConst.ADDITIVITY_ATTRIBUTE));
        if (!OptionHelper.isEmpty(additivityStr)) {
            boolean additive = OptionHelper.toBoolean(additivityStr, true);
            addInfo("Setting additivity of logger [" + loggerName + "] to " + additive);
            logger.setAdditive(additive);
        }
        ec.pushObject(logger);
    }

Logger的创建

Logger的创建有两个时机,一个在配置文件中通过元素定义,经LoggerAction解释后生成,一个是通过LoggerFactory.getLogger(),无论哪一种,最终都会进入LoggerContext.getLogger()

@Override
    public final Logger getLogger(final String name) {

        if (name == null) {
            throw new IllegalArgumentException("name argument cannot be null");
        }
		//如果请求的是根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;
        }
		//从ROOT开始,沿着name的方向,依次获取并创建Logger
        String childName;
        while (true) {
            int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
            if (h == -1) {
                childName = name;
            } else {
                childName = name.substring(0, h);
            }
            // move i left of the last point
            i = h + 1;
            synchronized (logger) {
                childLogger = logger.getChildByName(childName);
                if (childLogger == null) {
                    childLogger = logger.createChildByName(childName);
                    loggerCache.put(childName, childLogger);
                    incSize();
                }
            }
            logger = childLogger;
            if (h == -1) {
                return childLogger;
            }
        }
    }

通常元素中指定的name是包名,而getLogger()中指定的类名,logback会从root开始,尚着包名或类名的方向,以包为单位,逐级创建对应名称的Logger,比如:getLogger(“com.vip.aaa.bbb.HelloService”),会依次创建如下的Logger:

次序

logger名称

1

com

2

com.vip

3

com.vip.aaa

4

com.vip.aaa.bbb

5

com.vip.aaa.bbb.HelloService

一个Logger有一个parent(根Logger除外),和若干个child,所有的Logger构成一棵Logger树。而这么Logger,一旦创建出来,就全部会缓存在LoggerContext的loggerCache中。

日志级别的继承

1个Logger如果没有显式指定level,其level由其parent决定,见Logger.createChildByName

Logger createChildByName(final String childName) {
        int i_index = LoggerNameUtil.getSeparatorIndexOf(childName, this.name.length() + 1);
        if (i_index != -1) {
            throw new IllegalArgumentException("For logger [" + this.name + "] child name [" + childName
                            + " passed as parameter, may not include '.' after index" + (this.name.length() + 1));
        }

        if (childrenList == null) {
            childrenList = new CopyOnWriteArrayList<Logger>();
        }
        Logger childLogger;
        childLogger = new Logger(childName, this, this.loggerContext);
        childrenList.add(childLogger);
        //子级logger的有效级别继承自直属的父级Logger
        childLogger.effectiveLevelInt = this.effectiveLevelInt;
        return childLogger;
    }

Logger的打印

以最常用的Logger.info()为例,SLF4J推荐使用log.info(“hello {}”,变量名)方式来打印日志,可接受1个或多个变量。SLF4J定义了10个重载方法,在logback的实现中,最终会根据日志参数个数的不同,调用不同的方法:
0或者3个以上参数调用:filterAndLog_0_Or3Plus()
1个参数调用:filterAndLog_1()
2个参数调用:filterAndLog_2()
为什么这么做,文档中解释是:The next methods are not merged into one because of the time we gain by not creating a new Object[] with the params. This reduces the cost of not logging by about 20 nanoseconds.
分开多个方法,虽然代码看不去没那么优雅,但在日志不需要被记录(如达不到指定级别)的情况下,可以不需要创建参数数组,从而提升一点点性能(20纳秒)。进入:filterAndLog_0_Or3Plus()

private void filterAndLog_0_Or3Plus(final String localFQCN, final Marker marker, final Level level, final String msg, final Object[] params,
                    final Throwable t) {

        final FilterReply decision = loggerContext.getTurboFilterChainDecision_0_3OrMore(marker, this, level, msg, params, t);

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

        buildLoggingEventAndAppend(localFQCN, marker, level, msg, params, t);
    }

在LoggerContext中有个TurboFilterList,存放了若干个TurboFilter,用于在日志记录之前搞些事情,最终决定是否将这个日志放行,最会返回FilterReply,
DENY:表示拒绝,将抛弃这个日志请求。
NEUTRAL:放行,进入写一下TurboFilter
ACCEPT:接受,表示要定这个请求,跳过后面的TurboFilter,直接进入日志打印:buildLoggingEventAndAppend()

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

调用Appender时,会逐级追溯父级Logger,并将LoggerEvent交给父级Logger的Appender去处理,直到logger.additive被配置为false。

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

后面的代码,就是日志的格式化和输出,涉及到Encoder,Layout,Converter等,作者对各层组件(接口)做了很好的抽象,体现了很好的分层思想。具体的代码不一一展开,有兴趣的同学可以自己看看。主要的流程如下:

flink项目配置 sl4j log4j flink logback_日志框架