点击围观!腾讯 TAPD 助力金融行业研发提效、敏捷转型最佳实践! 了解详情
写点什么

一次 Logback 发现的隐患

  • 2020-03-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-03-15 20:20823

评论

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

今天去 OPPO 面试,被问麻了

程序员啊叶

Java 编程 程序员 架构 java面试

手把手教你在 Vue3 中自定义指令

江南一点雨

从业务需求出发,开启IDC高效运维之路

鲸品堂

IDC

算法题每日一练---第9天:第几个幸运数字

知心宝贝

算法 前端 后端 7月月更

如何构建面向海量数据、高实时要求的企业级OLAP数据引擎?

字节跳动数据平台

数据仓库 云原生 OLAP Clickhouse

1000个字带你一次性搞懂JavaAgent技术,反正我是彻底服了

程序员啊叶

Java 编程 程序员 java面试 构架

不愧是阿里内部“千亿级并发系统架构设计笔记”面面俱到,太全了

冉然学Java

Java 高并发系统设计 技术栈 构架 高并发处理

阿里Java架构师面试高频300题:集合+JVM+Redis+并发+算法+框架等

程序员啊叶

一次性把Docker的概念、容器与虚拟机的区别、容器交付的优势讲清

程序员啊叶

Java 编程 程序员 架构 java面试

城市燃气安全再拉警钟,如何防患于未“燃”?

AIRIOT

物联网 天然气管理平台 燃气安全

7.依赖注入

MASA技术团队

后端

免费的低代码开发平台有哪些?

优秀

低代码 低代码开发平台

十字链表的存储结构

乔乔

7月月更

Beyond Compare 4 实现class文件对比【最新】

白粥

工具 Beyond Compare 文件对比

阿里架构师花近三个月时间整理出来的Java独家面试题(Java岗)

程序员啊叶

Java 编程 程序员 架构 java面试

柏睿数据加入阿里云PolarDB开源数据库社区

阿里云数据库开源

开源数据库 polarDB PolarDB-X 阿里云数据库 PolarDB for PostgreSQL

离谱!这本书居然将高深莫测的Java高并发知识讲解得浅显易懂

了不起的程序猿

Java Java并发 java程序员

HDD杭州站·HarmonyOS技术专家分享HUAWEI DevEco Studio特色功能

HarmonyOS开发者

HarmonyOS

BSC智能链合约模式系统开发详情

l8l259l3365

终极套娃 2.0 | 云原生交付的封装

尔达Erda

云计算 程序员 微服务 云原生 开发

优必选大型仿人服务机器人Walker X的核心技术突破

优必选科技

机器人

BATM面试Java岗:精选200+面试题及答案、6大重点规划和经验总结

程序员啊叶

Java 编程 程序员 架构 java面试

测试驱动开发(TDD)在线练功房 | 9月17日开课

ShineScrum捷行

敏捷 测试 TDD 代码 测试驱动开发

哪个led显示屏厂家更好

Dylan

LED显示屏 led显示屏厂家

墨天轮高分技术文档分享——数据库安全篇(共48个)

墨天轮

MySQL 数据库 oracle postgresql 数据库安全

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