天天看点

从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图5所示,可以看到被阻塞地方有synchro

作者:从头开始自学java

从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图5所示,可以看到被阻塞地方有synchronized同步调用,再结合上文发现每两分钟写满一个500MB日志文件的现象,初步怀疑是日志量过大导致了线程阻塞。

AsyncAppender顾名思义是个异步Appender,采用异步方式处理日志,在其内部维护了一个BlockingQueue队列,每次处理日志时,都先尝试把Log4jLogEvent事件存入队列中,然后交由后台线程从队列中取出事件并处理(把日志交由AsyncAppender所关联的Appender处理),但队列长度总是有限的,且队列默认大小是128,如果日志量过大或日志异步线程处理不及时,就很可能导致日志队列被打满。

当日志队列满时,日志框架内部提供了两种处理方式,具体如下:

如果blocking配置为true,会选择相应的处理策略,默认是SYNCHRONOUS策略,可以在log4j2.component.properties文件中,通过log4j2.AsyncQueueFullPolicy参数配置日志框架提供的其他策略或自定义策略。

DISCARD策略,直接忽略日志。

SYNCHRONOUS策略,当前线程直接发送日志到Appender。

ENQUEUE策略,强制阻塞入队。

如果blocking配置为false,则由ErrorHandler和ErrorAppender处理失败日志。日志框架提供了默认的ErrorHandler实现,即DefaultErrorHandler,目前暂不支持业务在XML、JSON等日志配置文件里自定义ErrorHandler。日志框架默认不提供ErrorAppender,业务如有需要可在XML、JSON等日志配置文件里自定义error-ref配置。

DefaultErrorHandler内部在处理异常日志时增加了条件限制,只有下述两个条件任一满足时才会处理,从而避免大量异常日志导致的性能问题。

两条日志处理间隔超过5min。

异常日志数量不超过3次。

但项目所用日志框架版本的默认实现看起来存在一些不太合理的地方:

lastException用于标记上次异常的时间戳,该变量可能被多线程访问,无法保证多线程情况下的线程安全。

exceptionCount用于统计异常日志次数,该变量可能被多线程访问,无法保证多线程情况下的线程安全。

所以,在多线程场景下,可能有大量异常日志同时被DefaultErrorHandler处理,带来线程安全问题。值得一提的是,该问题已有相关Issue: DefaultErrorHandler can not share values across threads反馈给社区,并在2.15.0版本中进行了修复。

从上述DefaultErrorHandler代码中可以看到,真正负责处理日志的是StatusLogger,继续跟进代码进入logMessage方法,方法执行逻辑如下:

如果StatusLogger内部注册了StatusListener,则由对应的StatusListener负责处理日志。

否则由SimpleLogger负责处理日志,直接输出日志到System.err输出流。

从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图5所示,可以看到被阻塞地方有synchro
从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图5所示,可以看到被阻塞地方有synchro
从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图5所示,可以看到被阻塞地方有synchro
从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图5所示,可以看到被阻塞地方有synchro
从Blocked线程堆栈着手分析,查看PrintStream相关代码片段如下图5所示,可以看到被阻塞地方有synchro

继续阅读