写点什么

侦探剧场:堆内存神秘溢出事件

  • 2019-09-22
  • 本文字数:5775 字

    阅读完需:约 19 分钟

侦探剧场:堆内存神秘溢出事件

案发情景

小光是一名私家侦探,是小光侦探事务所的负责人。这天,他正在事务所中喝茶,突然接到警官 M 的电话,说接到线上总共三台机器,有一台机器报警,Java 堆内存占用超过 95%,无法正常得到服务器的响应。小光安排警官 M 保留好现场,急匆匆的赶往了现场…

猜测剖析

在前往现场的路上,小光思考了以下几个问题:


1.什么情况下会出现堆内存?


猜测可能是:


1)关键是分配大量内存,且无法被有效 GC。

瞬时并发数增大,且不能快速返回。这种情况需要一些线程的调用栈中,引用了大量的实例才可以占满堆内存。

2)程序中有 bug,导致死循环,在循环体中一直有分配内存的操作,且不是临时变量。


2.如何去定位问题?


1)最直接的方式,堆 dump,使用 MAT 或者 JVisualVm 来分析 dump 文件,找出是哪里占用了大量的堆内存。

2)当 1 无法执行时,可以使用 jdk 自带的一些工具,如 jmap 来分析内存。堆有可能是 dump 不出来的,因为线上堆大小是 8G,且同一台物理机有多个服务在运行,可能会影响其他服务。

3)内存作为主要分析对象,基于上述猜测 1,还需要使用 jstack 导出线程栈信息。

现场侦查

到达现场后,小光立即着手从现场找到有用的线索,分别在案发现场(问题 JVM)做了以下几件事:


  • 尝试进行整个案发现场的备份,即堆 dump,但被告知堆内存太大,无法进行 dump

  • 尝试使用 JMX 连接目标 JVM

  • 以失败告终,JVisualVM 长时间无法连接。(为什么无法连接成功,参考思考 1)

  • SSH 连接线上服务器,使用 JDK 自带工具尝试获取线索


1)ps -ef | grep java:找到目标 jvm 的 pid;

2)jmap -histo 目标 jvm 的 pid | head -20:查看 Class 与对应实例占用情况。但是以失败告终,提示: Attaching to process ID 3991, please wait…

Error attaching to process: sun.jvm.hotspot.debugger.DebuggerException: Can’t attach to the process;

3)尝试 jmap 无果,接着尝试 jstack:jstack 目标 jvm 的 pid:一样以失败告终,提示基本同上。


可能是当前用户无权限导致的。但是 jmx 应该不是,思考失败原因,参考归档 1


好在警官 M 在之前已经 jmap 出来一部分有效信息了,参考如下图:



但是,根据这个线索,只能定位到是 String 导致堆内存占满的,并没有其他有效的信息,而 String 对象是整个程序运行期间处处都有使用的,很难去直接定位到问题所在…


至此,现场勘查基本完成,但是并没有什么收获有效的可一次定位问题的信息。只能清理现场、重启服务,以防止影响后续服务。

监控信息

现场已经被清理了,但是现场还有一些监控信息。同时询问大致案发时间,是八点三十分左右,对部分内容取 8-9 点之间的信息,包括有以下内容:

应用日志

请求 M 警官协助,拉取了问题机当天的所有日志,一起另外一台没有问题的机器的所有日志,方便做差异分析。

GC 日志

在堆内存几乎占满时,GC 时间也变的很长,GC 日志有一定的参考价值。

监控日志

查看应用日志目录,发现有 dkimi 目录,看了下里面大致内容,发现是 dkimi 这个 agent 层的一些日志,也包括了一些有用信息,但是文件较大没有拉出来,有需要的时候自己去服务器上查看。

监控平台 matrix

monitor-matrix.zeus


线索分析

线索有以下内容:


  • 一张 jmap 图

  • 应用所有日志

  • GC 日志

  • dkimi 日志

  • 监控平台图表

  • 项目源码


直接从 1、3、4、5 中并不能直接分析出问题所在,但是可以根据这些信息得出一个非常有价值的线索:案发时间


