背景

閑魚某關鍵應用A依賴類目系統富客戶端（下文簡稱類目客戶端），旨在為閑魚商品域其他應用提供各類商品類目及屬性數據（下文簡稱CPV數據）查詢服務。

每天凌晨，該應用所依賴的類目富客戶端執行新老版本數據包切換時，應用提供的服務抖動非常明顯，表現為大量接口超時（耗時100ms -> 3-5s），服務成功率明顯下降（100% -> ~92%），RPC線程池活躍線程數上漲（50 -> ~100），抖動最長可持續20s，影響到商品發布、商品詳情頁等依賴CPV數據的關鍵業務場景；且夜間發生抖動，時間點不固定，抖動發生時開發同學也難以關注到，影響面較為不可控，因此需要排查并徹底解決此問題。

排查過程

其實這是一個表象很簡單，但是根因藏得比較深的問題，筆者在排查過程中也走了一些彎路，也一并寫出來供讀者作為前車之鑒的參考。

堆空間不夠？

結構化應用線上原先使用的是4C8G的標準規格容器，分配4G內存作為堆內存，截取部分JVM啟動參數如下：

-Xms4g -Xmx4g -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:+UnlockExperimentalVMOptions -XX:G1MaxNewSizePercent=65 -XX:+UseG1GC -XX:InitiatingHeapOccupancyPercent=55 -XX:G1HeapRegionSize=16m -XX:G1NewSizePercent=25 -XX:MaxGCPauseMillis=120 -XX:+ParallelRefProcEnabled   -XX:MaxDirectMemorySize=1g -XX:+TraceG1HObjAllocation -XX:ReservedCodeCacheSize=512m -XX:+UseCodeCacheFlushing

據反饋接口抖動的同學描述，在接口抖動的時間點，請求失敗的機器發生了FGC。

undefined

由于本人先前在排查類似的FGC問題時，經常能在Heap Dump的支配樹中看到類目客戶端相關對象長期占據高位，是內存占用大戶。所以難免主觀印象先入為主，初步以為是切換版本的過程中，在老版本數據包卸載之前，可能會存在短暫的堆內空間占用double的情況。

而啟動參數配置Eden區下限為25%?？赡艽嬖?nbsp;老年代常駐占用 + 新數據包 > 4G 的情況引發FGC。

因此覺得 既然空間占用double不可避免，老年代常駐的堆空間短時間內又不可能顯著下降，Eden區為了解決之前該應用發生Mixed GC時Eden區反?？s小導致YGC異常，又必須固定一個下限值，那只能是把容器內存規格擴大看看能否緩解 。

于是將應用容器基線升級到4C16G，設置在16G容器環境下，分配10G內存給堆空間，并逐步升級線上服務的容器規格。

結果花了兩天時間，升級了線上大部分的容器后，查看監控，發現大規格的容器確實沒有FGC了，且得益于超大的堆內存（10G），從GC監控上看甚至看不出有切包的動作。但是，RPC成功率還是會下跌（100% -> 97%），且RPC線程池線程數還是有少量上漲（50 -> ~71）。

由此可見，FGC并不是切包抖動的核心成因，背后還有更加深層次的原因需要挖掘。

容器CPU高觸發自適應限流？

再次詢問受影響的業務方，通過下游應用的日志發現推包抖動的時間點，發生了不少sentinel限流日志。而結構化應用里面并沒有針對接口主動配置限流，只有集團內的sentinel中間件，可能因為檢測到某一時間點CPU利用率過高（超過80%），自動執行限流策略。

sentinel為集團內的流控中間件，能夠以流量為切入點，從限流、流量整形、熔斷降級、系統自適應保護、熱點防護等多個維度來幫助業務保障微服務的穩定性。

登陸發生限流的服務Provider對應機器，確實看到了限流日志。

$cat cpu-sampling.log.1 | grep "2022-05-19 03:57"  | grep -v "0.0"
2022-05-19 03:57:12.435|||應用名|CpuSampling|0||4.151785714285714|1.0|6

可以看到在當前時刻，CPU利用率來到了 415%，可見確實在該時間點存在CPU四核全打滿的現象。

