一 現象

調用方A -> JSF -> 提供方B

大多數情況下，調用方耗時 和 提供方耗時 基本沒有差別

個別情況下，調用方耗時 遠高於 提供方耗時，大概5分鐘20+次

1.調用方A耗時如下圖





2.提供方B耗時如下圖



3.調用方監控添加

在調用JSF接口前後加的監控，沒有其他任何邏輯，包括日誌打印

4.提供方監控添加

在代碼最外層JSF接口加的監控，之外沒有任何代碼邏輯

5.耗時對比



二 排查思路



1.數據流轉環節分析



調用方從請求到接收數據，除了提供方業務耗時，還有其他環節，分別是

1.調用方容器和宿主機

2.調用方->提供方經過的網絡環節

3.提供方容器和宿主機的環節

4.提供方->調用方的網絡環節

2.初步定位

容器和宿主機之間由於流量過大，處理壓力大導致的瓶頸

網絡波動

一步一步排除，先看網絡



3.找證據

3.1 找監控

找到監控相關的技術同學，回答説沒有網絡的監控

於是找到了JDOS的同學，排查後提供了一種懷疑方向，如下圖





容器內存使用率（包含cache）基本一直保持在99%以上，建議先確定該指標的影響，並降低該指標

3.1.2 指標含義

指標定義文檔解釋如下



還是看不太懂指標的含義，懵B狀態

提工單諮詢，給出的解決方案如下

java應用，無ngix，還是懵，繼續求助

最後得出結論：

這個之前在營銷中心那邊有遇到C++ 使用page cache 還有使用zgc的 需要參考一下cache這個指標，其他的場景 目前看 系統會在物理內存不夠用的時候 釋放cache；

這個是指有的c++應用底層接口直接使用了pagecache，java可以忽略



更詳細解釋：

內存那部分是這樣的，每個容器的 Memory Cgroup 在統計每個控制組的內存使用時包含了兩部分，RSS 和 Page Cache。

RSS 是每個進程實際佔用的物理內存，它包括了進程的代碼段內存，進程運行時需要的堆和棧的內存，這部分內存是進程運行所必須的。

Page Cache 是進程在運行中讀寫磁盤文件後，作為 Cache 而繼續保留在內存中的，它的目的是為了提高磁盤文件的讀寫性能。（Java程序只要操作磁盤讀寫也會用到 page cache）

有時會看到這樣一種情況：容器裏的應用有很多文件讀寫，你會發現整個容器的內存使用量已經很接近 Memory Cgroup 的上限值了，但是在容器中我們接着再申請內存，還是可以申請出來，並且沒有發生 OOM。那是因為容器中有部分是PageCache,當容器需要更多內存時，釋放了PageCache,所以總大小並沒有變化。



結論：對於java系統來説，容器內存使用率（包含cache）沒有影響（cache會自動釋放）



3.1.3 降低容器內存使用率（包含cache）

雖説沒有影響，還是想辦法降低試試效果（非常相信大佬）

看了其他幾個java集羣





看到最後一個圖，小小分析了下，發現三個小時會降低一波，正好和日誌清除的時間間隔一致。

對提供方B清除日誌後發現果然降低，如下





但是毛刺依然存在！！

3.2 容器處理性能瓶頸

擴容前，CPU和內存也處於正常水平



擴容後（匯天4台 -> 匯天8台），CPU和內存沒啥太多變化



調用方耗時如下，基本沒啥變化，頭大





3.3 耗時分析

運維的同事幫忙分析了一波，給出年輕代GC耗時較高可能會影響耗時；如下



找了兩個毛刺的數據，找到對應提供方的機器，查看那一分鐘內有yanggc耗時（分鐘的粒度），計算下來，調用方耗時比較接近 提供方耗時+提供方yanggc耗時，但是沒有直接採取措施，主要一下原因

1.yanggc粒度比較粗，分鐘級

2.一直認為FullGC會導致STW，增加耗時，yangGc不會有太大影響

3.只有一兩次的數據分析，數據也沒有那麼準確

4.備戰期間，線上機器封板，動起來比較麻煩，想找下其他原因，雙管齊下



3.4 網絡對抓 + PFinder

1.調用方多台機器，提供方也是多台機器，網絡抓包要想抓全得N*M，比較費勁

2.PFinder也是隨機抓包

3.毛刺也是隨機產生的

想保證，抓到毛刺請求，且，PFinder有數據，採取如下對策

1.選擇調用方的一台機器 X 提供方的一台機器，進行抓包

2.監控調用方的這台機器的UMP監控

3.調用方的UMP監控有毛刺時，查看是否有PFinder監控數據，如果沒有則繼續抓，有則停止

最後抓到了想要的數據

網絡運維的同事幫忙對抓網絡包，左邊是調用方，右邊是提供方，如下



調用方的PFinder的數據如下



提供方代碼開始PFinder的數據如下

數據分析後結論如下：

調用方22:24:50.775730 發出 22:24:50.988867收到 耗時213ms

提供方22:24:50.775723收到數據包，等到22:24:50.983才處理，22:24:50.988776處理結束回包

提供方等待208ms左右，實際處理4.55ms，加起來 213左右，和調用方耗時對應上了

網絡抓包是從容器到容器的抓包



阻塞原因猜測:

1.容器瓶頸，處理不過來 - CPU、內存正常，且當天下午擴容一倍，沒有明顯好轉

2.yanggc照成延遲 - 和運維同學張憲波大佬分析的不謀而合，且是有數據支撐的



4.處理

1.目的：降低yanggc耗時（沒有FullGC）

2.當前：



3.方式：

1.增大堆內存（年輕代）

2.擴容（已經擴了一次，沒有明顯變化）

3.mq消費流量切到其他分組（一般先反序列化，根據參數過濾），減少新對象創建

4.結果：

調用方耗時如下





提供方耗時如下





提供方yanggc



調整前後調用方耗時



最終提供方和調用方耗時不一致的問題得到解決