壞代碼導致的性能問題大賞:CPU占用飆到了900%!


讀過《重構 - 改善既有代碼的設計》一書的同學們應該都很了解“代碼的壞味道”。當然確定什么是代碼“壞味道”是主觀的,它會隨語言、開發人員和開發方法的不同而不同。在工作當中,很多時候都是在維護之前的項目和在此基礎上增加一些新功能,為了能讓項目代碼易於理解和維護,要時刻注意代碼中的“壞味道”,當發現代碼如果有壞味道了,要及時去重構它使其變成優秀的整潔的代碼。今天我們要聊的是“壞味道的代碼”給系統性能帶來的影響,筆者會給大家展示幾個案例,希望能對大家有所啟發和幫助。
20211031161709.jpg

FGC實戰:壞代碼導致服務頻繁FGC無響應問題分析

問題

網絡問題?

晚上七點多開始,我就開始不停地收到報警郵件,郵件顯示探測的幾個接口有超時情況。多數執行棧都在:

java.io.BufferedReader.readLine(BufferedReader.java:371)
java.io.BufferedReader.readLine(BufferReader.java:389)
java_io_BufferedReader$readLine.call(Unknown Source)
com.domain.detect.http.HttpClient.getResponse(HttpClient.groovy:122)
com.domain.detect.http.HttpClient.this$2$getResponse(HttpClient.groovy)

這個線程棧的報錯我見得多了,我們設置的 HTTP DNS 超時是 1s, connect 超時是 2s, read 超時是 3s,這種報錯都是探測服務正常發送了 HTTP 請求,服務器也在收到請求正常處理后正常響應了,但數據包在網絡層層轉發中丟失了,所以請求線程的執行棧會停留在獲取接口響應的地方。這種情況的典型特征就是能在服務器上查找到對應的日志記錄。而且日志會顯示服務器響應完全正常。與它相對的還有線程棧停留在 Socket connect 處的,這是在建連時就失敗了,服務端完全無感知。

我注意到其中一個接口報錯更頻繁一些,這個接口需要上傳一個 4M 的文件到服務器,然后經過一連串的業務邏輯處理,再返回 2M 的文本數據,而其他的接口則是簡單的業務邏輯,我猜測可能是需要上傳下載的數據太多,所以超時導致丟包的概率也更大吧。

根據這個猜想,群登上服務器,使用請求的 request_id 在近期服務日志中搜索一下,果不其然,就是網絡丟包問題導致的接口超時了。

當然這樣 leader 是不會滿意的,這個結論還得有人接鍋才行。於是趕緊聯系運維和網絡組,向他們確認一下當時的網絡狀態。網絡組同學回復說是我們探測服務所在機房的交換機老舊,存在未知的轉發瓶頸,正在優化,這讓我更放心了,於是在部門群里簡單交待一下,算是完成任務。

問題爆發

本以為這次值班就起這么一個小波浪,結果在晚上八點多,各種接口的報警郵件蜂擁而至,打得准備收拾東西過周日單休的我措手不及。

這次幾乎所有的接口都在超時,而我們那個大量網絡 I/O 的接口則是每次探測必超時,難道是整個機房故障了么。

我再次通過服務器和監控看到各個接口的指標都很正常,自己測試了下接口也完全 OK,既然不影響線上服務,我准備先通過探測服務的接口把探測任務停掉再慢慢排查。

結果給暫停探測任務的接口發請求好久也沒有響應,這時候我才知道沒這么簡單。

解決

內存泄漏
於是趕快登陸探測服務器,首先是 top free df 三連,結果還真發現了些異常。
image.png

我們的探測進程 CPU 占用率特別高,達到了 900%。

我們的 Java 進程,並不做大量 CPU 運算,正常情況下,CPU 應該在 100~200% 之間,出現這種 CPU 飆升的情況,要么走到了死循環,要么就是在做大量的 GC。

使用 jstat -gc pid [interval] 命令查看了 java 進程的 GC 狀態,果然,FULL GC 達到了每秒一次。