但是從應用監控來看，該時刻機器CPU利用率只有20%多（100%為單位）。且sentinel的cpu-sampling日志只grep出來一條CPU打滿的日志。按照限流中間件20ms采樣一次CPU的頻率，說明這只是一個CPU尖刺，不應該有大面積的影響。筆者對限流導致RPC成功率下跌其實是抱有些許懷疑態度的，覺得應該不是這樣的問題。

不管怎么說，最簡單的驗證方法，就是線上找一臺 已經換了16G內存的機器 ，把sentinel中間件設置為：只記錄日志，不執行實際限流動作的dry run模式?？唇涌诔晒β适欠駮?。按照上面的推理，CPU尖刺最長不會超過40ms，就算CPU打滿40ms，也不至于導致接口有幾秒鐘的超時。

結果到了當天晚上，接口成功率還是掉下來，存在接口幾秒鐘的超時。

源碼窺密，探究類目客戶端切包過程中具體動作

發現單純的提升容器規格并不能解決切包抖動的問題后，筆者復盤了一下手頭上已經掌握的線索：

1. FGC不是引起切包抖動的核心原因，這是升級容器，花了錢之后得到的結論。那么，如果不花這個錢，我們能不能單純從監控上得出結論？其實是可以的。如果目前線上容器規格完全不能滿足切包所需的內存消耗，理論上集群每臺機器切包的時候都會FGC，但是實際上切包過程中全集群產生的FGC量并不算多，最多在20次左右，且只有1/6的機器發生FGC，剩下的機器也只是YGC略微上漲，然后很快恢復到正常水位。而即使是YGC量上漲，也只是分鐘YGC耗時從70ms漲到200ms，根本不至于把大量接口打到超時的。

2. sentinel檢測到CPU尖刺，自動執行了限流，確實會拉低服務成功率。但即使把限流關閉，接口還會存在幾秒鐘超時，說明限流不是造成接口成功率下跌的主要原因。

3. 類目客戶端到底把類目數據存在磁盤，還是存在堆里面，亦或者是在堆外內存，四處問了一圈，各有各的說法。 然而，不同的存儲方式可能最終會導向完全不同的結論。為了搞清楚這個問題，最精確的方法就是去把類目客戶端切包的源碼讀一遍。于是筆者花了點時間，

類目服務切包流程

縱觀整個切包過程，都是在類目客戶端自帶的netty ChannelHandler回調線程中 單線程執行 完成的，沒有任何多線程并行加載的動作。在初始化類目服務入口的時候，雖然有不少構建索引之類的看起來重計算的動作，但是由于底層是單線程執行，理論上CPU最多打到100%（一個核心），不會有打到400%的情況出現。凌晨結構化應用的業務CPU占用率很低，不到10%，理論上切包+業務不至于導致CPU打滿。更不太可能引起長達幾秒鐘的服務不響應現象。

隨著進一步梳理切包和錯誤發生的時間點、日志信息，一個更奇怪的現象浮出水面。

反?，F象：切包完畢后接口開始超時

觀察以下全鏈路日志：

com.taobao.idle.modulet.ItemKgraphServiceApi@getSpuPublishSearchV3~SMM 接口有長達8s的超時。注意這個錯誤的發生時間  2022-05-24 01:38:19.523 。

平時這個接口RT在400m左右，底層是 使用線程池并行轉調各種搜索服務 ，設置了1s的總體超時時間，大量try catch包裹，基本不會報錯。

再看這個時間點附近的類目樹日志:

可以看到, 01:38:00 的時候，類目數據就已經切換完了。01:38:14的時候，更是連舊文件都刪完了。切包已經結束了。

然而，到了 01:38:27 的時候，類目服務的其中一個Logger， 從 kGraphCommonFixedThreadFactory-10-thread-95 線程打印出兩行日志:

2022-05-24 01:38:27.715 [kGraphCommonFixedThreadFactory-10-thread-95] [] WARN  類目服務Logger - Load the cache of std_category_property_value store finished. It takes 7820ms,cached 278 blocks.
2022-05-24 01:38:31.236 [kGraphCommonFixedThreadFactory-10-thread-95] [] WARN  類目服務Logger - Load the cache of std_category_property_value store finished. It takes 11341ms,cached 109 blocks.

