GMTC北京站9折购票倒计时,部分日程已上线,戳此查看 了解详情
写点什么

一次 Logback 发现的隐患

  • 2020 年 3 月 15 日
  • 本文字数:2023 字

    阅读完需:约 7 分钟

一次 Logback 发现的隐患

一、现象描述

近期我们在线下环境进行了核心链路单接口的性能摸底,在使用我厂基于 Gatling 自研的 gatling-dubbo 框架(详见Dubbo 压测插件 2.0 —— 基于普通 API 调用)对 ic 应用的 getActivityList 这个 Dubbo 接口进行压测的时候,在 RPS 接近 100 时 MRT 仅为 41ms,但在 RPS 接近 200 时 MRT 骤增至 1s 以上:




这种情况是很可怕的,因为系统的 Dubbo 工作线程都被拖住了,大流量下很容易造成雪崩进而导致系统崩溃。


二、问题分析

首先看下 Java 工作线程都在做什么,有很多工具可以分析 Java 线程快照。我们可以先使用 jstack 这个 JDK 自带工具,看到线程信息如下:



框出来的有两处,上面那处表明当前线程正在等待对一个 AladdinClassLoader 对象加锁,下面那处表明当前线程正在进行 Logback 打 error 日志行为。


我们可以再尝试使用另一个工具 Arthas,该工具运维大哥会提前在每一台服务器上安装。使用该 Arthas 工具看到线程信息如下:



框出来的上面那处表明,当前线程对一个 AladdinClassLoader 对象加了锁,然而它阻塞了其他 195 个线程,也就是说还有另外 195 个线程没有正常执行,都正等着对当前这个 AladdinClassLoader 对象加锁呢。框出来的下面那处跟 jstack 的一样,也是表明当前线程正在进行 Logback 打 error 日志行为。


最后我们再用 jmc 工具来确认一下顶级阻塞锁,这个 jmc 也是 JDK 自带的工具,不过人家可是有 GUI 的,用它看到的线程信息如下:



这里可以确认,顶级阻塞锁,也就是造成持续阻塞时间最长的对象,就是这个 AladdinClassLoader 对象导致的。此外除了被选中的 Logback 打 error 日志行为,我们还能看到堆栈顶部的 PackagingDataCalculator.loadClass 方法。其实回顾前面使用 jstack 和 Arthas 时看到的堆栈信息,也出现了这个 PackagingDataCalculator.loadClass 方法。也就是说,是 ic 打错误日志时调用到这个方法造成了阻塞锁,那我们来看看 ic 是怎么打错误日志的。


排查 ic 的应用日志,它确实是在频繁地打异常堆栈:



仔细看,这个异常日志的堆栈信息中列出了抛异常方法所属的 jar 包及 version 信息,而我们平时的错误日志是不带这些 jar 包和 version 信息的,根据之前出现的 PackagingDataCalculator.loadClass 方法,可以先把该方法作为嫌疑对象进行下一步分析了。


我们来看下为啥 Logback 打 error 日志时会出现 PackagingDataCalculator.loadClass 方法这个嫌疑对象。如果想进一步定位这个类是从哪个 jar 包加载的,可以通过 sc命令查看:



始作俑者出现了,是 logback-classic-1.1.2.jar,我们来看看这个版本关于 packageData 选项的相关配置:



它是默认打开的,也就是说,如果应用没有进行自定义的 packageData 配置,那么在发生异常打印堆栈信息时,就会在堆栈信息中包含 package info,这个 package info 即带有发生异常方法所属的 jar 包及 version 信息,虽然有助于识别问题,但是用这种姿势打异常日志的话就需要 loadClass,导致每次打异常日志都需要 AladdinClassLoader 类加载器去加载,而类加载器是独占的,所以存在有多个线程打异常日志的话会出现大量 AladdinClassLoader 阻塞锁的情况。还好本次是在线下环境发现了这个问题,否则如果线上环境因为种种原因打错误日志而又不幸遇上大流量的话,那就不是隐患而是血案了。