image.png

這么多的 FULL GC,應該是內存泄漏沒跑了,於是 使用 jstack pid > jstack.log 保存了線程棧的現場,使用 jmap -dump:format=b,file=heap.log pid 保存了堆現場,然后重啟了探測服務,報警郵件終於停止了。

jstat

jstat 是一個非常強大的 JVM 監控工具,一般用法是: jstat [-options] pid interval

它支持的查看項有:

  • class 查看類加載信息
  • compile 編譯統計信息
  • gc 垃圾回收信息
  • gcXXX 各區域 GC 的詳細信息 如 -gcold

使用它,對定位 JVM 的內存問題很有幫助。

排查

問題雖然解決了,但為了防止它再次發生,還是要把根源揪出來。

分析棧
棧的分析很簡單,看一下線程數是不是過多,多數棧都在干嘛。

> grep 'java.lang.Thread.State' jstack.log  | wc -l
> 464

才四百多線程,並無異常。

> grep -A 1 'java.lang.Thread.State' jstack.log  | grep -v 'java.lang.Thread.State' | sort | uniq -c |sort -n

     10  at java.lang.Class.forName0(Native Method)
     10  at java.lang.Object.wait(Native Method)
     16  at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
     44  at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
    344  at sun.misc.Unsafe.park(Native Method)

線程狀態好像也無異常,接下來分析堆文件。

下載堆 dump 文件
堆文件都是一些二進制數據,在命令行查看非常麻煩,Java 為我們提供的工具都是可視化的,Linux 服務器上又沒法查看,那么首先要把文件下載到本地。

由於我們設置的堆內存為 4G,所以 dump 出來的堆文件也很大,下載它確實非常費事,不過我們可以先對它進行一次壓縮。

gzip 是個功能很強大的壓縮命令,特別是我們可以設置 -1 ~ -9 來指定它的壓縮級別,數據越大壓縮比率越大,耗時也就越長,推薦使用 -6~7, -9 實在是太慢了,且收益不大,有這個壓縮的時間,多出來的文件也下載好了。

使用 MAT 分析 jvm heap
MAT 是分析 Java 堆內存的利器,使用它打開我們的堆文件(將文件后綴改為 .hprof), 它會提示我們要分析的種類,對於這次分析,果斷選擇 memory leak suspect。

image.png

從上面的餅圖中可以看出,絕大多數堆內存都被同一個內存占用了,再查看堆內存詳情,向上層追溯,很快就發現了罪魁禍首。
image.png

分析代碼
找到內存泄漏的對象了,在項目里全局搜索對象名,它是一個 Bean 對象,然后定位到它的一個類型為 Map 的屬性。

這個 Map 根據類型用 ArrayList 存儲了每次探測接口響應的結果,每次探測完都塞到 ArrayList 里去分析,由於 Bean 對象不會被回收,這個屬性又沒有清除邏輯,所以在服務十來天沒有上線重啟的情況下,這個 Map 越來越大,直至將內存占滿。

內存滿了之后,無法再給 HTTP 響應結果分配內存了,所以一直卡在 readLine 那。而我們那個大量 I/O 的接口報警次數特別多,估計跟響應太大需要更多內存有關。

給代碼 owner 提了 PR,問題圓滿解決。

小結

其實還是要反省一下自己的,一開始報警郵件里還有這樣的線程棧:

groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:166)
groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132)
groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:186)
groovy.json.internal.JsonParserCharArray.decodeJsonObject(JsonParserCharArray.java:132)
groovy.json.internal.JsonParserCharArray.decodeValueInternal(JsonParserCharArray.java:186)

看到這種報錯線程棧卻沒有細想,要知道 TCP 是能保證消息完整性的,況且消息沒有接收完也不會把值賦給變量,這種很明顯的是內部錯誤,如果留意后細查是能提前查出問題所在的,查問題真是差了哪一環都不行啊。

來源 | https://zhenbianshu.github.io/

記一次jvm瘋狂gc導致CPU飆高的問題解決

