通過 jstack 與 jmap 分析一次線上故障
一、發現問題
下面是線上機器的cpu使用率,可以看到從4月8日開始,隨著時間cpu使用率在逐步增高,最終使用率達到100%導致線上服務不可用,後面重啟了機器後恢復。
二、排查思路
簡單分析下可能出問題的地方,分為5個方向:
- 系統本身程式碼問題
- 內部下游系統的問題導致的雪崩效應
- 上游系統呼叫量突增
- http請求第三方的問題
- 機器本身的問題
三、開始排查
- 檢視日誌,沒有發現集中的錯誤日誌,初步排除程式碼邏輯處理錯誤。
- 首先聯絡了內部下游系統觀察了他們的監控,發現一起正常。可以排除下游系統故障對我們的影響。
- 檢視provider介面的呼叫量,對比7天沒有突增,排除業務方呼叫量的問題。
- 檢視tcp監控,TCP狀態正常,可以排除是http請求第三方超時帶來的問題。
- 檢視機器監控,6臺機器cpu都在上升,每個機器情況一樣。排除機器故障問題。
即通過上述方法沒有直接定位到問題。
四、解決方案
1.重啟了6臺中問題比較嚴重的5臺機器,先恢復業務。保留一臺現場,用來分析問題。
2.檢視當前的tomcat執行緒pid
3.檢視該pid下執行緒對應的系統佔用情況。top -Hp 384
4.發現pid 4430 4431 4432 4433 執行緒分別佔用了約40%的cpu
5.將這幾個pid轉為16進位制,分別為114e 114f 1150 1151
6.下載當前的java執行緒棧 sudo -u tomcat jstack -l 384>/1.txt
7.查詢5中對應的執行緒情況,發現都是gc執行緒導致的
8.dump java堆資料
sudo -u tomcat jmap -dump:live,format=b,file=/dump201612271310.dat 384
9.使用MAT載入堆檔案,可以看到javax.crypto.JceSecurity物件佔用了95%的記憶體空間,初步定位到問題。
MAT下載地址:http://www.eclipse.org/mat/
10.檢視類的引用樹,看到BouncyCastleProvider物件持有過多。即我們程式碼中對該物件的處理方式是錯誤的,定位到問題。
五、程式碼分析
我們程式碼中有一塊是這樣寫的
這是加解密的功能,每次執行加解密都會new一個BouncyCastleProvider物件,放倒Cipher.getInstance()方法中。
看下Cipher.getInstance()的實現,這是jdk的底層程式碼實現,追蹤到JceSecurity類中
verifyingProviders每次put後都會remove,verificationResults只會put,不會remove.
看到verificationResults是一個static的map,即屬於JceSecurity類的。
所以每次執行到加解密都會向這個map put一個物件,而這個map屬於類的維度,所以不會被GC回收。這就導致了大量的new的物件不被回收。
六、程式碼改進
將有問題的物件置為static,每個類持有一個,不會多次新建。
七、本文總結
遇到線上問題不要慌,首先確認排查問題的思路:
- 檢視日誌
- 檢視CPU情況
- 檢視TCP情況
- 檢視java執行緒,jstack
- 檢視java堆,jmap
- 通過MAT分析堆檔案,尋找無法被回收的物件