1. 确定案发时间


由图 4(上图)可知,案发时间在 8:24 分左右,但不确定该监控平台的监控间隔,以及时间的准确性。通过检查 dkimi 日志,发现每隔 30s 会自动上报当前 jvm 状态 json 数据,状态中包括了 jvm:gc:ParNew:time,即 gc 时间。



取 22 分到 25 分的数据,大致定位了时间为 23-24 分钟之间。


2. 取案发时间区间监控日志



在拉取日志后,小光的智商突然下线…通过通读两台机器这一分钟的所有日志后,没有发现任何异常,所以也就没有得到任何结论…


在漫无目的的查看日志没有结果之后,开始怀疑起了日志区间,从此开始进入了误区…


3. 进入误区


先从日志中报 error 的地方入手,虽然 error 不会导致堆内存溢出,但是或许会有一些有用的信息。



发现大量的 Zookeeper 异常,正常机器上的日志上并没有这个异常。莫非是这里的问题?开始看这里的源码…结果并没有什么收获(这就是所谓的病急乱投医吧)。


在仔细思考后,小光觉得这个异常一定与堆内存泄漏相关,莫非是这个报错之前有其他操作导致了这个问题?


在查看该时间点附近相关日志后,发现了:



莫非是这个 sessionTimeout 导致了上面的 error, 超时时间 30s,那么是否有什么操作导致整个 zookeeper 连接阻塞了将近 30s,无法有效与 zookeeper 进行交互导致的?上面发现 session timed out 个 WARN 从 24:59 开始就有了,查看这段日志相关的源码。没有发现任何异常…那么从这个前面开始找…


突然小光注意到了日志的事件,在 8:24:59 之前,最近一条日志竟然是 8:24:37,中间二十多秒的日志去哪儿了?



缺少的二十多秒的日志,不可能是应用二十多秒没有日志输出,那么可以做到这种事情的,只有 JVM 的 Stop The World!查看 GC 日志,发现 GC 时间确实有二十多秒。


由此判断 ERROR 日志基本上可以确定为 GC 暂定导致的,又回归了线索的原点。


4. 结合监控尝试找出嫌疑人


既然无法从 ERROR 中得到嫌疑人的有效信息,那就回归最开始的猜想:不能快速返回的请求。


可以看到上面日志中,有个 WebFilter 日志,最后有耗费的时长,拉取这段时间所有 WebFilter 日志:



看了下时间,并没有发现较长的响应时间。莫非是非 Web 请求导致的问题?


通过结构化日志到数据库,分析是否有非 web 线程的日志,并与正常机器的日志线程做对比,观察线程不一致的日志。如何结构化请看归档 2:



其中 n1 是 log4j 的一个 token,n2 是一次 web 请求的生命周期中唯一的 id,使用 ThreadLocal 实现的。



查了下 151 的 workflowMessageListenerContainer 日志,并没有什么异常…


至此,通过查看 web 相关请求的响应时间,排除了 web 相关请求,通过两台机器对比线程,排除了非 web 相关请求。这样问题就死在这里了…


小光抬眼看了下时间,已经到了晚上,思路也渐渐的不清晰了,暂时休息,明天继续。


5. 第二天,根据不在场证明确定嫌疑人


第二天,小光早早的起了床,并立了一个 Flag,今天肯定能查到原因。因为昨晚他突然想到,当一个请求很耗时,甚至都不返回成为死循环时,可能连日志都没有。


同时,WebFilter 的日志打印,是在 finally 中,当请求无法返回时,当然不会打印日志,昨天确实是忽略了这个问题,走了个大的弯路。



可以看到,只有 finally 中打印了日志,请求之前并没有打印日志。


那么是否有 before 和 after 都打印了日志,只要分析一下有 before 但是没有 after 的请求,那么就可以定位到问题点了!


想到这里,小光立马兴奋了一起,打开代码,找寻其他切入点,果然找到了一个 WebInterceptor:




这里的 before 和 after 都打印了日志,且日志可以通过上面的 n2 即日志 id 来关联,没有日志 id 的时候可以使用请求地址来做对比。


