设为首页 加入收藏

TOP

侦探剧场:堆内存神秘溢出事件(一)
2018-03-06 09:03:08 】 浏览:189
Tags:侦探 剧场 内存 神秘 溢出 事件

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

案发

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

路上

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

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

    猜测可能是:

    • 瞬时并发数增大,且不能快速返回。这种情况需要一些线程的调用栈中,引用了大量的实例才可以占满堆内存。
    • 程序中有bug,导致死循环,在循环体中一直有分配内存的操作,且不是临时变量。

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

  2. 如何去定位问题
    • 最直接的方式,堆dump,使用MAT或者JVisualVm来分析dump文件,找出是哪里占用了大量的堆内存。
    • 当1无法执行时,可以使用jdk自带的一些工具,如jmap来分析内存。堆有可能是dump不出来的,因为线上堆大小是8G,且同一台物理机有多个服务在运行,可能会影响其他服务。
    • 内存作为主要分析对象,基于上述猜测1,还需要使用jstack导出线程栈信息。

现场

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

  1. 尝试进行整个案发现场的备份,即堆dump,但被告知堆内存太大,无法进行dump
  2. 尝试使用JMX连接目标JVM

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

  3. SSH连接线上服务器,使用JDK自带工具尝试获取线索
    • ps -ef | grep java:找到目标jvm的pid
    • 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
    • 尝试jmap无果,接着尝试jstack:jstack 目标jvm的pid:一样以失败告终,提示基本同上

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

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

    jmap情况

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

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

现场监控信息

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

  1. 应用日志

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

  2. GC日志

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

  3. 监控日志

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

  4. 监控平台matrix

    monitor-matrix.zeus 监控平台图

线索分析

线索有以下内容:

  1. 一张jmap图
  2. 应用所有日志
  3. GC日志
  4. dkimi日志
  5. 监控平台图表
  6. 项目源码

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

1. 确定案发时间

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

cat dkimi-agent.2018-01-10.log | grep '2018-01-10 08:2[2-5]:.*HeartB.*jvm:gc:ParNew:time'

2018-01-10 08:22:26 - jvm:gc:ParNew:time:2107
2018-01-10 08:22:56 - jvm:gc:ParNew:time:2107
2018-01-10 08:23:26 - jvm:gc:ParNew:time:2128
2018-01-10 08:23:56 - jvm:gc:ParNew:time:9462
2018-01-10 08:24:28 - jvm:gc:ParNew:time:19735
2018-01-10 08:24:59 - jvm:gc:ParNew:time:21332
2018-01-10 08:25:44 - jvm:gc:ParNew:time:22556

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

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

cat all_is_well.log | grep '20180110-08:2[3-4]'

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

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

3. 进入误区

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

cat all_is_well.log | grep '20180110-08:2.*ERROR'
20180110-08:25:44.743 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@68c3c43c]
20180110-08:25:44.745 [ZkClient-EventThread-40] ERROR org.I0Itec.zkclient.ZkEventThread [44263889_40_754] [] - Error handling event ZkEvent[Children of /fake changed sent to com.alibaba.dubbo.remoting.zookeeper.zkclient.ZkclientZookeeperClient$2@6cfc4dfc]
20180110-08:25:44.746 [ZkClient-EventThread-40] ERROR org.I0
编程开发网
首页 上一页 1 2 3 4 5 6 下一页 尾页 1/6/6
】【打印繁体】【投稿】【收藏】 【推荐】【举报】【评论】 【关闭】 【返回顶部
上一篇如何编写相对标准的后端项目(二.. 下一篇从 Java9 共享内存加载 modules ..

评论

帐  号: 密码: (新用户注册)
验 证 码:
表  情:
内  容:

最新文章

热门文章

C 语言

C++基础

windows编程基础

linux编程基础

C/C++面试题目