1. 現象
某天突然收到運維告警訊息,反饋產線有介面在某一段時間慢了,隨之效能優化的JIRA任務也開過來了,大致內容如下:
API告警 - Base Tomcat Accesslog:
微服務: xxxapi
介面: /xxxx/xxx POST
在 [ 2022/xx/xx 10:42:00 ~ 10:43:00 ] 時間視窗,RT > 閾值(300ms) 發生 141 次。
公司內部對API的響應時間要求是低於300ms,超過的都屬於有效能問題的介面,接下來就排查吧。
2. 排查
2.1. 查監控平臺:介面速度
首先就去檢視公司的API監控平臺,確認這個介面的確在這段時間的確在響應速度上,有100多次超過300ms。
不過發現幾個有意思的現象:
- 在那段時間前後,該介面都很正常,所以應該只是那段時間發生了什麼。
- 不只是那一個介面超過300ms了,其實那段時間內,也有個別其他介面超過閾值。只不過因為那個介面的併發比較高,很明顯的被告警機制檢測出來。
2.2. 查監控平臺:全鏈路日誌
雖然上面發現,可能不只是那一個介面的問題,但還是要仔細分析一下那個介面的全鏈路日誌。
通過呼叫鏈路圖,可以明顯的發現,主要的耗時都在redis命令的執行階段。又找了那段時間,其他的幾個介面,結果都是一樣的。
接下來就應該看看對應介面的程式碼,是不是執行redis命令時,有什麼影響效能的問題。
2.3. 分析程式碼
找到對應介面的程式碼,程式碼中唯一用到redis的命令是 HMGET key field1 [field2]
,分析後排除該程式碼的問題:
- 程式碼中就那一次的redis呼叫,
HMGET
不是耗時的命令(不在後文 O(n)命令之列),且field
的數量是可列舉的,最多也就幾十個,不會有多耗時。 - 該介面因為之前預計到併發高,所以上線之前經過壓測,上萬QPS完全不成問題,不會在這裡栽跟頭。
2.4. 查監控平臺:redis連線池
排除了程式碼層面上該介面的問題,那隻能從運維側看看執行redis命令慢的問題了,正好監控平臺上有mysql、redis連線池的監控。不看不知道,一看嚇一跳。
在出問題時間段,redis連線數瞬間飆升,直接超過了最大空閒連線數。在時間節點上,和產線出現慢響應的時間完全吻合。
可以推測出,這段時間可能執行了某些奇怪的命令,造成了redis阻塞,其他redis請求只能頻繁的建立新的連線,從而導致redis連線池中連線數飆升。
想要推測那段時間redis經歷了什麼,只能託付於運維的同事了。
2.5. 運維:查redis慢請求
通過從運維同事匯出來的,那段時間redis執行過的慢請求日誌,果然和預想的一樣。那段時間執行了大量的慢請求命令,尤其是一段 lrange
命令,每次執行時間都超過了300ms,一分鐘執行了幾百次。
通過具體的redis命令,倒推找到了對應的程式碼,該程式碼對應的其實是一段對應使用者登入後,通過MQ非同步重新整理使用者許可權的邏輯。因為是非同步消費,所以就算執行的慢,也並不會因為響應時間閾值而被告警。
再結合 ELK 中有關該介面的呼叫日誌,可以還原出問題發生的完整過程。
2.6. 場景還原
該 lrange
命令單獨執行還行,可那段時間在產線有大批量使用者的登入併發,導致該慢請求命令阻塞住了redis,大量redis請求都在阻塞排隊,redis連線池中連線數也在不斷擴充套件。
所以說,那段時間所有的redis請求命令,都會因為阻塞而延遲執行完成。告警的那個介面屬於“躺槍”,因為它呼叫的併發高,所以表現顯著,被告警程式當典型抓住了。
如果沒有這一步步排查,很難相信一個API的告警,是由於另外一個毫無關係的API影響的。
3. 解決
3.1. 解決
lrange
是時間複雜度為 O(n) 的命令,原則上是不應該被頻繁呼叫的。分析程式碼上下文邏輯,其實只是為了全量儲存和讀取 List 型別資料。完全可以用redis中的 String 代替 List。
對於redis 中 keys *
、flushdb
、flushall
等超耗時的命令,可以直接作為禁用命令,維護進 redis.conf
的禁用命令清單中。
但像 lrange
這種可以用,但要嚴格審視應用場景的命令,就需要研發人員特別注意。下面整理了一下redis常見的 O(n) 命令。
3.2. O(n) 命令
- String: MSET、MSETNX、MGET
- List: LPUSH、RPUSH、LRANGE、LINDEX、LSET、LINSERT
- Hash: HDEL、HGETALL、HKEYS/HVALS
- Set: SADD、SREM、SRANDMEMBER、SPOP、SMEMBERS、SUNION/SUNIONSTORE、SINTER/SINTERSTORE、SDIFF/SDIFFSTORE
- Sorted Set: ZADD、ZREM、ZRANGE/ZREVRANGE、ZRANGEBYSCORE/ZREVRANGEBYSCORE、ZREMRANGEBYRANK/ZREMRANGEBYSCORE
3.3. 其他
因為Spring中 Lettuce 連線池的bug,公司要求都改回 Jedis 連線池。感覺在該問題的避免上,Jedis 連線池應該也有優化空間。待後續實踐後再分享。