结构化该请求相关的日志:



最终竟然真的找到了一个,而且有且只有一个:



查看时间点,也确实与案发时间对的上。为增加确定性,搜索该时间点之后线程 catalina-exec-19 的相关日志,发现在该时间点之后,就没有与此线程相关的日志了。由此,根据各线程的不在场证明可以基本确定嫌疑人为线程 catalina-exec-19。


查看该条日志,得到请求信息,内容为:


推理破案

上次讲到最终定位到了犯罪嫌疑人,但是犯罪嫌疑人也不是吃素的,证据又不足以定罪,小光继续进行分析推理:


1. 嫌疑人拒不认罪


嫌疑人 catalina-exec-19 表示,没有凶器与行凶方式,证据是不充足的,不能进行逮捕。小光说,既然已知嫌疑人,以及凶器的一点线索,找到凶器只是时间问题,接着便埋头开始推理。


凶器的线索在日志中已经提供:请求地址是http://xxx.com/apply。同时该线程日志 id 为 25216485580601。通过请求处理逻辑,以及调用过程中整个的日志信息,要想得到确切的问题点不会太难。


查看了代码才发现,上面想的还是有点简单了,这个接口的处理逻辑使用了模板模式,在模板模式中又嵌套了模板模式…与 25216485580601 相关的日志有 71 条,多为 DataPermissionInterceptor 类的日志,该类拦截所有 dao 层调用。


同时可知,在最后一条日志打印出来之后,该线程就没有再打印日志了,既没有报错也没有终止,那么大概率是死循环到某处了。


2. 找出凶器


通过请求参数"docType":[“103014”]找到对应的处理类,又通过层层模拟调用,结合日志,最终确定了问题发生在这段代码之中:



第 71 条日志是在 getNoworkDays 方法中打印的,而在 UserProcessUtil.partDocToDetails 后面又肯定会有新的日志产生,那么问题就发生在 getNoworkDays 方法体内和 UserProcessUtil.partDocToDetails 方法体内。(中间还遇到了日志与调用过程不一致的情况,后发现是因为 dao 层有 @Cacheable 注解,导致 dao 层逻辑没有经过 DataPermissionInterceptor 拦截器)


大致浏览了一下 getNoworkDays,发现其中并没有特殊的方法调用和循环,嫌疑对象指向了 UserProcessUtil.partDocToDetails 方法:



查看 transferDayAttenceDoc 方法,其中隐去简单调用方法:



看到这段代码时,突然一道光穿透了小光的两耳(此处配名侦探柯南发现真相图)。下面那个 while (true)非常可疑!


分析代码,循环终止条件是 end.equals(newend)。newend 则是 startDay 每次循环加一的结果,那么就是在某种情况下无法触发循环结束条件。


把请求中参数的"docStartTime":[“2018-01-08 08:22:50”],“docEndTime”:[“2018-01-10 08:22:56”]作为参数传入方法调用后,直接死循环了…结果是因为判断条件是拿全部 String 做的 equals。而 newend 是经过日期格式化的,只取日期那一部分的值,而 end 则不做任何变化,那么一个日期与一个日期时间,做字符串 equals 是肯定不会相等的,必然会死循环。


到这里,小光以为案件已破。但是仔细一想,这样的话岂不是所以进到这里的逻辑,都会直接触发死循环,这一点又解释不通。


查看调用该方法传入的参数,发现 start 和 end 其实是经过格式化的日期字符串:



继续分析 equals 条件,当传入参数 start 大于传入参数 end 时,就永远不会触发结束条件。什么情况下会 start 大于 end 呢。


此时,又一道光闪过小光的眼前!DateFormat 是线程不安全的,当多个线程使用同一个 DateFormat 时,有可能导致格式化后的结果不是自己想要的!看 DateUtil.formatDate 的代码:



果然与猜想的一样,此处使用了一个静态的 DEFAULT_DATE_FORMAT 来格式化日期,当多线程操作时,会导致 start 变为其他线程正在操作的时间。若此时间正好比 end 大,那么就会触发死循环。关于 DateFormat 线程不安全,参考归档 3.


