RedisTemplate的踩坑現場

張偉帆（網易嚴選技術團隊）

RedisTemplate是Spring封裝的一個最常用的redis數據訪問工具類，功能強大，使用簡潔。但在RedisTemplate看似簡單的API下，也是暗流涌動，背後別有一番洞天。本文從一個線上性能問題入手，抽絲剝繭一步步探索RedisTemplate，挖出了RedisTemplate操作psetex命令的深坑。

一、背景

在之前的壓測過程中，商詳頁面RT居高不下，發現yx_malltech_user這個redis集羣的異常報警，起初是在業務沒有開啓分流讀的情況下，一個Redis集羣slave節點存在大量連接，佔用大量CPU資源，且導致redis主從斷掉等異常行爲。

dba分析後發現，從數據庫實時監控平臺，可以看到有大量的cluster命令產生，且這個請求一直存在，只是壓測流量過大，導致問題放大，單個cluster命令請求都是在30毫秒以上。都是打到隨機一個NODE節點上，導致這個節點cpu飆升。

然後DBA開始相應的處理，包括但不限於單獨隔離異常節點到獨立機器上，配置參數優化等，問題沒有根本解決。可以確定不是Redis服務端問題，應該是業務代碼端問題，需要從業務用法開始排查使用方式，看是如何觸發了大量的cluster命令。

6.9單壓商詳發現問題還是存在。開始我們的排查之路。

二、服務信息

• 涉及服務：yanxuan-app
• 涉及場景：商詳
• spring版本：4.0.8
• spring-data-redis版本：1.8.4.RELEASE
• jedis版本：2.9.0

三、分析過程

1. 監控觀察

既然是cluster命令異常過多，我們觀察下監控數據。
6.9號下午對於商詳的單壓

可以看到cluster命令確實過多，且耗時較長。從而影響其他正常get，set操作。

我們仔細觀察，發現異常的請求不僅僅是cluster，還是psetex。正常來講，我們操作緩存並不會直接使用psetex命令。單獨觀察下兩者。

下面兩張圖分別是 psetex命令與cluster命令的走勢圖，發現是一致的。基本可以確定psetex和cluster是有強關聯關係的。

pset如下

cluster如下

且cluster只打到 10.130.68.239:16379 這一臺機器上。

2. 代碼分析

從上面觀察得到，psetex命令和cluster命令基本同比例，且psetex命令請求量不少。而我們開發中，實際上並不會使用pset，我們都是redisTemplate.opsForValue().set()

這一點很奇怪，所以我們開始擼下代碼。

這裏面封裝了緩存邏輯，底層就是redisTemplate.opsForValue().set()方法，那我們進去redisTemplate源碼看下，它究竟偷偷做了啥。

在這個代碼裏面，我們就明白了psetex哪裏來的。如果你timeout使用的時間單元是ms，就會使用psetex，而其他就使用setex命令。感覺我們往前走了一步。但是psetex和cluster命令同比例爲啥呢？繼續看下。

這裏面會根據key去計算對應的槽所在節點。我們再進去topology方法裏瞧瞧。

看到這段代碼，真相就在眼前了。原來獲取集羣拓撲信息有一個緩存，失效時間100ms（這裏吐槽下，spring居然把緩存過期時間寫死了）。緩存失效，然後從cluster的clusternodes循環取節點去發送cluster nodes命令來更新拓撲信息。這裏就證明了cluste命令與psetex命令之間存在的關聯性了。緩存過期時間是100ms，必然引起頻繁的發起cluster nodes命令。通過和dba大大峯哥確認，確實在壓測過程中存在的大量cluster命令，就是cluster nodes命令。驗證了猜想。

四. 解決方法與驗證

1. 解決方法

解決方法很簡單：將設置緩存中使用毫秒作爲過期時間的代碼全都改成按秒級別來設置緩存。

只要改成秒級別，也就是使用setex，setex不會觸發cluster命令。避免使用psetex命令，帶來的頻繁cluster nodes命令。

2. 驗證

