一次 Logback 发现的隐患

Posted 2021-04-24 有赞coder

文 | 子陌 on 测试

一、现象描述

近期我们在线下环境进行了核心链路单接口的性能摸底，在使用我厂基于 Gatling 自研的 gatling-dubbo框架（详见 ）对 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 引发大量锁竞争，其实就是老版本的问题，新版本是已经解决的。
   

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

有赞测试组在持续招人中，大量岗位可选，包括工具开发、稳定性、实际业务等各个领域，有意向的同学可以发简历到 [e-mail]

相关阅读

-The End-

Vol.222

有赞技术团队

为 442 万商家，150 个行业，330 亿电商交易额

提供技术支持

微商城｜零售｜美业 | 教育

技术博客：tech.youzan.com

The bigger the dream, 

the more important the team