再看死循环逻辑,往一个 list 中丢 String 对象,与最开始 jmap 结果也一致!


3. 还原作案手法


在多线程并发环境下,并发越高,上面的问题越容易重现。这也解释了之前到月底发生该问题的现象,月底考勤系统并发增加,问题出现概率增高。


通过构建多线程共用同一个 DateFormat,开启 500 个线程同时 Format 日期 2018.01.12,主线程调用两次 Format,分别 Format 2018.01.08 和 2018.01.10,之后作为参数传入 getBetweenDates,尝试几次后,果然重现:



4. 真相大白


至此,凶器已被找到,证据确凿,嫌疑人也已无法狡辩,只得乖乖俯首认罪。而小光也说出了那就他早就想说的话:真相永远只有一个!


后记


思考上面问题出现的原因:


Util 作者写了个方法,期望该方法的使用者,传入参数时,一定符合他的约定。


而使用者在使用该方法时,也都严格按照该约定进行传参。


但是中间杀出了个程咬金,多线程环境下结果的不确定性,最终导致了严重的堆内存泄漏问题。


案件已经侦破,那么各位针对上面的问题,有什么好的解决方法吗?当然直接换线程安全的日期格式化工具是非常有必要的,方法中做参数的必要性校验也是有必要的。


插曲


归档


1.JVisualVM 长时间无法连接、工具 Attach 失败的原因:


首先要了解一下这些工具执行的原理,为何会报出 Attach 失败?


这些工具的执行原理都是基于 Sun 公司的 Attach API。通过 com.sun.tools.attach.VirtualMachine 类,调用 attach(pid)方法,attach 到目标 JVM 上。


那么目标 JVM 又是怎么觉察到 attach 进来一个工具呢?通过线程 Signal Dispatcher 来实现。当 attach 时,会对目标线程发出一个信号量,该信号量交由该线程处理,信号量处理程序发现是 attach 信号,检测 Attach Listener 线程是否启动,如果没有启动则启动一个 Attach Listener 线程,attach 的具体操作交由 Attach Listener 执行。


attach 到目标虚拟机后,真正逻辑的执行是靠 Java Platform Debugger Architecture(JPDA)来进行的。


所有真正的执行还是要依赖目标 JVM 的,所以当目标 JVM 堆内存不足,且长时间 GC 占用 CPU 时间片时,Attach 是很难执行的。


要想获取更相信的信息,请参考:


1)Java 调试那点事


2)JPDA 体系概览


3)JVM Attach 机制实现


2.结构化日志方式


1)脚本语言:Python、Node.js


2)sed 命令


3)awk 命令


4)grep 命令


【参考脚本】


3.DateFormat 线程不安全的原因


说严禁点,其实是 SimpleDateFormat 的 parse 和 format 方法线程不安全。究其原因是因为其中使用了一个共享的 calendar 变量来进行日期与实时间的处理。在 format 时,先进行了一个 calendar 的 setTime 操作。这里就导致了多线程环境下,结果的不一致。


4.上面虽然引起了堆内存大量占用,但是并没有 OOM,思考原因


上面说了堆内存被大量占用,且有个死循环一直分配内存。奇怪的是却一直没有报出 OutOfMemmoryError。这里需要去了解一下抛出 OutOfMemmoryError 的时机,参考 JVM 源码分析之临门一脚的 OutOfMemoryError 完全解读。


个人猜测是因为,尝试分配内存时,发现内存不足,尝试进行 GC,一次 GC 时间达到了半分钟。GC 后,由于有其他线程可以释放一部分内存,又可以让死循环多分配点内存,最终持续进行分配与 GC,始终达不到触发 OOM 错误的时机,故没有抛出 OOM。

END

写在后面的话:


第一次尝试这种写作风格,欢迎各位提出意见与建议。如果觉得文章不错,欢迎关注和点赞哈,您的支持是我最大的动力。本地还有一些存货,有机会的话我会继续写这个系列,希望大家支持.


本文转载自公众号贝壳产品技术(ID:gh_9afeb423f390)。


原文链接:


