一次对象过大引发的gc性能问题的分析与定位

现象：一个接口在4C的机器上跑最大只有7TPS，CPU使用率就已经90%多。

定位：

一、  使用top命令查看CPU使用状况，找到进程号

 

 

二、  使用top -H -pid命令，查看进程信息，看到有四个进程CPU占用很高，加一块儿已经超过100%：

 

 

三、  查看具体的线程信息，先使用printf "%x\n" 6007，将线程ip转换成16进制，结果为1777。

四、使用jstack pid |grep pid 命令，查看具体的线程信息，打印结果发现是GC线程，对四个占用CPU高的线程逐一分析，发现恰好都是下面的四个线程，至此，初步定位性能问题是有GC引发的。

 

 

五、  配置好java visualvm ，查看GC状况，结果以下，FULL GC不存在问题，不存在内存泄漏问题，把问题缩小到年轻代。

 

 

 

六、  使用jstat -gcutil pid命令，查看具体gc信息，发现Eden区大概5s会满一次。

 

 

七、  查看gc日志，看到minor gc频率跟高，关键是一次minor gc的时间很长，用户耗时达到了500多ms，通常几毫米，最高几十毫秒正常，至此，基本把问题定位到是有minor gc，性能问题是因为minor gc太频繁且耗时长形成的，初步猜想两个缘由，一是因为Eden区太小，另外一个是因为对象过大，先从简单的排查，加大Eden区看看：

 

 

八、查看JVM配置，关系到年轻代的信息基本上就是这几个参数，发现Eden配置的确实小，并且垃圾的时间有点长，感受开发配置的不太合理，因此去掉了后面三JVM参数，使用默认设置，重启服务，使配置生效：

 

 

九、重启完后，再次使用jstat命令，发现gc频率下降了一半，但悲剧的是，gc的时间翻了一倍，TPS依然没变，至此确实和JVM配置无关，须要关注对象大小。

 

 

 

十、查看线程信息，找到部署相关的项目，定位到具体的方法：

 

 

十一、找到代码，是一个select操做，返回的是select的结果：

 

 

十二、继续定位到具体的SQL：

 

 

1三、查看这个SQL返回的结果，有三万多条，至此基本肯定问题所在，返回的list过大，致使Eden区很快就满，并且回收缓慢，形成垃圾回收出现问题，同时GC占用大量CPU，致使CPU使用太高，最终就出现了看见的TPS只有7，CPU就满了的问题。

 

 

总结：由于性能测试数据是咱们本身造的，第一反应是咱们造的数据有问题，再次确认后，发现咱们数据没问题，这个查询的where条件传的是课次信息，一个课次有几万学生属于正常数据。正常状况下查这个表时会同时带上学生id，这样的结果不会超过十条，不会存在问题。可是开发为了方便，调用了以前的方法，结果就出现了这样的问题。

反思：其实这个问题是能够经过慢查询日志来定位的，因为咱们这个项目用的是阿里云的机器，运维不给配权限，咱们只好用MONyog这个工具监控慢查询，并且使用发现，很差用。除此以外，还有经验问题，因为咱们数据量不是特别大，百万如下的表居多，按照以往的经验，只要走到索引都不会出现慢SQL，因此不少SQL执行时我都会explain看一下。另外一个缘由是当时这个项目提交了太多接口，没时间考虑太多，抱着先出个结果的态度进行的压测，这次问题的定位也是在全部接口压测完才去看的，当时看到是因为对象过大引发的性能问题，就想到了以前确实有一个SQL查到了不少数据，经过此次测试，之后在调脚本的时候，须要对SQL的结果进行关注了。

 

PS：其实有另外一个方法定位问题，使用jmap -histo:live 10270 >2.txt ，直接看内存的对象，能够直接看到哪一个对象大，而后去代码里看这个对象是什么，更直接方便。