一次對象過大引發的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 ，直接看內存的對象，能夠直接看到哪一個對象大，而後去代碼裏看這個對象是什麼，更直接方便。