而這個線程池，正是運行 getSpuPublishSearchV3 接口底層轉調各種搜索的執行線程，且代碼為異步執行的Future設置了1s超時，如果執行超過一秒，接口服務的代碼也不會繼續等待，而是直接往下執行了。

更巧的是：從01:38:19到01:38:27，整整8秒，恰好和上面監控的超時對的上?？吹竭@里，問題似乎變得更加復雜。

1. 1. 剛剛我們才提到，切包是在類目客戶端的netty ChannelHandler線程里進行，怎么現在又跑到了業務線程池上，甚至能Hang住了接口？
2. 2. 為什么類目服務都都跑在別的線程池上面了，且線程池超時設置1s了，為什么接口還會有8s的超時？

撥云見霧，逐個擊破

其實回答問題1不難。因為日志已經打出來了，只需要全局搜 Load the cache of ，就能找到唯一一個類目樹打日志的地方，再往上倒著找調用棧。會發現 類目屬性 和 類目屬性值 這兩個存儲是懶加載的。只有切完包之后，第一次請求讀取類目的屬性及屬性值，才會觸發  通過mmap的方式將store文件映射到Java進程的一段連續虛擬地址，并把數據從磁盤讀上內存的動作。

核心代碼:

MappedByteBuffer mappedBuffer = storeFile.getFileChannel().map(MapMode.READ_ONLY, segmentPosition, segmentSize); // 創建mmap映射
mappedBuffer.load(); // 把數據讀上內存
Buffer buffer = FixedByteBuffer.wrap(mappedBuffer);
this.bufferCacheArray[t] = new BufferCache(buffer, ((t == 0) ? meta.getHeaderSize() : 0), blockCountThisSegment, meta.getBlockSize());
for (int i = ((t == 0) ? 0 : blockIdFlags[t - 1]); i < blockIdFlags[t]; i++) {
       getReadBlock(i); // 提前創建 blockId -> block buffer的映射
}

因此，加載完成后的日志自然是在業務線程池打的。

Page Fault的“威力”

問題2就不好回答了。因為有一個十分明顯的矛盾點： 本次Store加載是在業務線程池加載，對所有Future都只等待1s，1s加載不完立刻就返回了，不可能有8s的耗時。而且機器已經是16G容器，又沒有FGC導致的STW。 那就只有進程級別的hang會影響到多個線程了。

為了確認是否存在進程hang，筆者再次去看自適應的cpu-sampling日志。不看不知道，一看嚇一跳：

20ms采樣一次CPU并打日志的線程也被hang住了！整整到了01:38:27才恢復日志打印。而這段時間正好是store在load的時間，也和接口超時時間吻合

那基本只有一種可能，那就是 第一次讀取mmap映射虛擬地址段的數據時，因為數據在硬盤里，還沒在內存上，會觸發page fault，使得JVM進程陷入內核態，執行從磁盤加載數據到內存的page fault handler，導致進程掛起直到回到用戶態 。

參考 《Understanding the Linux kernel》一書 9.4.2 節 Handling a Faulty Address Inside the Address Space。其中有一段話是這么寫的：

The handle_mm_fault( ) function returns VM_FAULT_MINOR or VM_FAULT_MAJOR if it succeeded in allocating a new page frame for the process. The value VM_FAULT_MINOR indicates that the Page Fault has been handled without blocking the current process; this kind of Page Fault is called minor fault.

The value VM_FAULT_MAJOR indicates that the Page Fault forced the current process to sleep (most likely because time was spent while filling the page frame assigned to the process with data read from disk); a Page Fault of the current process is called a major fault.

The function can also return VM_FAULT_OOM (for not enough memory) or VM_FAULT_SIGBUS (for every other error).

關注加粗的部分，在處理內存page fault事件時，如果出現了Major Page fault，那么這種Page fault會強制使得當前進程休眠（基本上發生在在需要把數據從磁盤讀到進程地址空間內的頁塊這種耗時場景下）。

再看 MappedByteBuffer#load() 方法Javadoc:

可以看到，Javadoc上寫明：Invoking this method may cause some number of page faults and I/O operations to occur.調用這個方法很可能會產生一些page fault。