https://mp.weixin.qq.com/s/fSrWF4PFZkvky7rkeCf46w


2019-09-22 21:59748

评论

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

2022 IoTDB Summit:东方国信王超《Apache IoTDB 在东方国信的商业化及应用》

Apache IoTDB

大数据 开源 时序数据库 IoTDB

Caffeine高性能本地缓存框架初探

FunTester

React等前端框架如何与小程序结合

Onegun

前端 前端框架 React Vue 3

数据测试实践:从一个bug开始的大数据引擎兼容性探索

京东科技开发者

大数据 bug修复 引擎 测试数据构造 企业号 3 月 PK 榜

精选案例 | 博睿数据30w+监测节点护航新华网、人民网两会重保工作

博睿数据

可观测性 智能运维 博睿数据 精选案例 主动式拨测

瓴羊Quick BI和Tableau哪个更适合复杂表格呢?

夏日星河

SSH和VNC的四个区别简单讲解

行云管家

SSH 行云管家

动转静两大升级!一键转静成功率领先,重点模型训练提速18%+

飞桨PaddlePaddle

人工智能 百度 飞桨 PaddlePaddle 框架解析

秒懂算法 | 搜索基础

TiAmo

DFS BFS 搜索算法

Vineyard 论文被 SIGMOD'2023 接收,助力计算引擎之间高效数据交换

阿里巴巴中间件

阿里云 计算引擎

等保联盟是什么机构?有什么用?

行云管家

等保 等级保护 等保联盟

用户分享 | 达梦第三方客户端DockQuery使用体会

BinTools图尔兹

数据库 用户体验 国产数据库工具

探索以小程序提升运维效率

Onegun

运维 小程序容器

中国特供版也残了!AMD 3GHz最强核显梦碎

科技之家

MMMBSC互助基金系统开发智能合约部署

薇電13242772558

智能合约 dapp

瓴羊Quick BI和Power BI哪个比较好呢?

巷子

ByteHouse实时导入技术演进

字节跳动数据平台

大数据 数据仓库 Clickhouse 数据仓库服务 企业号 3 月 PK 榜

瓴羊Quick BI:“3端4表4擎、3+NPlus”得到众多行业内部人士的认可!

对不起该用户已成仙‖

搬得进来,搬得出去!快来过一把数据迁移的“瘾”

OceanBase 数据库

数据库 oceanbase

技术沙龙 | 探索软件测试前沿技术及最佳实践,体验ChatGPT在测试领域中的应用

测试人

软件测试 沙龙 ChatGPT

旺链科技荣获科创中国数字经济技术创新峰会多个奖项

旺链科技

区块链+ 区块链、

技术沙龙 | 探索软件测试前沿技术及最佳实践,体验ChatGPT在测试领域中的应用

测吧(北京)科技有限公司

测试

性能平台数据提速之路

百度Geek说

大数据 百度 提效 企业号 3 月 PK 榜 性能平台

TypeScript 与 JavaScript:你应该知道的区别

京东科技开发者

JavaScript typescript 前端 后端 企业号 3 月 PK 榜

面试官:请说一下如何优化结构体的性能?

王中阳Go

Go golang 高效工作 学习方法 高效学习

OceanBase 生态产品:时序数据库CeresDB 正式发布 1.0 版本

OceanBase 数据库

数据库 oceanbase

DevOps 与平台工程:企业该如何选择?

SEAL安全

DevOps IdP 平台工程 企业号 3 月 PK 榜

淘宝 APP 网络架构演进与弱网破障实践

阿里技术

架构 网络

2022 IoTDB Summit:用友郭关飞《用友在 Apache IoTDB 应用与生态建设方面的探索与实践》

Apache IoTDB

大数据 开源 时序数据库 IoTDB

NFTScan:怎么使用 NFT API 开发一个 NFT 数据分析平台?

NFT Research

数据分析 API NFT

京东云RASP云原生安全免疫创新实践

京东科技开发者

Web 安全 漏洞 业务安全 企业号 3 月 PK 榜

侦探剧场:堆内存神秘溢出事件_文化 & 方法_王耀_InfoQ精选文章