一次排查事故纪录
服务器大范围报读超时,排查记录:
8月13日:
1周一晚上根据opjmap的内存,发现老年代和年轻代都是百分之九十九。因为老年代满后会引起fullgc,检查gc日志证实频繁fullgc,但是fullgc几乎没有效果,导致jvm连续fullgc,所有线程等待,引起读超时现象。
2op给出的jmaphisto里面有大量keywordtype对象,怀疑有大量这种对象被引用没有释放
3根据事故点的dump日志发现有大量log4j在争夺root时被blocked,同事给出优化建议,将lo4j的子日记不打到catalina.out里面。
8月14日:
3同事排查代码未发现keywordtype有被map、list引用的情况
4替换log4j,子log不打到catalina.out里面,并且将earth日志隔离出去,business层增加buffer,上线。解决log4j瓶颈问题,但是仍然大量读超时,并且发现dump出来的线程快照里面基本上都是runnable的线程,此时仍然频繁fullgc,且fullgc未果,大家怀疑heap里面到底有什么东西。另外发现了使用log4j的buffer的一个问题,发生业务日志丢失的情况,具体问题还没有排查出来结果。
5要求op准备jmap事故现场的heap.bin来排查
8月15日:
6早上有两台服务器重启后丢失业务日志,有一台服务器重启失败,十个小时左右无流量。
7检查事故现场的heap.bin,这东西很大时,别直接jhat,开一个两倍或者三倍的内存在jhat-J-mx14gheap.bin。
8检查heap.bin,同事发现大量的keywordtype最终没有被引用,而且这些keywordtype里面的内容大致相同。排查出这些keywordtype属于同一用户。检查访问日志,发现这个用户发送了一些大批量的查询请求,发送内容又大部分重复,发送的时间点和fullgc开始的时间点吻合。怀疑受到恶意攻击或者客户程序bug引起。
9根据以上排查,让pm联系这个客户,得知这个客户在进行线上试验。
10和qa、op协作,紧急上线。完成修复