背景

線上web服務器不時的出現非常卡的情況,登錄服務器top命令發現服務器CPU非常的高,重啟tomcat之后CPU恢復正常,半天或者一天之后又會偶現同樣的問題。解決問題首先要找到問題的爆發點,對於偶現的問題是非常難於定位的。

重啟服務器之后只能等待問題再次出現,這時候首先懷疑是否某個定時任務引發大量計算或者某個請求引發了死循環,所以先把代碼里面所有懷疑的地方分析了一遍,加了一點日志,結果第二天下午問題再次出現,

這次的策略是首先保護案發現場,因為線上是兩個點,把一個點重啟恢復之后把另一個點只下線不重啟保留犯罪現場。

排查

在問題的服務器上首先看業務日志,沒有發現大量重復日志,初步排除死循環的可能,接下來只能分析jvm了。

第一步:top命令查看占用CPU的pid

image.png

這是事后的截圖,當時的cpu飆高到500多,pid是27683

然后ps aux | grep 27683 搜索一下確認一下是不是我們的tomcat占用的cpu,這個基本是可以肯定的,因為tomcat重啟之后CPU立馬就降下來了。

也可以使用jps顯示java的pid

第二步:top -H -p 27683 查找27683下面的線程id,顯示線程的cpu的占用時間,占用比例,發現有很多個線程都會CPU占用很高,只能每個排查。

第三步:jstack查看線程信息,命令:jstack 27683 >> aaaa.txt 輸出到文本中再搜索,也可以直接管道搜索 jstack 27683 | grep "6c23" 這個線程id是16進制表示,需要轉一下,可以用這個命令轉 printf "%x\n" tid 也可以自己計算器轉一下。

悲劇的是我在排查的時候被引入了一個誤區,當時搜索到6c26這個線程的時候,發現是在做gc,瘋狂gc導致的線程過高,但是找不到哪里造成的產生這么多對象,一直在找所有可能的死循環和可能的內存泄露。

image.png

然后通過命名 jstat -gcutil 【PID】 1000 100 查看每秒鍾gc的情況。

image.png

這個是事后復盤的截圖,當時的截圖已經沒有了

發現S0不停的再新建對象,然后gc,不停的反復如此gc,去看堆棧信息,沒有什么發現,無非都是String和map對象最多,確定不了死循環的代碼,也找不到問題的爆發點,至此陷入徹底的困惑。一番查找之后確認也不是內存泄露,苦苦尋找無果,我陷入了沉思。

CPU還是一直保持在超高,無奈之下,還是jstack 27683 看線程棧,無目的的亂看,但是發現了一個問題,當前的點我是下線的也就是沒有用戶訪問的,CPU還是一直這么高,而且線程棧也在不停的打印,那么也就是說當前還在運行的線程很可能就是元凶,馬上分析線程棧信息,有了重大發現。

image.png

大量的這個線程信息出現,httpProxy_jsp這個jsp的線程在不停的活躍,這個是什么鬼jsp?難道服務器被攻擊了?馬上去代碼里找,發現確實有這個jsp,查看git的提交記錄,是幾天之前另一個同事提交的代碼,時間點和問題第一次出現的時間非常吻合,感覺自己運氣好應該是找到問題的點了,把同事叫過來分析他的代碼,這個jsp其實非常簡單,就是做一個代理請求,發起了一個后端http請求。

image.png

HttpRequestUtil如下,是同事自己寫的工具類,沒有用公用工具,其中一個post方法里connection沒有設置鏈接超時時間和read超時時間:

image.png

這里面有個致命的問題,他http請求沒有設置超時等待時間,connection如果不設置超時時間或者0就認為是無窮大,也就是會一直都不超時,這時候如果被請求的第三方頁面如果不響應或者響應非常慢,這個請求就會一直的等待,或者是請求沒回來接着又來一次,導致這個線程就卡住了,但是線程堆積在這里又不崩潰還一直的在做某些事情會產生大量的對象,然后觸發了jvm不停的瘋狂GC把服務器CPU飈到了極限,然后服務器響應變得非常慢,問題終於找到了,而且非常符合問題的特點,果然把這個地方換了一種寫法加了2秒鍾超時的限制,問題沒有再出現。

