42

频繁 FGC 的坑

 4 years ago
source link: https://mp.weixin.qq.com/s?__biz=MzI5OTM2NjkzMg%3D%3D&%3Bmid=2247483727&%3Bidx=1&%3Bsn=9c4e95b5808edfe780fc6e86cd1c0532&%3Bchksm=ec96ee34dbe167223b7690ddd6e19030d43707b874657773f61840d3660ad91736fdb05ac692&%3Btoken=407528224&%3Blang=zh_CN
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

问题重现

2020年新年伊始,排查一个线上GC问题。最直观的现象就是,1月2号线上一个Elasticsearch查询服务突然报警,几乎同时业务反馈某实时报表数据查询页面报错。同时看到后台日志java.lang.OutOfMemoryError: GCoverheadlimitexceeded,Eurake注册服务页面也已经没有检测到心跳,主动把此服务从注册中心列表服务剔除。情况紧急,此服务集群节点第一次出现这种情况,而且最近迭代没有进行版本更新,有点措手不及。当即采取的措施是优先保证业务使用,先恢复服务,将原本-Xms128m -Xmx512m的值调大到 -Xms1024m -Xmx1024m,重启服务恢复正常,后台日志正常,看似一切正常。

原因排查

业务使用一段时间后又开始报错,通过分析页面Network请求后端接口发现,接口相应出现了超时。有些ES的查询居然耗时高达49S,线程与线程之间出现了卡顿的情况,卡顿时间很多在15S左右。

猜想原因服务在生产运行半年以上ES有一定数据量级1.由于对ES做了大的聚会查询操作,是不是ES性能出现了问题,检查ES本身资源使用情况,和响应均正常?2.是否服务代码有资源未能及时释放。

措施

1.对ES关键查询做了日志打印,启动脚本添加了对GC日志的打印,命令如下:-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:/data/app/server/es-query-server/heapEs.log,调整了垃圾回收算法为并行执行-XX:ConcGCThreads 2.进一步扩大堆内存至 -Xms2048m -Xmx2048m。

3.将实时大报表查询做了临时下线处理,保留了两个轻量的列表查询。紧急发布服务,再次恢复正常。

问题定位与修复

第二天下午又出现报错问题,通过日志发现ES查询正常性能很好,排除ES相应导致的问题。那么问题就出现在自己服务代码本身的漏洞了,通过gcviewer分析了gc日志在某个时间段以后一直FGC,heap一直没有有效回收。之前的卡顿现象也可以解释了,fgc导致服务出现了Stop the world。

ArA3Yfy.jpg!web

通过jmap -dump:live,file=dump_075.bin 133333命令获取

dump文件.JDK自带jvisualvm监控工具分析dump文件.

EBJbeqM.jpg!web

注意到dump文件最大的对象是一个char[]数组,而且里面都是请求对象,通过使用场景判断,不应该出现那么多对象,所以进一步推断是否出现了死循环,测试环境恢复了之前的实时数据查询的大列表,发现页面的查询列表出现时间数据无法展示的情况,进一步看后台日志,针对报错信息,定位到了一个日期计算夸年夸季度出现了条件不匹配导致死循环。

总结

性能问题的调优,往往很复杂,准确定位问题考验开发人员对底层熟悉程度,也考验对排查问题的工具的灵活运用。不经意的错误,特别容易忽略,多积累,研究底层原理,有助于排查复杂问题。


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK