1 問題源起
上游系統通過公司rpc框架調用我們系統接口超時（默認超時時間為100ms）數量從50次/分突然上漲到2000次/分，在發生變化時間段里我們的系統也沒有做過代碼變更，但上游系統的調用確發生了變化。由於處於主要鏈路上，sre同學找過來詢問原因，所以開始了問題排查。
2 問題初步定位
排查rpc超時的基本思路是這樣的：
1) 服務端處理確實超時
2) 服務端或者客戶端由於某種原因卡住
a) 磁盤清理
b) tr線程池
c) gc
d) 網絡
因為在發生問題時上游調用其他系統的服務並發生類似的情況，所以可以認為是服務端出現了問題而不是客戶端。
2.1 服務端處理確實超時
rpc框架在有一個traceId，用於標識請求。同一個traceId在請求端的耗時是一百多毫秒，但是在接收端的耗時只有2-3ms，抽查了幾天里的多個請求都是這樣的情況請求端的耗時遠大於接收端的耗時。這樣就排除了超時是由服務端處理引起的。
2.2 磁盤清理
線上系統通常會打印一些日志，用於記錄系統的運行情況，方便問題排查和進行監控，當這些日志的數量累計到一定量時，會進行磁盤清理。在磁盤清理期間，會對IO有較大的影響。通過查看磁盤清理日志，發現磁盤清理時間和調用超時時間並不匹配；另外磁盤清理是偶發性的，但是上游系統調用超時是持續性的，因而磁盤清理導致超時也可以排除。
2.3 rpc線程池
rpc框架采用的是NIO方式進行客戶端和服務端進行通訊，在服務端會有一個線程池處理到達的請求，查看了對應的線程池日志，發現線程池的隊列中出現堆積的次數一天只有幾次而已，但請求端調用服務出現的超時問題會連續幾個小時出現的。因而超時問題由線程池的配置引起也可以排除。
2.4 網絡
我們的服務是多地多機房部署模式，從調用方最遠的機房到我們這邊機房網絡耗時大概為25ms，來回就是50ms，加上服務端的處理時間，客戶端的請求總時間應該在60ms左右，但是現在的總耗時在100ms以上，說明網絡也不是該問題的主要原因。
2.5 gc
對上游系統調用我們系統超時的機器進行匯總，發現超時的請求主要集中在內存為4g的機器上，而10g的機器出現超時的情況很少，因而對4g和10g機器的gc進行了分析，發現二者有很大的不同：
|
|
新生代大小 |
Young gc清理內存量 |
Young gc耗時 |
Young gc 時間間隔 |
| 4g機器 |
780m |
707840k |
0.8s |
10s |
| 10g機器 |
1800m |
1382400k |
0.05s |
17s |
從上面的表格可以看到，10g機器的新生代清理效率是4g機器的新生代清理效率20多倍，4g機器新生代的清理耗時過長。初步判斷，請求方訪問超時應該和4g機器的young gc執行時間過長可能有關。
3 具體原因定位
3.1 young gc過程
jvm中的young gc過程大致分為如下幾個步驟：
1) 存活對象標注
2) 存活對象從Edge區拷貝到Survivor 1，重置指針
3) 清理Edge區和Survivor 2
4g和10g機器都是4核，二者的cpu的主頻和一級二級緩存是相同的，從理論上講二者的清理效率應該是相等的，但現在4g機器清理的內存的性能卻比10g清理卻相差如此多，說明問題可能發生在存活對象標注上。同時young gc過程中的存活對象標注是要STW，這個階段jvm會對外停止響應，很有可能是因為這個STW導致響應超時。
3.2 GC root
Jvm中的young gc是從GC roots開始的，GC root作為tracing GC的“根集合”，主要包含：
1) Class - 由系統類加載器(system class loader)加載的對象，這些類是不能夠被回收的，他們可以以靜態字段的方式保存持有其它對象。我們需要注意的一點就是，通過用戶自定義的類加載器加載的類，除非相應的java.lang.Class實例以其它的某種（或多種）方式成為roots，否則它們並不是roots，.
2) Thread - 活着的線程
3) Stack Local - Java方法的local變量或參數
4) JNI Local - JNI方法的local變量或參數
5) JNI Global - 全局JNI引用
6) Monitor Used - 用於同步的監控對象
7) Held by JVM - 用於JVM特殊目的由GC保留的對象，但實際上這個與JVM的實現是有關的。可能已知的一些類型是：系統類加載器、一些JVM知道的重要的異常類、一些用於處理異常的預分配對象以及一些自定義的類加載器等。然而，JVM並沒有為這些對象提供其它的信息，因此就只有留給分析分員去確定哪些是屬於"JVM持有"的了。
4g機器和10g機器運行的代碼都是相同，因而能夠導致gc root不同個地方應該是第二和第六項。
3.3 Thread分析
對4g機器的線程進行了dump，在zprofile中進行了下分析，分析結果顯示存在線程阻塞的情況，而后定位到所有的線程阻塞都是在一個發送消息的方法上，而這個方法是synchronized的，由於synchronized導致了調用線程獲取不到鎖的時候發生了阻塞。
3.4 發送消息為什么會采用同步
這個方法的作用是發送消息，但是為了減少消息發送的次數，在內部進行了消息的合並，當消息內容達到一定量時才發送（現在設定的是3k），整體流程如下
這其實是一個簡單的流程，但由於會存在多個線程對存儲消息的list和存儲消息體大小的size進行寫操作，特別是對list的操作時，會存在有些線程在向list中添加數據，而有些線程間接觸發了arraylist的clear操作，這樣就會報ConcurrentModificationException
。同時為避免在計算消息體大小時多線程操作引起的計算值比實際值小的問題就給這個方法用了synchronized 關鍵字加鎖讓其順序操作。
4 修改
主要的修改有3個
1) 把用arraylist存儲消息體采用ConcurrentHashMap，map中的key是一個uudi，value是消息體本身。從arraylist改為ConcurrentHashMap，可以大大增加並發性能。
2) 采用AtomicInteger來保存當前map中消息內容的大小。
3) 當map中的消息體總大小到達閾值后，先將當前map中的所有的key取出，然后將map中的數據封裝到一條消息中發送出去，將當前map中消息體的大小置為0，而后for循環刪除已成功發送的key。
5 效果對比
5.1 young gc耗時
5.2 線程阻塞
優化后線程阻塞情況不存在。
5.3 調用報錯情況
報錯從之前的近2000/分回到了50/分。
6 后記
問題雖然得到了解決，但是線程阻塞和young gc耗時的確切關系還是沒有不太清除，需要后續繼續了解，也看哪位大神給解釋下。