一次 Logback 发现的隐患

2020 年 3 月 15 日

一次 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:20184

评论

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

英特尔中国研究院宋继强:芯片、系统、软件成为异构计算的三层级

飞天鱼2017

四十个鹏城春夏,一场数字繁花

脑极体

OAM 深入解读:如何基于 OAM Runtime 编写一个扩展 Trait?

钱王骞

云原生 k8s OAM

脑洞:基于Enterprise Continuum证明DDD用于构建汽车的可行性

Winfield

企业架构 领域驱动设计 DDD 架构演进

关于中台,可能都是正确的废话

fino星君

中台 业务中台

第7周作业

文古

2. 妈呀,Jackson原来是这样写JSON的

YourBatman

Java json Jackson Fastjson

敏捷软件开发宣言及十二原则

Young先生

敏捷开发

腾讯面试题: 百度搜索为什么那么快?

小松漫步

面试

IO系列——用户空间与内核空间

Java联盟

io 零拷贝 用户空间 内核空间 zero copy

CDN百科第七期 | 关于CDN的原理、术语和应用场景那些事

巨侠说

CDN

Redis系列(六):你说要看Redis线程模型?安排

z小赵

redis 高并发

架构师训练营第八周笔记

Melo

架构师训练营第八周学习总结

张明森

LeetCode题解:1. 两数之和,JavaScript,双循环暴力解法,详细注释

Lee Chen

LeetCode 前端进阶训练营

22种超全用户触点采集,易观方舟SDK又更新了

易观大数据

推荐 16 款 IDEA 插件,让你的开发速度飞起来!

Bruce Duan

idea插件

【区块链+通证经济】从量变到质变区块链发展的下一阶段是什么?

CECBC区块链专委会

数字货币 防篡改 通证

最高法主张加强数字货币产权保护有法可依

CECBC区块链专委会

数字货币 法偿货币 中国人民银行 虚拟财产

如何识别刷屏文章中的伪科学

Lee Chen

随笔杂谈 前端进阶训练营

LeetCode001-两数之和-easy

书旅

算法 LeetCode 数据结构与算法

报志愿|想学区块链,要上什么大学?报什么专业?

CECBC区块链专委会

高考 报考志愿 区块链专业 高校学院

信创舆情一线--两部门发文加强对数字货币等新型权益的保护

统小信uos

性能优化

独孤魂

Demo 示例:如何原生的在 K8s 上运行 Flink?

Apache Flink

flink

Vue 学习笔记-2

多选参数

vue.js Vue vuejs

除了技术,加密货币开发者更应关注可使用性

CECBC区块链专委会

加密货币 用户为本 可使用性 容错机制

高能预警!Apache Flink Meetup · 上海站返场啦

Apache Flink

flink

JVM系列之:对象的锁状态和同步

程序那些事

JVM GC 同步

Vue 学习笔记-3

多选参数

vue.js Vue vuejs

胡继晔:发挥我国优势把依法治网落实到区块链管理中

CECBC区块链专委会

CECBC 胡继晔 依法治网 数字货币监管

一次 Logback 发现的隐患-InfoQ