Log4j2打印INFO日志导致线程Block

前言

      随着业务的快速增长,日志导致的线程 Block 问题愈发频繁。比如调用后端 RPC 服务超时,导致调用方大量线程 Block;再比如,业务内部输出异常日志导致服务大量线程 Block 等,这些问题严重影响着服务的稳定性。

日志队列满导致线程 Block

      通过监控平台查看线程监控指标, Blocked 线程堆栈不难看出这跟日志打印相关,而且是 INFO 级别的日志,遂即登陆机器查看日志是否有异样,发现当时日志量非常大,差不多每两分钟就写满一个500MB 的日志文件。

为什么会 Block 线程

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

但上述猜测仍有一些值得推敲的地方:

1、如果仅仅因为日志量过大就导致线程 Block,那日志框架也太不堪重用了,根本没法在高并发、高吞吐业务场景下使用。

2、日志配置里明明是输出日志到文件,怎么会输出到 Console PrintStream ?

为什么会输出到 Console

      继续沿着线程堆栈调用链路分析,可以看出是 AsyncAppender 调用 append 方法追加日志时发生了错误。

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

      在本项目的日志配置文件中可以看到,AsyncAppender 设置了 blocking 为 false,且没有配置 error-ref

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

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

○ DISCARD 策略,直接忽略日志。

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

○ ENQUEUE 策略,强制阻塞入队。

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

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

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

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

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

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

● 异常日志数量不超过 3 次。但项目所用日志框架版本的默认实现看起来存在一些不太合理的地方:

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

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

      所以,在多线程场景下,可能有大量异常日志同时被 DefaultErrorHandler 处理,带来线程安全问题。值得一提的是,该问题在 2.15.0 版本中进行了修复

        从上述 Blocked 线程堆栈来看,是 StatusConsoleListener 负责处理日志,而StatusConsoleListener 是 StatusListener 接 口 的 实 现 类。

StatusConsoleListener 是怎么来的

      通常来说,每个项目都会有一个日志配置文件(如 log4j2.xml),该配置对应 Log4j2日志框架中的 Configuration 接口,不同的日志配置文件格式有不同的实现类:

● XmlConfiguration,即 XML 格式日志配置

● JsonConfiguration,即 JSON 格式日志配置

      以log4j2.xml 示例配置,Log4j2 在启动时会加载并解析 log4j2.xml 配置文件,由对应的 ConfigurationFactory 创建具体 Configuration 实例。

      创建 XmlConfiguration 时, 会 先 创 建 StatusConfiguration, 随 后 在 初 始 化StatusConfiguration 时创建并注册 StatusConsoleListener 到 StatusLogger 的listeners 中,日志配置文件中 <Configuration> 标签的属性值通过 XmlConfiguration->StatusConfiguration->StatusConsoleListener 这样的关系链路最终影响StatusConsoleListener 的行为。

      StatusLogger 采用单例模式实现,它输出日志到 Console(如 System.out 或 System.err),从上文分析可知,在高并发场景下非常容易导致线程 Block。

日志配置文件中的 <Configuration> 标签可以配置属性字段,部分字段如下所示:

status,可选值包括 OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、ALL,该值决定 StatusConsoleListener 级别,默认是 ERROR

dest,可选值包括 out、err、标准的 URI 路径,该值决定 StatusConsoleListener 输出流目的地,默认是 System.out。

        在本项目的日志配置文件中可以看到并没有设置 Configuration 的 dest 属性值,所以日志直接输出到 System.out

StatusLogger 有什么用

      StatusLogger 在交由 StatusListener 处理日志前,会判断日志级别,如果级别条件不满足,则忽略此日志,StatusConsoleListener 的日志级别默认是 ERROR。

问题小结

        日志量过大导致 AsyncAppender 日志队列被打满,新的日志事件无法入队,进而由 ErrorHandler 处理日志,同时由于 ErrorHandler 存在线程安全问题,导致大量日志输出到了 Console,而 Console 在输出日志到 PrintStream 输出流时,存在synchronized 同步代码块,所以在高并发场景下导致线程 Block。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 220,492评论 6 513
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 94,048评论 3 396
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 166,927评论 0 358
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 59,293评论 1 295
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 68,309评论 6 397
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 52,024评论 1 308
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,638评论 3 420
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,546评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 46,073评论 1 319
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 38,188评论 3 340
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 40,321评论 1 352
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,998评论 5 347
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,678评论 3 331
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 32,186评论 0 23
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 33,303评论 1 272
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,663评论 3 375
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 45,330评论 2 358

推荐阅读更多精彩内容