一次 Logback 发现的隐患

文 | 子陌 on 测试

一、现象描述

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

二、问题分析

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

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

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

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

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

三、引申总结

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

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

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

相关阅读

1. Mock服务插件在接口测试中的设计与应用

2. 有赞前端质量保障体系

3. Dubbo压测插件的实现——基于Gatling

4. 有赞全链路压测实战

5. 前端精准测试探索：覆盖率实时统计工具

6. K8S 在有赞 PaaS 测试环境中的实践

-The End-

本公众号长期关注于数据库技术以及性能优化，故障案例分析，数据库运维技术知识分享，个人成长和自我管理等主题，欢迎扫码关注。