那么，只要確認在load store的過程中，JVM進程產生了大量的Major Page Fault, 就能解釋清楚為什么會出現跨多線程Hang的的情況了。

這里筆者主要使用兩個命令: pmap? 和  sar 。

pmap能夠展示進程的所有連續地址空間，通過查看地址空間的文件引用情況，以及RSS列的值，可以表明當前連續內存空間中有多少個頁面被進程引用。

在日常機器上復現場景，可以看到，在執行load store方法之前，當前進程沒有引用到任何有關類目文件的虛擬地址空間。

調用查詢屬性及屬性值的方法后，可以看到

類目樹的屬性、屬性值store被加載上來，且RSS值 == KBytes，說明整個文件都被讀到了內存里。

還有一個重要的抓手是 sar? 命令。 sar 命令可以以指定的采樣率去采樣當前整個操作系統的Page Fault發生指標。

可以看到，initCache過程中，觸發了大量的major page fault，同時筆者連接到服務器上的Arthas命令行也hang死無任何反應。進一步驗證了上述情況。

Arthas的命令行底層是termd庫，純Java實現。而Arthas又是以java agent的形式附加到目標JVM上的，如果連Arthas的控制臺輸入命令都沒有回顯了，基本上只有JVM進程整體Hang死一種可能，該現象也進一步驗證了上文提及的進程陷入內核態Hang死的假設。

那為什么會hang住好幾秒的時間？通過測量線上容器的IO速度，發現容器的磁盤讀寫速度在100MB左右，而類目屬性值的store文件非常大，達到1.7G。加載一遍這個文件非常耗時。

至此，我們終于可以給出結論。

結論

結構化應用夜間類目客戶端推包完成新老數據包版本切換后，存儲類目屬性及屬性值的數據不會立即加載到內存。會等到第一個查詢類目屬性、屬性值的請求到來才會懶加載數據到內存。由于類目屬性值store非常大，達到1.7個G。在把1.7G數據整體加載到內存的過程中觸發大量Major Page Fault，導致進程進入內核態處理缺頁異常。而由于業務容器IO性能較差，完整讀取文件十分耗時，最終導致Java進程hang住十幾秒的現象。

最終解法

帶著問題去咨詢類目服務相關同學，他們給出的建議是升級到最新版本的客戶端。筆者對比了新老版本客戶端的代碼，主要有兩處改進。

1. 在切包之前，會去load一把store，而不是等到請求進來再懶加載。

2. load store的時候，不是一口氣load整個文件，而是把文件切分為64M的小塊，每次load 64M，然后sleep一會。再繼續load下一塊，避免一次性load超大文件塊導致進程長時間處于內核態無法對外提供服務。

回過頭來思考一些前文提出的問題。既然接口超時是主要是加載大文件引起的，那升16G容器還有必要嗎？

筆者認為還是有必要的。原因有兩點

1. 現在新版的類目客戶端會在切版本、釋放老包資源（包括虛擬地址空間）之前先load一把store，雖然store在堆外內存，但是仍然需要占用進程的地址空間，而且實際上還是需要把數據讀上內存。因此在切包過程中，從整個Java進程視角來看，確實是會產生double的store空間占用。而目前一個類目store就要1.7G了，兩份就是3.4G。還有4G的空間劃分給了JVM的堆。剩下不到1G的內存空間，8G容器內存非常吃緊，很容易在切包過程中，load新store的時候產生容器OOM導致容器被殺。

2. 雖然store數據都是存在堆外的，但是store的一些索引對象和元數據還是存在堆里面的，大約占用堆6-700M空間。而無論是新版還是舊版的類目客戶端，索引都是在切包之前build的。因此在構建新包索引的時候，峰值也會產生2倍的 堆內空間占用 ，很容易堆內存不足產生YGC甚至FGC。

總結

一個看上去表象非常像GC引起的接口超時，底層卻隱藏著更深層次的原因。通過這個案例，也提醒我們，作為技術人，遇到問題，無論表象多么明顯，和之前遇到過的場景多么相似，都需要避免被所謂經驗蒙蔽雙眼、先入為主的壞習慣。大膽推斷，小心論證。多問一些為什么，才能一步一步的接近真相。