追踪一下slf4j的工作原理

Posted by hcy on August 20, 2019

追踪一下slf4j的工作原理

slf4j 是一个java界非常流行的日志门面框架,使用它,你可以任意更换底层实现,如logbacklog4j,而不需要修改代码。那他是如何做到的。

引入slf4j的包

​ 这里采用最新稳定版,因为只引入slf4j无法打印日志,这里选择logback作为底层实现。

1
2
3
4
5
6
7
8
9
10
11
<dependency>
   <groupId>org.slf4j</groupId>
   <artifactId>slf4j-api</artifactId>
   <version>1.7.28</version>
</dependency>

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.3</version>
</dependency>

测试输出

​ 从LoggerFactory获取一个Logger对象,就能使用了。

1
2
3
4
5
6
	public static void main(String[] args) {
		Logger log = LoggerFactory.getLogger(T1.class);
		log.info("info");
		log.debug("debug");
		log.warn("warn");
	}

代码解析

委托给ILoggerFactory

​ 获取过程中采用懒加载模式,为避免多线程堵塞,使用状态位标识初始化时的多种状态。

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
55
	//使用类全路径名创建Logger
    public static Logger getLogger(Class<?> clazz) {
        Logger logger = getLogger(clazz.getName());
   	    return logger;
    }
	
	//通过获取ILoggerFactory工厂,创建Logger
	public static Logger getLogger(String name) {
   	 ILoggerFactory iLoggerFactory = getILoggerFactory();
   	 return iLoggerFactory.getLogger(name);
	}
	
	
	/*
		判断状态位 INITIALIZATION_STATE,状态位共五种状态
			UNINITIALIZED   尚未初始化
			SUCCESSFUL_INITIALIZATION  成功初始化
			NOP_FALLBACK_INITIALIZATION 无底层实现类
			FAILED_INITIALIZATION  初始化报错
			ONGOING_INITIALIZATION  初始化中
	*/

    public static ILoggerFactory getILoggerFactory() {
		//这里类似懒汉单例模式,加锁后设置状态位为ONGOING_INITIALIZATION,然后调用初始化代码。这样就只能有一个线程会初始化loggerfactory,其他线程走下面的switch 中的 ONGOING_INITIALIZATION。
        if (INITIALIZATION_STATE == UNINITIALIZED) {
            synchronized (LoggerFactory.class) {
                if (INITIALIZATION_STATE == UNINITIALIZED) {
                    INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                    performInitialization();
                }
            }
        }
        switch (INITIALIZATION_STATE) {
        //初始化成功,返回单例的LoggerFactory
        case SUCCESSFUL_INITIALIZATION:
            return StaticLoggerBinder.getSingleton().getLoggerFactory();
        //没底层实现时走这里        
        case NOP_FALLBACK_INITIALIZATION:
            return NOP_FALLBACK_FACTORY;
        //初始化过程中抛异常,这里也抛异常        
        case FAILED_INITIALIZATION:
            throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
        //初始化中,返回一个代理Factory,此代理Factory能创建代理Logger
        case ONGOING_INITIALIZATION:
            // support re-entrant behavior.
            // See also http://jira.qos.ch/browse/SLF4J-97
            return SUBST_FACTORY;
        }
        throw new IllegalStateException("Unreachable code");
    }
	

	//这里的INITIALIZATION_STATE的定义,其加了volatile关键字,多线程修改他时,能立刻被看到
 	static volatile int INITIALIZATION_STATE = UNINITIALIZED;

五种状态

  • 1.如果第一次访问,为未初始化状态,UNINITIALIZED,则让第一个获得锁的进行初始化,且不会堵塞后来的线程,将状态切换成ONGOING_INITIALIZATION
  • 2.如果初始化成功,SUCCESSFUL_INITIALIZATION,后来的线程可以直接从StaticLoggerBinder中获取loggerFactory
  • 3.如果没有底层实现类,NOP_FALLBACK_INITIALIZATION,则返回NOP_FALLBACK_FACTORY
  • 4.如果初始化报错了,FAILED_INITIALIZATION,则直接抛出异常,阻止程序继续执行。
  • 5.如果正在初始化中ONGOING_INITIALIZATION,则返回一个代理loggerFactory,他会把所有的logger记录在队列中,等待真正初始化完成后,用真实的logger把队列中的日志输出出来。

​ 其中比较有意思的就是,slf4j为了在初始化Factory期间不堵塞程序,设置了ONGOING_INITIALIZATION状态,在此状态下(初始化中)获取Factory会返回SubstituteLoggerFactory

1
2
3
	//初始化中时,返回的临时loggerfactory
	static final SubstituteLoggerFactory SUBST_FACTORY = new SubstituteLoggerFactory();

SubstituteLoggerFactory实现细节

​ 下面代码是SubstituteLoggerFactorygetLogger()方法。

第二行的loggers 是一个MapgetLogger方法会返回SubstituteLogger对象,并缓存到loggers里面。

1
2
3
4
5
6
7
8
9
	//SubstituteLoggerFactory的getLogger方法
    synchronized public  Logger getLogger(String name) {
        SubstituteLogger logger = loggers.get(name);
        if (logger == null) {
            logger = new SubstituteLogger(name, eventQueue, postInitialization);
            loggers.put(name, logger);
        }
        return logger;
    }

SubstituteLogger实现细节

​ 这个logger是一个代理logger,它包含一个_delegate对象,当_delegate为空时,会根据createdPostInitialization标志位返回NOP_LOGGER或者EventRecodingLogger

