一次纠结的线上问题的排查

上周五接到一个任务, 说某个客户的一个线上java应用挂了, 现象就是cpu飙升, 几乎跑满, 无法响应请求。ssh连上去看了看应用日志, 有大量的java.lang.OutOfMemoryError: Java heap space 这种类型的日志, 看了看jvm启动参数, 给的比较小, 于是没放心上, 那就分配多一点jvm内存, 周末观察一下再说. 这里需要检讨一下, 调大内存的时候, 就应该加上-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=...., 这样内存溢出的时候就可以分析内存快照。

修改了参数后, 周六当天风平浪静。 但到了周日, 同样的现象又出现了, 照样是cpu飙升, 内存溢出, 于是开始怀疑应用是否被触发死循环。 因为已经计划周一上班就组织项目代码审查, 所以就将希望寄托在code review上了。 这里再次检讨下, 白白浪费了一次现场排查的机会, 而且这里重启过程中也没想着再次给jvm加上heap dump启动参数, 也没有当场将现场内存dump出来。

周一上午开始进行代码审查。 因为之前据同事说, 在没有加批量操作之前, 应用运行的很好, 加上批量操作之后, 应用就各种问题。 那好吧, 重点就放在批量操作这部分功能的实现上。 在审查过程中, 发现该应用的web部分代码很简单, 批量操作最多也只允许提交200条记录, 没有文件上传, 也没有可疑的由数据引起的死循环。 当天上午该应用也没有出现什么问题(后来发现可能是那段时间没有什么访问量)。 应用日志也没有给出什么有价值的线索(顺便吐槽下, 这个应用几乎没有什么log),于是思路陷入僵局.

周一下午的时候, 有同事尝试在测试环境中重现这个问题, 居然真的重现了。 大概就是在做批量操作的时候, 为了给用户实时的反馈, 前端发了大量的请求, 极端情况下, 一次提交可能有成千上万个独立的请求, 把应用卡死了。 前端同学立刻修改这段逻辑, 发上去了. 当时以为已经解决这个问题, 就没有再跟踪了。 再次检讨下, 事后回头应该能够想到, 如果只是某一时段有大量请求进来, 造成cpu和内存使用吃紧, 那么待这波请求过去, 机器cpu和内存应该可以自己回落才对, 但是实际现象却是cpu和内存使用一直居高不下, 但是当时没有深究下去了。

前端修改发上去后, 当天确实也没有再出现什么故障。

时间来到了周二中午, 应用突然又挂了, 现象和之前一样。 顿时有点崩溃, 因为客户在给一个很重要的领导做演示, 大家压力都比较大, 于是以保证演示过程为先, 先用重启大法对付过去。 但是这次长了心, 将heap dump以及gc log什么都配好加上去了, 监控也都配置好, 待应用再次挂掉就去现场排查。

周二晚上8点左右, 同事发消息说, 应用又挂了, 立刻上去将线程dump出来。 在看jstack输出的时候, 发现大量的线程卡死在去redis中拿session, 但是据以往的经验, 这个session的实现应该没问题的。 于是继续分析被block住的线程, 一条条看下来, 发现被block住的有个权限校验线程比较眼熟, 曾经在服务过另一个客户的时候处理过因为这个权限引起的内存泄露问题。 于是立刻让同事确认使用的权限包的版本号, 初步分析应该是掉进了同一个坑。 立刻让同事打了个patch发上去, 继续观察。

周三上午来公司, 将dump出来的内存用mat进行分析, 很快确认了这个内存泄露的问题, 首先看到堆内存中, 一个class的对象占用了3/4的内存, 如图示:

图中除了灰色的区块, 其余三个区块都是com.google.common.cache.LocalCache这个对象。 那么这个缓存对象中存了什么东西呢, 继续跟下去: 从上图中可以看出, 里面存放的是和鉴权相关的对象。 那么这些对象又是如何进去的呢? mat依然可以给我们提供线索:

此时可以基本认定, 正是昨晚修复的那个问题。 为了进一步验证我们的猜想, 同事在测试环境做了个验证, 首先发布有问题的那个版本, 起了10个线程,每个线程发1000次请求,没有任何业务逻辑,只是走一下 AclLoader,CPU直接满掉, 内存溢出, 问题重现。 然后发布修复的版本, 同样的测试, 一万次很快执行完了,CPU基本没起伏, 内存也很平稳, 至此已确诊: 因为每次请求都要经过鉴权, 而鉴权的interceptor有内存泄露, 而批量操作会发大量请求, 加速了内存泄露的过程, 造成频繁的full gc(查gc日志可以看到), 进而cpu飙升, 无法响应请求。

总结下这次问题排查的教训:

  1. 对问题要有追究到底的态度, 不能浅尝辄止。
  2. 要规范jvm参数, -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/log/gc/oom-${your-app-name}.hprof -Xloggc:/var/log/gc/gc-${your-app-name}.log 这部分参数一定要加上。
  3. 要珍惜故障现场的机会。
  4. 不要有先入为主的想法, 之前被同事误导, 以为是批量操作引起的故障, 造成排查方向错误, 要从事实出发。
  5. 要掌握常用的故障排查工具。

陈今梁

Read more posts by this author.

Subscribe to The Terminus Blog

Get the latest posts delivered right to your inbox.

or subscribe via RSS with Feedly!