這次問題的解決過程得出幾點心得:

1、jvm的問題是很復雜的,通過日志看到的很可能不是問題的根源,解決問題也有運氣成分,分析日志+業務場景+瞎蒙都是解決問題的方法,分析問題不要一條道走到黑,多結合當前的場景加上一些猜測。

2、這個問題的根源是CPU飆高,一開始總想着是代碼里有死循環,后來又以為是內存泄露,所以走了很多彎路,最后還是用最笨的方法看線程棧的日志看出了問題,所以問題沒有統一的解決方案,具體問題都要具體處理的,不能拘泥於以往的經驗。

3、在寫代碼過程中盡量使用原項目中已經被廣泛使用的公共工具類,盡量不要把自己自創的沒有經過項目檢驗的代碼引入工程,即使看起來很簡單的一段代碼可能給項目引入災難,除非你有充足的把握了解你代碼的底層,比如這個超時的設置問題。

記一次Synchronized關鍵字使用不合理,導致的多線程下線程阻塞問題排查

在為客戶進行性能診斷調優時,碰到了一個Synchronized關鍵字使用不合理導致多線程下線程阻塞的情況。用文字記錄下了問題的整個發現-排查-分析-優化過程,排查過程中使用了我司商業化產品——XLand性能分析平台,通過文章主要希望跟大家分享下分析和優化思路以及注意點,有興趣深入了解的同學可以評論交流。

現象

在執行單接口負載“判斷登陸是否正常接口”測試時候,發現10用戶增加至50用戶並發,TPS保持不變,響應時間處於持續遞增狀態,應用CPU為27%,數據庫CPU為3%,資源消耗維持穩定狀態,由此判斷應用程序可能存在瓶頸。
1.png
2.png
3.png

分析

通過XLand分析平台線程分析,發現某線程存在鎖等待情況,通過XLand中的x分析定位,發現AuthProvider類中getAccessor方法有Synchronized關鍵字,當兩個以上線程同時調用該同步方法時,每次只能有一個線程能進入該方法,其他線程必須等前一個線程執行完該同步方法后,才能有機會進入。
馬賽克4.png
5.png

風險點

Synchronized關鍵字解決的是多個線程之間訪問資源的同步性,Synchronized關鍵字可以保證被它修飾的方法或者代碼塊在任意時刻只能有一個線程執行。謹慎使用Synchronized關鍵字,以防導致不必要的線程阻塞,影響響應時間。

優化措施

把AuthProvider類中的Synchronized關鍵字去掉,發現在10用戶並發下判斷登陸是否正常接口TPS由原來的174筆/秒增長至624筆/秒,增長了3倍。在日常編程中謹慎使用synchronized,如果沒有多線程修改靜態變量或單例屬性這類需求就不要用,如果有需要也建議只鎖必要的代碼塊,而不是鎖整個方法。

后記

Java 應用性能的瓶頸點非常多,比如磁盤、內存、網絡 I/O 等系統因素,Java 應用代碼,JVM GC,數據庫,緩存等。一般將 Java 性能優化分為 4 個層級:應用層、數據庫層、框架層、JVM 層。每層優化難度逐級增加,涉及的知識和解決的問題也會不同。但說實話,其實大多數問題還沒有需要你懂框架源代碼、JVM參數、GC工作機制這一步,只需要略會分析SQL,理解代碼邏輯,會定位到有問題的Java代碼並作修改即可。畢竟不是有這么一句話是這么說來着——80%的性能問題都是你寫的爛代碼導致的,哈哈哈。雖然有點犀利,但是保持良好的編碼習慣,合理使用某些可能引起問題的關鍵字,謹慎使用內存資源,的確能規避很大一部分問題。好了,最后祝大家都徒手千行無bug!


免責聲明!

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



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