chenying | 3586 words
近期我们在线下环境进行了核心链路单接口的性能摸底,在使用我厂基于 Gatling 自研的 gatling-dubbo 框架(详见Dubbo 压测插件 2.0 —— 基于普通 API 调用)对 ic 应用的 getActivityList 这个 Dubbo 接口进行压测的时候,在 RPS 接近 100 时 MRT 仅为 41ms,但在 RPS 接近 200 时 MRT 骤增至 1s 以上:
首先看下 Java 工作线程都在做什么,有很多工具可以分析 Java 线程快照。我们可以先使用 jstack 这个 JDK 自带工具,看到线程信息如下:
我们可以再尝试使用另一个工具 Arthas,该工具运维大哥会提前在每一台服务器上安装。使用该 Arthas 工具看到线程信息如下:
最后我们再用 jmc 工具来确认一下顶级阻塞锁,这个 jmc 也是 JDK 自带的工具,不过人家可是有 GUI 的,用它看到的线程信息如下:
排查 ic 的应用日志,它确实是在频繁地打异常堆栈:
我们来看下为啥 Logback 打 error 日志时会出现 PackagingDataCalculator.loadClass 方法这个嫌疑对象。如果想进一步定位这个类是从哪个 jar 包加载的,可以通过sc
命令查看:
原因已定位,该找解决方案了。临时的解决方案是避免打错误日志,比如这次是线下环境某配置错误导致的打日志,那么我们把这个配置调整正确,对应的错误日志自然不会再出现,不过这种方法指标不治本,根本解决方案还是升级 logback-classic 至 1.2.3 版本,该版本的 packageData 选项默认就是关闭的:
打日志本身就是一项消耗系统资源的行为。就笔者遇到的打日志引发的性能问题,主要包括以下三类:
1) 通用配置类,包括日志目的地、日志格式、日志级别、输出方式等方面,比如经典 log4j.properties 中的%L
输出行号配置问题。其他感兴趣的小伙伴们可以自行调研,此处就不做细谈了;
2) 打日志过于频繁。笔者遇到过一个问题,回归测试中发现某接口性能下降严重,分析发现是因为频繁打日志导致系统的 I/O 资源到达瓶颈,进一步定位发现是有这样一个设定:根据 Disconf 框架的要求,每条线程进来后会先检测本地是否有某个配置项,如果该配置项缺失的话就直接打一波警告日志,压测过程中进入对应应用的控制台会发现整个屏幕都在刷该警告日志……令人窒息,而 I/O 资源就是这么被耗尽的。后来该问题通过 Disconf 框架升级解决;
3) 日志框架版本问题,例如本文提到的 Logback 引发大量锁竞争,其实就是老版本的问题,新版本是已经解决的。
总而言之,日志必不可少,但打日志的姿势不能出错,对于自己所用的日志框架一定要有足够的了解,当然最好是整个系统对于日志框架的版本、配置能有一个统一的规范。
有赞测试组在持续招人中,大量岗位可选,包括工具开发、稳定性、实际业务等各个领域,有意向的同学可以发简历到 chenying@youzan.com
欢迎关注我们的公众号