改完上線後，觀察監控。發現在上線過程中，明顯有下降的趨勢。

在平峯期表現，已經降到非常低了

最終的壓測驗證：

從壓測結果來看，表現也是非常良好。問題得以解決。

核心鏈路壓測中，整體商詳的MRT也從之前100ms+降到66ms。

五. 總結與思考

1. 總結

這個問題比較有意思，罪魁禍首居然是一個時間單元。在於使用了 1000ms 和 1s 理論上應該是一樣的，絕大部分人並不會去關心。然而spring底層留下了這麼一個用法上的坑，導致了問題在大流量壓測下的出現。一個小小的區別帶來了巨大的影響。

而我們對於緩存的過期時間其實沒必要精確到毫秒級別的，所以直接改成秒級別即可。

2. 思考

PSETEX和SETEX除了過期時間的精度問題，並沒有本質的區別。

所以spring提供了根據時間單元來區別使用setex和psetex，而接口沒有顯示體現。我個人覺得這是spring接口設計一個不合理的地方。雖然是爲了方便開發者要屏蔽細節，可是底層的邏輯並不是完全一樣（不是隻是發送不同命令而已）。而是有獲取cluster nodes等命令邏輯，是兩套邏輯。對於我們開發設計暴露出去的接口和方法也是一種警醒。一個接口，方法應該保證用戶便於理解，不能有二義性。否則就得拆分多個接口，讓用戶選擇，不給用戶留坑。

後續優化措施：

• 梳理出一個版本的最佳實踐，然後規範框架的使用版本。比如spring-data-redis1.x版本就統一使用1.8.4，然後有對應的最佳實踐；2.x版本就統一使用2.2.4，也有對應的最佳實踐。這樣子可以避免踩重複的坑，能站在巨人的肩膀上看的更遠。
• 建立規範的CodeReview機制。通過多人的代碼review以及不同人的經驗，可能發現一些隱藏的坑。避免上線後出現問題。

六. 番外

1. 爲什麼cluster命令會總是打到某一個節點上呢？

前面我們說到，還有一個問題點，cluster命令總是打到某一臺節點上，導致這個節點cpu使用率飆升。

原因還是出在下面Spring-data-redis的這段代碼上:

for循環遍歷所有節點，從第一個開始發送nodes命令，如果得到返回，就直接返回了。而我們節點信息一般情況下都是不變的。因此entrySet的順序也不會改變，Cluster Nodes命令就會一直髮送到同一個節點上。

在網上資料查到，這個bug已經官方修復了。https://jira.spring.io/browse/DATAREDIS-890在2.1.3版本發佈了。

2. Cluster nodes命令爲啥會很慢呢？

嗯，這個就是直接摘抄網上資料了。

答案在下圖，CLUSTER_SLOTS常量等於16384，因此redis每次都要循環很多次去組裝每個節點的slot信息。CPU至少需要循環16384乘以N次，N爲redis集羣master的個數。因此，隨着redis集羣規模的擴大、以及客戶端節點數的增加，NODES命令打滿CPU的問題會越來越嚴重。

redis系統命令NODES的性能問題，在2018年已經有反饋給redis官方：https://github.com/antirez/redis/issues/5574

3. PSETEX命令的使用場景？

https://redis.io/commands/psetex查看了redis官方對於PSETEX命令的說明

PSETEX works exactly like SETEX with the sole difference that the expire time is specified in milliseconds instead of seconds.

PSETEX和SETEX除了過期時間的精度問題，並沒有本質的區別。
所以我個人理解，psetex應該是用在對於過期時間的精度要求較高的場景吧。

此次問題的定位排查，感謝dba大大在服務端做了大量的優化，且提供了非常好的分析方向，才能很快且明確的從業務代碼上進行排查。在業務代碼的排查過程中，離不開文淵。十分感謝！！！

網易技術熱愛者隊伍持續招募隊友中！網易嚴選，因爲熱愛所以選擇， 期待志同道合的你加入我們， Java開發簡歷可發送至郵箱：[email protected]