我們常說面試造火箭，很多人對此提出質疑，相信大家看了這篇文章會明白面試造火箭的道理，這篇排查問題的技巧涉及到索引，GC，容器，網絡抓包，全鏈路追蹤等基本技能，沒有這些造火箭的本事，排查這類問題往往會無從下手，本篇也能回答不少朋友的問題：為什么學 Java 卻要掌握網絡，MySQL等其他知識體系，這會讓你成為更出色的工程師哦。

?

一. 問題現象

商品團隊反饋，會員部分 dubbo 接口偶現超時異常，而且時間不規律，幾乎每天都有，商品服務超時報錯如下圖：

超時的接口平時耗時極短，平均耗時 4-5 毫秒。查看 dubbo 的接口配置，商品調用會員接口超時時間是一秒，失敗策略是failfast，快速失敗不會重試。

會員共部署了8臺機器，都是 Java 應用，Java 版本使用的是 JDK 8，都跑在 docker 容器中 。

?

二. 問題分析

開始以為只是簡單的接口超時，著手排查。首先查看接口邏輯，只有簡單的數據庫調用，封裝參數返回。SQL 走了索引查詢，理應返回很快才是。

于是搜索 dubbo 的攔截器ElapsedFilter打印的耗時日志（ElapsedFilte r是 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，打印全鏈路各個步驟的時間。

服務端接收 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. 網絡抓包

觀察具體的超時機器和時間，發現并不是多臺機器超時，而是一段時間有某臺機器比較密集的超時，而且頻率比之前密集了許多。以前的超時在各機器之間較為隨機，而且頻率低很多。比較奇怪的是，應用 經過發布之后，原來超時的機器不超時了，而是其他的機器開始超時，看起來像是接力賽。（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

有道無術，術可成；有術無道，止于術

歡迎大家關注Java之道公眾號

好文章，我在看??

新人創作打卡挑戰賽發博客就能抽獎！定制產品紅包拿不停！

總結

以上是生活随笔為你收集整理的这个超时问题花了我两周才解决！的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。