大家好，我是坤哥
我們常說面試造火箭，很多人對此提出質疑，相信大家看了這篇文章會明白麵試造火箭的道理，這篇排查問題的技巧涉及到索引，GC，容器，網路抓包，全鏈路追蹤等基本技能，沒有這些造火箭的本事，排查這類問題往往會無從下手，本篇也能回答不少朋友的問題：為什麼學 Java 卻要掌握網路，MySQL等其他知識體系，這會讓你成為更出色的工程師哦。
一. 問題現象
商品團隊反饋，會員部分 dubbo 介面偶現超時異常，而且時間不規律，幾乎每天都有，商品服務超時報錯如下圖：
超時的介面平時耗時極短，平均耗時 4-5 毫秒。檢視 dubbo 的介面配置，商品呼叫會員介面超時時間是一秒，失敗策略是failfast，快速失敗不會重試。
會員共部署了8臺機器，都是 Java 應用，Java 版本使用的是 JDK 8，都跑在 docker 容器中 。
二. 問題分析
開始以為只是簡單的介面超時，著手排查。首先檢視介面邏輯，只有簡單的資料庫呼叫，封裝引數返回。SQL 走了索引查詢，理應返回很快才是。
於是搜尋 dubbo 的攔截器 ElapsedFilter 列印的耗時日誌（ElapsedFilter 是 dubbo SPI 機制的擴充套件點之一，超過 300 毫秒的介面耗時都會列印），這個介面的部分時間耗時確實很長。
再查詢資料庫的慢 SQL 平臺，未發現慢 SQL。
1. 資料庫超時？
懷疑是獲取資料庫連線耗時。程式碼中呼叫資料庫查詢可以分為兩步，獲取資料庫連線和 SQL 查詢，慢SQL 平臺監測的 SQL 執行時間，既然慢 SQL 平臺沒有發現，那可能是建立連線耗時較長。
檢視應用中使用了 Druid 連線池，資料庫連線會在初始化使用時建立，而不是每次 SQL 查詢再建立連線。Druid 配置的 initial-size（初始化連結數）是 5，max-active（最大連線池數量）是 50，但 min-idle（最小連線池數量）只有 1，猜測可能是連線長時間不被使用後都回收了，有新的請求進來後觸發建立連線，耗時較長。
因此調整 min-idle 為 10，並加上了 Druid 連線池的使用情況日誌，每隔 3 秒列印連線池的活躍數等資訊，重新觀察。
改動上線後，還是有超時發生，超時發生時檢視連線池日誌，連線數正常，連線池連線數也沒什麼波動。
2. STW？
因此重新回到報錯日誌觀察，ElapsedFilter 列印的耗時日誌已經消失。由於在業務方法的入口和出口，以及資料庫操作的前後列印了日誌，發現整個業務操作耗時極短，都在幾毫秒內完成。
但是呼叫端隔一段時間開始超時報錯，且並不是呼叫一個介面超時，而是呼叫好幾個介面都同時超時。另外，呼叫端的幾臺機器都會同時報超時（可以在 elk 平臺篩選 hostname 檢視），而提供服務超時的機器是同一臺。
這樣問題就比較清晰了，應該是某一時刻提供服務的某臺機器出現比較全域性性的問題導致幾乎所有介面都超時。
繼續觀察日誌，抓了其中一個超時的請求從呼叫端到服務端的所有日誌（理應有分散式 ID 可以追蹤，context id 只能追蹤單應用內的一個請求，跨應用就失效了，所以只能自己想辦法，此處是根據呼叫IP+時間+介面+引數在 elk 定位）。
這次有了新的發現，服務端收到請求的時間比呼叫端發起呼叫的時間晚了一秒，比較嚴謹的說法是呼叫端的超時日誌中 dubbo 有列印 startTime（記為T1）和 endTime，同時在服務端的介面方法入口加了日誌，可以定位請求進來的時間（記為T2），比較這兩個時間，發現 T2 比 T1 晚了一秒多，更長一點的有兩到三秒。
內網呼叫網路時間幾乎可以忽略不計，這個延遲時間極其不正常。很容易想到 Java 應用的 STW(Stop The World)，其中，特別是垃圾回收會導致短暫的應用停頓，無法響應請求。
排查垃圾回收問題第一件事自然是開啟垃圾回收日誌（GC log），GC log 列印了 GC 發生的時間，GC 的型別，以及 GC 耗費的時間等。增加 JVM 啟動引數
-XX:+PrintGCDetails -Xloggc:${APPLICATION_LOG_DIR}/gc.log -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime。
為了方便排查，同時列印了所有應用的停頓時間。（除了垃圾回收會導致應用停頓，還有很多操作也會導致停頓，比如取消偏向鎖等操作）。由於應用是在 docker 環境，因此每次應用釋出都會導致 GC 日誌被清除，寫了個上報程式，定時把 GC log 上報到 elk 平臺，方便觀察。
以下是介面超時時 gc 的情況：
可以看到，有次 GC 耗費的時間接近兩秒，應用的停頓時間也接近兩秒，而且此次的垃圾回收是ParNew 演算法，也就是發生在新生代。所以基本可以確定，是垃圾回收的停頓導致應用不可用，進而導致介面超時。
2.1 安全點及 FinalReferecne
以下開始排查新生代垃圾回收耗時過長的問題。
首先，應用的 JVM 引數配置是
-Xmx5g -Xms5g -Xmn1g -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -Xss256k -XX:SurvivorRatio=8 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70
通過觀察 marvin 平臺（我們的監控平臺），發現堆的利用率一直很低，GC 日誌甚至沒出現過一次 CMS GC，由此可以排除是堆大小不夠用的問題。
ParNew 回收演算法較為簡單，不像老年代使用的 CMS 那麼複雜。ParNew 採用標記-複製演算法，把新生代分為 Eden 和 Survivor 區，Survivor 區分為 S0 和 S1，新的物件先被分配到 Eden 和 S0 區，都滿了無法分配的時候把存活的物件複製到 S1 區，清除剩下的物件，騰出空間。比較耗時的操作有三個地方，找到並標記存活物件，回收物件，複製存活物件（此處涉及到比較多垃圾回收的知識，詳細部分就不展開說了）。
找到並標記存活物件前 JVM 需要暫停所有執行緒，這一步並不是一蹴而就的，需要等所有的執行緒都跑到安全點。部分執行緒可能由於執行較長的迴圈等操作無法馬上響應安全點請求，JVM 有個引數可以列印所有安全點操作的耗時，加上引數
-XX:+PrintSafepointStatistics -XX: PrintSafepointStatisticsCount=1 -XX:+UnlockDiagnosticVMOptions -XX: -DisplayVMOutput -XX:+LogVMOutput -XX:LogFile=/opt/apps/logs/safepoint.log。
安全點日誌中 spin+block 時間是執行緒跑到安全點並響應的時間，從日誌可以看出，此處耗時極短，大部分時間都消耗在 vmop 操作，也就是到達安全點之後的操作時間，排除執行緒等待進入安全點耗時過長的可能。
繼續分析回收物件的耗時，根據引用強弱程度不通，Java 的物件型別可分為各類 Reference，其中FinalReference 較為特殊，物件有個 finalize 方法，可在物件被回收之前呼叫，給物件一個垂死掙扎的機會。有些框架會在物件 finalize 方法中做一些資源回收，關閉連線的操作，導致垃圾回收耗時增加。因此通過增加JVM引數 -XX:+PrintReferenceGC，列印各類 Reference 回收的時間。
可以看到，FinalReference 的回收時間也極短。
最後看複製存活物件的耗時，複製的時間主要由存活下來的物件大小決定，從 GC log 可以看到，每次新生代回收基本可以回收百分之九十以上的物件，存活物件極少。因此基本可以排除這種可能。
問題的排查陷入僵局，ParNew 演算法較為簡單，因此 JVM 並沒有更多的日誌記錄，所以排查更多是通過經驗。
2.2 垃圾回收執行緒
不得已，開始求助網友，上 stackoverflow 發帖（連結見文末），有大神從 GC log 發現，有兩次 GC 回收的物件大小几乎一樣，但是耗時卻相差十倍，因此建議確認下系統的 CPU 情況，是否是虛擬環境，可能存在激烈的 CPU 資源競爭。
其實之前已經懷疑是 CPU 資源問題，通過 marvin 監控發現，垃圾回收時 CPU 波動並不大。但運維發現我們應用的垃圾回收執行緒數有些問題（GC 執行緒數可以通過 jstack 命令列印執行緒堆疊檢視），JVM 的 GC 執行緒數量是根據 CPU 的核數確定的，如果是八個核心以下，GC 執行緒數等於CPU 核心數，我們應用跑在 docker 容器，分配的核心是六核，但是新生代 GC 執行緒數卻達到了 53個，這明顯不正常。
最後發現，這個問題是 JVM 在 docker 環境中，獲取到的 CPU 資訊是宿主機的（容器中 /proc目錄並未做隔離，各容器共享，CPU資訊儲存在該目錄下），並不是指定的六核心，宿主機是八十核心，因此建立的垃圾回收執行緒數遠大於 docker 環境的 CPU 資源，導致每次新生代回收執行緒間競爭激烈，耗時增加。
通過指定 JVM 垃圾回收執行緒數為 CPU 核心數，限制新生代垃圾回收執行緒，增加JVM引數
-XX:ParallelGCThreads=6 -XX:ConcGCThreads=6
效果立竿見影！新生代垃圾回收時間基本降到 50 毫秒以下，成功解決垃圾回收耗時較長問題。
三. 問題重現
本以為超時問題應該徹底解決了，但還是收到了介面超時的報警。現象完全一樣，同一時間多個介面同時超時。檢視 GC 日誌，發現已經沒有超過一秒的停頓時間，甚至上百毫秒的都已經沒有。
1. Arthas 和 Dubbo
回到程式碼，重新分析。開始對整個 Dubbo 介面接收請求過程進行拆解，打算藉助阿里巴巴開源的Arthas 對請求進行 trace，列印全鏈路各個步驟的時間。（Arthas 和 dubbo）
服務端接收 dubbo 請求，從網路層開始再到應用層。具體是從 netty 的 worker 執行緒接收到請求，再投遞到 dubbo 的業務執行緒池（應用使用的是 ALL 型別執行緒池），由於涉及到多個執行緒，只能分兩段進行 trace，netty 接收請求的一段，dubbo 執行緒處理的一段。
Arthas 的 trace 功能可以在後臺執行，同時只列印耗時超過某個閾值的鏈路。（trace 採用的是instrument+ASM，會導致短暫的應用暫停，暫停時間取決於被植入的類的數量，需注意）
由於沒有列印引數，無法準確定位超時的請求，而且 trace 只能看到呼叫第一層的耗時時間，結果都是業務處理時間過長，最後放棄了該trace方法。
受 GC 執行緒數思路的啟發，由於應用執行基本不涉及刷盤的操作，都是 CPU 運算+記憶體讀取，耗時仍舊應該是執行緒競爭或者鎖引起的。重新回到 jstack 的堆疊進行排查，發現匯流排程數仍有 900+，處於一個較高的水平，其中 forkjoin 執行緒和 netty 的 worker 的執行緒數仍較多。於是重新搜尋程式碼中執行緒數是通過CPU核心數設定（Runtime.getRuntime().availableProcessors()）的地方，發現還是有不少框架使用這個引數，這部分無法通過設定JVM引數解決。
因此和容器組商量，是否能夠給容器內應用傳遞正確的 CPU 核心數。容器組確認可以通過升級 JDK 版本和開啟 CPU SET 技術限制容器使用的 CPU 數，從 Java 8u131 和 Java 9 開始，JVM 可以理解和利用 cpusets 來確定可用處理器的大小(Java 和 cpu set 見文末參考連結)。現在使用的也是JDK 8，小版本升級風險較小，因此測試沒問題後，推動應用內8臺容器升級到了 Java 8u221，並且開啟了 cpu set，指定容器可使用的 CPU 數。
重新修改上線後，還是有超時情況發生。
2. 網路抓包
觀察具體的超時機器和時間，發現並不是多臺機器超時，而是一段時間有某臺機器比較密集的超時，而且頻率比之前密集了許多。以前的超時在各機器之間較為隨機，而且頻率低很多。比較奇怪的是，wukong 經過釋出之後，原來超時的機器不超時了，而是其他的機器開始超時，看起來像是接力賽。（docker 應用的宿主機隨著每次釋出都可能變化）
面對如此奇怪的現象，只能懷疑是宿主機或者是網路問題了，因此開始網路抓包。
由於超時是發生在一臺機器上，而且頻率較為密集，因此直接進入該機器，使用 tcpdump 命令抓取host 是呼叫方進來的包並儲存抓包記錄，通過 wireshark 分析（wireshark 是抓包分析神器），抓到了一些異常包。
注意抓包中出現的 「TCP Out_of_Order」,「TCP Dup ACK」,「TCP Retransmission」，三者的釋義如下:
TCP Out_of_Order: 一般來說是網路擁塞，導致順序包抵達時間不同，延時太長，或者包丟失，需要重新組合資料單元，因為他們可能是由不同的路徑到達你的電腦上面。
TCP dup ack XXX#X: 重複應答，#前的表示報文到哪個序號丟失，#後面的是表示第幾次丟失
TCP Retransmission： 超時引發的資料重傳
終於，通過在 elk 中超時日誌列印的 contextid，在 wireshark 過濾定位超時的 TCP 包，發現超時的時候有丟包和重傳。抓了多個超時的日誌都有丟包發生，確認是網路問題引起。
問題至此基本告一段落，接下來容器組繼續排查網路偶發丟包問題。
巨人的肩膀
- stackoverflow 提問帖子: http://aakn.cn/YbFsl
- jstack 視覺化分析工具：https://fastthread.io/
- 2018年的 Docker 和 JVM：`https://www.jdon.com/51214
更多精品文章，歡迎大家掃碼關注「碼海」
