一次對象過大引起的gc性能問題的分析與定位


現象:一個接口在4C的機器上跑最大只有7TPS,CPU使用率就已經90%多。

定位:

1、  使用top命令查看CPU使用情況,找到進程號

 

 

2、  使用top -H -pid命令,查看進程信息,看到有四個進程CPU占用很高,加一起已經超過100%:

 

 

3、  查看具體的線程信息,先使用printf "%x\n" 6007,將線程ip轉換成16進制,結果為1777。

4、使用jstack pid |grep pid 命令,查看具體的線程信息,打印結果發現是GC線程,對四個占用CPU高的線程逐一分析,發現剛好都是下面的四個線程,至此,初步定位性能問題是有GC引起的。

 

 

5、  配置好java visualvm ,查看GC情況,結果如下,FULL GC不存在問題,不存在內存泄漏問題,把問題縮小到年輕代。

 

 

 

6、  使用jstat -gcutil pid命令,查看具體gc信息,發現Eden區大概5s會滿一次。

 

 

7、  查看gc日志,看到minor gc頻率跟高,關鍵是一次minor gc的時間很長,用戶耗時達到了500多ms,一般幾毫米,最高幾十毫秒正常,至此,基本把問題定位到是有minor gc,性能問題是由於minor gc太頻繁且耗時長造成的,初步猜測兩個原因,一是由於Eden區過小,另一個是由於對象過大,先從簡單的排查,加大Eden區看看:

 

 

8、查看JVM配置,關系到年輕代的信息基本上就是這幾個參數,發現Eden配置的確實小,而且垃圾的時間有點長,感覺開發配置的不太合理,所以去掉了后面三JVM參數,使用默認設置,重啟服務,使配置生效:

 

 

9、重啟完后,再次使用jstat命令,發現gc頻率降低了一半,但悲劇的是,gc的時間翻了一倍,TPS依然沒變,至此確實和JVM配置無關,需要關注對象大小。

 

 

 

10、查看線程信息,找到部署相關的項目,定位到具體的方法:

 

 

11、找到代碼,是一個select操作,返回的是select的結果:

 

 

12、繼續定位到具體的SQL:

 

 

13、查看這個SQL返回的結果,有三萬多條,至此基本確定問題所在,返回的list過大,導致Eden區很快就滿,而且回收緩慢,造成垃圾回收出現問題,同時GC占用大量CPU,導致CPU使用過高,最終就出現了看見的TPS只有7,CPU就滿了的問題。

 

 

總結:因為性能測試數據是我們自己造的,第一反應是我們造的數據有問題,再次確認后,發現我們數據沒問題,這個查詢的where條件傳的是課次信息,一個課次有幾萬學生屬於正常數據。正常情況下查這個表時會同時帶上學生id,這樣的結果不會超過十條,不會存在問題。但是開發為了方便,調用了之前的方法,結果就出現了這樣的問題。

反思:其實這個問題是可以通過慢查詢日志來定位的,由於我們這個項目用的是阿里雲的機器,運維不給配權限,我們只好用MONyog這個工具監控慢查詢,而且使用發現,不好用。除此之外,還有經驗問題,由於我們數據量不是特別大,百萬以下的表居多,按照以往的經驗,只要走到索引都不會出現慢SQL,所以很多SQL執行時我都會explain看一下。另一個原因是當時這個項目提交了太多接口,沒時間考慮太多,抱着先出個結果的態度進行的壓測,此次問題的定位也是在所有接口壓測完才去看的,當時看到是由於對象過大引起的性能問題,就想到了之前確實有一個SQL查到了很多數據,通過這次測試,以后在調腳本的時候,需要對SQL的結果進行關注了。

 

PS:其實有另一個方法定位問題,使用jmap -histo:live 10270 >2.txt ,直接看內存的對象,可以直接看到哪個對象大,然后去代碼里看這個對象是什么,更直接方便。


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM