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

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 三連，結果還真發現了些異常。

我們的探測程式 CPU 佔用率特別高，達到了 900%。

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

使用 jstat -gc pid [interval] 命令檢視了 java 程式的 GC 狀態，果然，FULL GC 達到了每秒一次。

這麼多的 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。

從上面的餅圖中可以看出，絕大多數堆記憶體都被同一個記憶體佔用了，再檢視堆記憶體詳情，向上層追溯，很快就發現了罪魁禍首。

分析程式碼
找到記憶體洩漏的物件了，在專案裡全域性搜尋物件名，它是一個 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

這是事後的截圖，當時的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導致的執行緒過高，但是找不到哪裡造成的產生這麼多物件，一直在找所有可能的死迴圈和可能的記憶體洩露。

然後通過命名 jstat -gcutil 【PID】 1000 100 檢視每秒鐘gc的情況。

這個是事後覆盤的截圖，當時的截圖已經沒有了

發現S0不停的再新建物件，然後gc，不停的反覆如此gc，去看堆疊資訊，沒有什麼發現，無非都是String和map物件最多，確定不了死迴圈的程式碼，也找不到問題的爆發點，至此陷入徹底的困惑。一番查詢之後確認也不是記憶體洩露，苦苦尋找無果，我陷入了沉思。

CPU還是一直保持在超高，無奈之下，還是jstack 27683 看執行緒棧，無目的的亂看，但是發現了一個問題，當前的點我是下線的也就是沒有使用者訪問的，CPU還是一直這麼高，而且執行緒棧也在不停的列印，那麼也就是說當前還在執行的執行緒很可能就是元凶，馬上分析執行緒棧資訊，有了重大發現。

大量的這個執行緒資訊出現，httpProxy_jsp這個jsp的執行緒在不停的活躍，這個是什麼鬼jsp？難道伺服器被攻擊了？馬上去程式碼裡找，發現確實有這個jsp，檢視git的提交記錄，是幾天之前另一個同事提交的程式碼，時間點和問題第一次出現的時間非常吻合，感覺自己運氣好應該是找到問題的點了，把同事叫過來分析他的程式碼，這個jsp其實非常簡單，就是做一個代理請求，發起了一個後端http請求。

HttpRequestUtil如下，是同事自己寫的工具類，沒有用公用工具，其中一個post方法裡connection沒有設定連結超時時間和read超時時間：

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

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

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

2、這個問題的根源是CPU飆高，一開始總想著是程式碼裡有死迴圈，後來又以為是記憶體洩露，所以走了很多彎路，最後還是用最笨的方法看執行緒棧的日誌看出了問題，所以問題沒有統一的解決方案，具體問題都要具體處理的，不能拘泥於以往的經驗。

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

記一次Synchronized關鍵字使用不合理，導致的多執行緒下執行緒阻塞問題排查

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

現象

在執行單介面負載“判斷登陸是否正常介面”測試時候，發現10使用者增加至50使用者併發，TPS保持不變，響應時間處於持續遞增狀態，應用CPU為27%，資料庫CPU為3%，資源消耗維持穩定狀態，由此判斷應用程式可能存在瓶頸。

分析

通過XLand分析平臺執行緒分析，發現某執行緒存在鎖等待情況，通過XLand中的x分析定位，發現AuthProvider類中getAccessor方法有Synchronized關鍵字，當兩個以上執行緒同時呼叫該同步方法時，每次只能有一個執行緒能進入該方法，其他執行緒必須等前一個執行緒執行完該同步方法後，才能有機會進入。

風險點

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！