原因已定位,该找解决方案了。临时的解决方案是避免打错误日志,比如这次是线下环境某配置错误导致的打日志,那么我们把这个配置调整正确,对应的错误日志自然不会再出现,不过这种方法指标不治本,根本解决方案还是升级 logback-classic 至 1.2.3 版本,该版本的 packageData 选项默认就是关闭的:



这样升级之后,默认情况下打异常日志就不会出现 AladdinClassLoader 阻塞锁了。解决效果是,该接口在 ic 单实例下,从 RPS 不到 200 时 MRT 超过 1s 提升到 RPS 超过 500 时 MRT 仅为 55ms:




三、引申总结

打日志本身就是一项消耗系统资源的行为。就笔者遇到的打日志引发的性能问题,主要包括以下三类:


  1. 通用配置类,包括日志目的地、日志格式、日志级别、输出方式等方面,比如经典 log4j.properties 中的 %L 输出行号配置问题。其他感兴趣的小伙伴们可以自行调研,此处就不做细谈了;

  2. 打日志过于频繁。笔者遇到过一个问题,回归测试中发现某接口性能下降严重,分析发现是因为频繁打日志导致系统的 I/O 资源到达瓶颈,进一步定位发现是有这样一个设定:根据 Disconf 框架的要求,每条线程进来后会先检测本地是否有某个配置项,如果该配置项缺失的话就直接打一波警告日志,压测过程中进入对应应用的控制台会发现整个屏幕都在刷该警告日志……令人窒息,而 I/O 资源就是这么被耗尽的。后来该问题通过 Disconf 框架升级解决;

  3. 日志框架版本问题,例如本文提到的 Logback 引发大量锁竞争,其实就是老版本的问题,新版本是已经解决的。


总而言之,日志必不可少,但打日志的姿势不能出错,对于自己所用的日志框架一定要有足够的了解,当然最好是整个系统对于日志框架的版本、配置能有一个统一的规范。


2020 年 3 月 15 日 20:20535

评论

发布
暂无评论
发现更多内容

为什么你写的拦截器注入不了 Java bean?

Java旅途

Java spring Spring Boot 拦截器

vivo 调用链 Agent 原理及实践

vivo互联网技术

Java 架构 调用链

展现非凡领跑力,京东会展云斩获“十大云原生行业落地典范”奖项

京东科技开发者

云计算 AI 云原生

田哥:面试被问== 与equals 的区别,该怎么回答?

田维常

面试

第九周作业

熊桂平

极客大学架构师训练营

week5-根据当周学习情况,完成一篇学习总结

未来已来

《Elasticsearch服务器开发》.pdf

田维常

elasticsearch

第九周作业

经典计算机课程

Joseph295

Week_09 作业

golangboy

极客大学架构师训练营

5G革命:如何让「数据」实现最大性能?

VoltDB

数据库 数据分析 5G 工业互联网

记一次HEX和RGB互换算法的思考及应用

徐小夕

Java 面试 算法 大前端

还在用分库分表?看TiDB如何解决海量数据无感扩容难题

京东科技开发者

数据库 分布式数据库 #TiDB

鹿鼎记 · 韦小宝,丽春院、天地会、入皇宫等五个场景的恶搞版多线程锁学习!

小傅哥

Java 程序员 小傅哥 多线程

第九周课后练习

饭桶

第9周学习总结

饭桶

架构师训练营第九周学习笔记

一马行千里

学习 极客大学架构师训练营

【架构师训练营 1 期】第九周作业

诺乐

第五周作业

jizhi7

【薪火计划】04 - 心态和角色

brave heart

管理

极客大学 - 架构师训练营 第十周作业

9527

讲武德,你们要的高性能日志工具 Log4j2,来了

沉默王二

Java log4j

第九周总结

第九周作业

文智

极客大学架构师训练营

【架构师训练营 1 期】第九周学习总结

诺乐

week5-(2选1)

未来已来

Week_09 总结

golangboy

极客大学架构师训练营

脚手架 | 从零搭建满足权限校验等需求的前端命令行工具

梁龙先森

node.js 大前端

Week 9 作业02

Croesus

第五周总结

jizhi7

极客大学架构师训练营

第九周总结

熊桂平

一次 Logback 发现的隐患_文化 & 方法_子陌_InfoQ精选文章