三十万次Full GC

症状

今天测试同学反馈API耗时很长,超过3秒的比例很高。 查看日志发现,小部分请求耗时比较大,约2秒左右,但是比例不高,与反馈比例有点不一致。后来发现是有一台服务器停止工作了(进程假死),对请求没有响应,也没有拒绝,重启后问题缓解。 因为第一次出现,没有引起重视。但是过了几个小时候,相同的问题又出现在另外一台服务器上,狗日的墨菲定律

思路

查日志

  • 先检查日志,找出耗时很长的请求,看看耗时都耗费在哪些地方:但是没有很好的结果,反而发现一些很奇怪的事情,有的相邻的两条日志之间的时间差有1秒多,但是这1秒没看出来服务器做了任何事情(没有思路,而且是第一次遇到,先放一边去了)

查进程状态

  • 后来发现有服务器假死,不响应任何请求,就先top查看CPU,内存等服务器信息,发现都还算正常,甚至还在慢慢输出一些日志信息(也是相当莫名其妙啊)
  • 为了不影响用户,先在负载均衡设备上去掉假死的服务器,保留现场
  • jstack PID: 程序不响应,提醒使用-F参数,但是还是报错(错误不记得了,不过记得是JVM内部的异常)
  • jmap导出内存映射: 程序也不响应,使用-F参数,还是报错
  • 这个时候,真的有点不知所措了,各种工具都用不上啊。不过top命令还是看出,进程确实是正常的,CPU的占用率也有变化。

意外发现

本来应该早就该发现的

  • 再去看日志,发现业务日志基本停止了,但是gc日志一直在刷新,而且都是Full GC,频率很快,差不多2秒一次(一次时间约1.5秒)。仔细分析日志可以看出,Full GC后回收的内存特别少
  • jstat -gcutil PID: 发现Full GC高达三十多万次
  • 这个时候我们基本确定是因为系统内存占用量太大,导致一直Full GC,又因为回收的内存很少,所以马上又需要再次Full GC,JVM根本没有时间去响应业务请求
  • 而且我们也在其他几台服务器上也发现了同样的问题,只是那些服务器的内存还没有这么满,JVM还有部分时间可以用来响应用户请求

内存泄漏?

接下来就要定位占用内存的元凶了

  • 在其他服务器上使用jmap导出内存映像,使用jdk自带的jvmvisual分析,通过类的排序看到一些类的实例数特别多。但是跟算法同学计算了一下,基本还算正常。然后通过占用内存数排序,发现double[]占用了63%的内存,我们怀疑可能是算法用到了double[],但是没有及时释放,存在内存泄漏(感觉很明显了)。

谁偷走了内存?

  • 元凶找到了,但是要找到使用者。因为jvmvisual看不出来对象之间的引用关系,我们也很难判断是哪些对象引用了double[]。我们就在代码中搜索double[],但是分析了好久,也没有看出内存泄漏的影子。
  • (不开心)再次不知所措,虽然我们肯定是内存泄露,但却没有好的办法定位源头
  • 这个时候,我们想到了jhat和大名鼎鼎的mat(Eclipse Memory Analyzer ),最后使用mat来执行内存分析(因为直到mat分析完毕,jhat都还没打开内存文件)
  • mat之前使用不太熟悉,这次就摸索着打开各种图表查看,最后找到了对象引用关系。发现存在34个特别大的double[],再跟算法同学求证,就是存在一个特别大的模型,而且每个应用都有独立的模型。每个模型占用内存大约100M。
  • 至此,问题已经完全定位,元凶也已经找到

原因

  • 内存占用太大,导致内存不足,Full GC过于频繁,JVM无法影响请求

办法

  • 减小模型大小,不同算法实例共享模型

结果

  • 内存占用降下来了,Full GC也恢复到正常的个位数

总结

  • (先收集信息,再定位问题)事后看来,问题其实还是有很多表现,只是没有第一时间发现,而是着急去快速定位问题了。如果一开始就使用了jstat -gcutil PID查看的话,就可以很快的地发现Full GC的问题
  • 知道是Full GC导致响应时长很慢,就明白了为什么相邻的两行日志的时间会差那么多了(因为JVM Stop the World了)
  • 计算机真没有什么莫名其妙,只是我们还没找到那一个点
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 227,572评论 6 531
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 98,071评论 3 414
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 175,409评论 0 373
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 62,569评论 1 307
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 71,360评论 6 404
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 54,895评论 1 321
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 42,979评论 3 440
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 42,123评论 0 286
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 48,643评论 1 333
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 40,559评论 3 354
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 42,742评论 1 369
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 38,250评论 5 356
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 43,981评论 3 346
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 34,363评论 0 25
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 35,622评论 1 280
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 51,354评论 3 390
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 47,707评论 2 370

推荐阅读更多精彩内容