记录一次Full GC分析的案例
问题描述： 线上一个读取kafka的应用经常运行一段时间就读取不到消息的问题，头两次单纯的以为是kafka和网络环境问题（看来以后出错要第一时间怀疑自己的代码^_^），重启两次之后又运行了一天就出现读取不到消息的问题。仔细查询日志，发现某个时间点消费者线程正常退出（没有抛出异常），最后一次读取到消息的时间
2017-05-24 16:49:23,029 INFO [eventbus-consumer-0] [consumer] [poll 2 messages]
到kafka的日志中查询对应时间点的日志：
[2017-05-24 16:49:54,494] INFO [GroupCoordinator 0]: Preparing to restabilize group device with old generation 2 (kafka.coordinator.GroupCoordinator)
[2017-05-24 16:49:54,495] INFO [GroupCoordinator 0]: Group device generation 2 is dead and removed (kafka.coordinator.GroupCoordinator)
[2017-05-24 16:51:09,426] INFO Scheduling log segment 0 for log DeviceChangeEvent_1999-0 for deletion. (kafka.log.Log)
发现在最后一次读取消息的之后30s，kafka没有收到消费者的心跳，直接将消费者移除。（session.timeout.ms为默认设置30s）
仔细查看自己的代码，消费者线程并没有任何退出机制:使用的while(true)死循环，正在一筹莫展，怀疑kafka的问题的时候，突然想到会不会是GC引起的卡顿，通过jstat查询GC状况，果然发现应用一直在做FULL GC的操作：
[root~]# jstat -gc 5618 5s
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
24576.0 25088.0 0.0 0.0 103424.0 103424.0 153600.0 153517.1 28032.0 26927.0 3456.0 3171.7 87 1.602 37 21.362 22.964
24576.0 25088.0 0.0 0.0 103424.0 87399.5 153600.0 153533.8 28288.0 26961.2 3456.0 3178.8 87 1.602 43 25.783 27.385
24576.0 25088.0 0.0 0.0 103424.0 103424.0 153600.0 153395.3 28288.0 26965.6 3456.0 3178.8 87 1.602 50 29.767 31.369
24576.0 25088.0 0.0 0.0 103424.0 85115.1 153600.0 153254.2 28288.0 26969.9 3456.0 3178.8 87 1.602 57 34.131 35.733
24576.0 25088.0 0.0 0.0 103424.0 103424.0 153600.0 153134.8 28288.0 26997.7 3456.0 3179.3 87 1.602 65 38.314 39.916
24576.0 25088.0 0.0 0.0 103424.0 103424.0 153600.0 153542.9 28288.0 27004.5 3456.0 3179.3 87 1.602 73 42.594 44.196
24576.0 25088.0 0.0 0.0 103424.0 103424.0 153600.0 153445.9 28288.0 26967.8 3456.0 3173.8 87 1.602 79 46.965 48.567
24576.0 25088.0 0.0 0.0 103424.0 103424.0 153600.0 153374.5 28288.0 26965.1 3456.0 3173.2 87 1.602 82 48.936 50.538
24576.0 25088.0 0.0 0.0 103424.0 103424.0 153600.0 153374.5 28288.0 26965.1 3456.0 3173.2 87 1.602 82 48.936 50.538
通过jmap -heap命令查询堆内存，发现堆内存已经被耗尽，FULL GC也无法回收足够的内存，所以应用一直尝试FULL GC
[root~]# jmap -heap 5618
Attaching to process ID 5618, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.20-b23
using thread-local object allocation.
Parallel GC with 4 thread(s)
Heap Configuration:
MinHeapFreeRatio = 0
MaxHeapFreeRatio = 100
MaxHeapSize = 314572800 (300.0MB)
NewSize = 157286400 (150.0MB)
MaxNewSize = 157286400 (150.0MB)
OldSize = 157286400 (150.0MB)
NewRatio = 1
SurvivorRatio = 8
MetaspaceSize = 21807104 (20.796875MB)
CompressedClassSpaceSize = 1073741824 (1024.0MB)
MaxMetaspaceSize = 17592186044415 MB
G1HeapRegionSize = 0 (0.0MB)
Heap Usage:
PS Young Generation
Eden Space:
capacity = 105906176 (101.0MB)
used = 105906176 (101.0MB)
free = 0 (0.0MB)
100.0% used
From Space:
capacity = 25690112 (24.5MB)
used = 0 (0.0MB)
free = 25690112 (24.5MB)
0.0% used
To Space:
capacity = 25165824 (24.0MB)
used = 0 (0.0MB)
free = 25165824 (24.0MB)
0.0% used
PS Old Generation
capacity = 157286400 (150.0MB)
used = 157179888 (149.89842224121094MB)
free = 106512 (0.1015777587890625MB)
99.93228149414062% used
根据前面的分析，我们已经知道了是代码中有地方没有合理的释放对象的引用，
通过jmap -dump命令生成堆dump，用压缩工具压缩之后下载到本地（不压缩的话下载很慢，500M的文件压缩完之后只有80M不到）
用jvisualvm工具打开dump文件
猜测是有一个map长期持有了对象引用，由于我的代码里很多参数，变量都是map，所以很难看出问题出现在哪个对象里，所以我改为使用mat（Eclipse Memory Analyzer）来分析
用mat打开dump文件后，在Leak Suspects视图里我们清楚的看到了一个可疑对象占用了243M的内存
在下面的可以可疑问题描述里，我们知道是一个Map对象长期持有了对象
The memory is accumulated in one instance of "java.util.TreeMap$Entry" loaded by "<system class loader>".
点击details，查看详细报告,我们可以看到整个引用链
通过上面的引用链，判断是KafkaEventConsumer引发的问题，点击这个对象，选择list objects -> with outgoing reference，可以看到这个对象的内部详情
通过上面的图，我们最终找到了罪魁祸首KafkaEventConsumer里的process变量（这是一个map：Map<TopicPartition, TreeSet<RecordFuture>> process = new HashMap<>()）里面key=DeviceControlEvent_1_3对应的TreeSet长期持有了对象未释放。
最终查找代码和环境，是因为有一个同事用了一个模拟程序以1ms一条的速度发送某个特定事件，超出了应用的处理速度，导致队列挤压.对消息的消费增加了限流、黑名单的逻辑后在没有出现过FULL GC
