记一次频繁生产频繁full-gc事件

背景

线上一个基础服务收到频繁 full-gc 的告警，每小时平均两次的 full-gc，一次平均耗时 1 s。

从监控中发现确实存在频繁 full-gc 的情况，且有时还伴随机器重启，大概隔3天老年代的内存占用会达到一个峰值（3 G）。

相关的配置：

• 机器配置 2C/4G
• JDK8，用的是 G1 垃圾回收器
• 堆内存 -Xmx3296m，3G 左右

临时解决方案

• 重启服务，并扩容机器，新增两台机器，内存从 4G 扩充到 8G
• 保留一台发生问题的机器，把它拉出并及时进行 head dump，当时它的堆内存占用已达到一个较高的峰值

问题分析

head dump

通过 MAT 分析 head dump 文件，发现 SearchLogHandler 类中存在一个超大的 HashMap 对象，大约 500M 左右。

基本可以定位这个对象就是问题的根源所在。

代码分析

SearchLogHandler 的核心作用是：消费产品搜索相关请求的日志消息，存储为结构化的数据，为后续数据分析提供基础。

整个处理过程如下：

• 消费请求日志，将其缓存在 HashMap 中（按照请求类型+线程id维度进行存储），HashMap 定义为静态变量
• 如果缓存中的日志数量达到处理阈值，则取出批量处理并进行持久化操作
• 处理成功后会将缓存中对应的日志记录移除

结合当时系统的日志存在很多异常报错，如 NumberFormatException 异常，最终找到问题的核心原因：
在日志处理的过程中存在异常场景，没有处理异常，导致后续的日志记录移除操作被打断，对应的日志记录一直积压在缓存中，无法得到释放。

发生异常的原因：在处理日志的过程中，会将字符串类型的 cityId 转成 int 类型，在某些场景下，请求中的 cityId 为空，导致调用 Integer.parseInt() 时抛出了 NumberFormatException 异常。

内存泄漏

用来做缓存的 HashMap 定义为 SearchLogHandler 类的静态变量，因为主动释放数据的操作被异常打断了，进而导致 HashMap 中的数据越来越大，且这些对象无法被正常回收，出现了内存泄漏的问题。

最终的结果就是老年代的内存占用越来越大（回收不掉的对象都晋升到了老年代），而老年代最后也没有足够的空间来存放即将晋升的对象，导致频繁 full-gc，机器重启。

解决方案

核心是保证每条日志请求的处理完成之后都能被正常释放，因此在处理过程中加入了异常处理流程，即使处理过程中发生了异常，也不影响对象的正常释放。

通过这个生产事件，也提醒我们在编码的过程中需要注意对于一些敏感资源的释放操作，不能因为程序异常而被打断，是一个老生常谈的问题了哈哈，也许只有真正在上面栽跟头才能铭记于心吧。