EventRecodingLogger会将日志输出到到eventQueue里。

createdPostInitialization默认是false,Logger初始化后该值被设置为true。

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
	//SubstituteLogger的info方法,是如何实现的
	
	private volatile Logger _delegate;
	private final boolean createdPostInitialization;
   

	public void info(String msg) {
        delegate().info(msg);
    }

    Logger delegate() {
        if(_delegate != null) {
            return _delegate;
        }
        if(createdPostInitialization) {
            return NOPLogger.NOP_LOGGER;
        } else {
            return getEventRecordingLogger();
        }
    }

    private Logger getEventRecordingLogger() {
        if (eventRecodingLogger == null) {
            eventRecodingLogger = new EventRecodingLogger(this, eventQueue);
        }
        return eventRecodingLogger;
    }

delegate()方法会有三种返回可能,

  1. 如果存在被代理的_delegate,则返回_delegate
  2. 如果createdPostInitializationtrue,则返回一个nopLogger,否则返回一个EventRecodingLogger
  3. nopLogger 会扔掉所有的日志
  4. EventRecodingLogger会将所有日志放入queue中存储起来。

所以slf4j在初始化阶段的日志也不会丢失,而是存储在queue中,等到初始化完成,会取出来输出。

loggerFactory初始化过程

​ 核心在bind方法里。

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
 private final static void bind() {
        try {
			//用类加载器加载名称叫做 ‘org/slf4j/impl/StaticLoggerBinder.class’的类,这个字符串是写死在代码里的。因为可能存在多个实现,所以使用Set<URL>
            Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
        	//调用StaticLoggerBinder的静态方法,StaticLoggerBinder可能不存在而报NoClassDefFoundError下面会捕获这个异常。
            StaticLoggerBinder.getSingleton();
			//修改状态位为success
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
			//将SubstituteLoggerFactory的loggers(map)存储的临时logger获取出来,设置logger中的_delegate变量为真实logger
            fixSubstituteLoggers();
			//从队列中取出日志,用真实logger输出
            replayEvents();
            //清理SubstituteLoggerFactory 内map中存储的logger,清理队列
            SUBST_FACTORY.clear();
        } catch (NoClassDefFoundError ncde) {
			//如果报NoClassDefFoundError,可能是没有任何实现类,这时将状态位设为NOP_FALLBACK_INITIALIZATION
            String msg = ncde.getMessage();
            if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
                INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
            } else {
                failedBinding(ncde);
                throw ncde;
            }
		//如果报NoSuchMethodError,可能是底层实现类没有按照要求实现,将状态位设为FAILED_INITIALIZATION
        } catch (java.lang.NoSuchMethodError nsme) {
            String msg = nsme.getMessage();
            if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
                INITIALIZATION_STATE = FAILED_INITIALIZATION;
            }
            throw nsme;
        } catch (Exception e) {
            failedBinding(e);
            throw new IllegalStateException("Unexpected initialization failure", e);
        }
    }

总结

slf4j会反射org/slf4j/impl/StaticLoggerBinder.class类,如果发现多个实现类,会输出日志提醒用户存在多个实现,并使用第一个实现类。

​ 他会直接调用StaticLoggerBinder.getSingleton(),如果不存在org/slf4j/impl/StaticLoggerBinder.class会抛ClassNotFound异常,这就表明底层实现不存在。

​ 获取StaticLoggerBinder实例过后,会调用fixSubstituteLoggers()修复初始话中创建的临时logger,会将存储在queue中的日志重新输出。

一个bug

​ 上面的实现其实存在一个BUG,核心方法bind()里面的fixSubstituteLoggers()方法,replayEvents()方法只会在存在底层log实现时才会执行,不存在底层实现会抛异常进入cache代码块。如果这种情况下将导致日志一直输出到Queue里面,导致OOM

1
2
3
4
//这几行代码在没有底层实现时不能执行
fixSubstituteLoggers();
replayEvents();
SUBST_FACTORY.clear();

2020-04 更新

​ 上面提到的bug已经在1.7.30版本修复,新版本在finally代码块里面处理的这些逻辑,无论是否初始化成功都会释放Queue里面的日志,所以不用担心日志不释放的问题。

但极端情况下还会出现问题

​ 1. 线程A执行下面代码,因为第一次执行会触发初始化逻辑:

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

​ 2. 线程B在执行下面代码,获取到的ILoggerFactorySubstituteLoggerFactory实例

1
2
3
4
5
 public static Logger getLogger(String name) {
        ILoggerFactory iLoggerFactory = getILoggerFactory();
     	sleep(10000); //假设线程B执行到这里,让出cpu
        return iLoggerFactory.getLogger(name);
    }

​ 3. 线程A接着执行,直到LoggerFactory初始化完成,在方法fixSubstituteLoggers()里面会将SubstituteLoggerFactory里面的状态位postInitialization设为true,并修复创建LoggerFactory期间生成的的代理Logger

​ 4. 接着线程B继续执行,他会拿到ILoggerFactory对象获取到一个SubstituteLogger,这个SubstituteLogger不能得到修复,会恒返回NOP_LOGGER实例。从而使日志失效。

新版本

1.8版本以后slf4j加载底层实现改为javaSPI技术做了。请看这个类java.util.ServiceLoader


转载请注明出处:https://www.huangchaoyu.com/2019/08/20/追踪一下slf4j的工作原理/