從解決Redis訪問超時的問題談起——故事比結果要精彩

從解決Redis訪問超時的問題談起——故事比結果要精彩 14575°C

做者：the5fire | 標籤： redis  slowlog  zrange  timeout  經驗  | 發佈：2015-01-17 3:47 p.m.

這周終於解決了Redis訪問常常超時的問題，終於能夠踏實睡覺了。從上週就開始糾結在這個問題上，能夠用寢食難安來形容，感受這個問題就像個定時炸彈同樣，雖然根據手搜的訪問量，極少的Timeout Error對用戶基本不會形成影響，可是這種問題若是不及時遏制致使Redis總體被拖慢形成的危害是至關嚴重滴！畢竟在手搜的架構中，Redis是極其重要的一環。

先來說個故事（說說問題上下文），有興趣來手搜工做的Python程序員認真聽：

前段時間咱們新上了個業務，爲了知足需求咱們對進程級的cache作了些改動，根據業務對cache key進行了拆分，致使的狀況是同一份數據會被緩存多份，只由於展現類型不一樣（可簡單理解爲不一樣的展現用的key不一樣，數據相同）。有經驗的同窗應該可以想到這麼作的結果會是怎麼樣的——同一份數據會請求兩次Redis（由於cache key不一樣）。(能夠看的出來，對於多種展現需求的業務在展現層作cache並不合適） 功能測試沒問題，so，上線。晚高峯來了。運維同窗和值班同窗被報警短信「轟炸」了，大量應用服務器端口訪問超時（Nagios監控）。由於那天只有咱們的改動上線了，因此能夠定位爲咱們代碼的問題。遂，備機上。 第二天看日誌發現大量的Redis的Timeout Error（timeout=1s），雖然日誌中在咱們這個系統上線以前就已經存在不少這種日誌，顯然咱們此次改動的上線加重了這一情況。

從直觀的感受上，咱們的功能致使Redis請求增多，所以這時就聚焦在如何較少Redis的請求上。 在分析了一個頁面的加載到底會請求多少次Redis以後發現一個很大的問題，由於針對具體業務的設計，一個頁面在加載時訪問Redis的次數跟頁面上展現的內容成正比。所以頁面上的內容越多，對Redis的請求會越頻繁，所以一次正常的頁面訪問極可能會產生100次甚至更多的Redis請求。 問題已經很明顯了，由於這種設計，必須徹底依賴本地緩存，無緩存狀況訪問頁面的速度是不可接受的。

知道問題在哪就好辦了，通過不斷的思考和嘗試，找到一種方案。減小頁面上的內容確定是不行的，那麼就只能合併請求了。

說了一大堆，其實問題的本質在於要把以前串行的Redis請求換成並行。另外值得一說的是Redis自己的響應是很是快的，另外還有一些時間消耗在網絡上。 串行換成並行的方案能夠簡單理解爲把以前的: GET 1, GET 2 換成: MGET 1 2 這樣。改完以後在無緩存的狀況下頁面加載速度幾乎提高了一倍。 OK，既然可行，那就測試，在測試，上線。Yeah！沒人被短信轟炸。

你覺得故事到這裏就結束了，那就太Naive了。Nagios監控只是用來看端口訪問是否符合預期的（1s內響應），並不能發現全部的問題。

上線幾天以後發現狀態碼爲500的狀況增多了，且波動很大。So，繼續看日誌（有人問，大家不是用Sentry嗎？爲毛看日誌？呃，內個，內個，業務調整...)。 我們仍是來看日誌吧，依然是大量的Timeout Error，仍是Redis的問題。依據上面的方案咱們已經徹底減小了Redis請求次數，爲什麼仍是慢。

有興趣的同窗能夠思考下，爲什麼仍是慢？以前的方案會形成哪一種影響。

喝口水，繼續講故事：（終於明白知乎上爲什麼常常有人講故事了，講故事原來比寫正經文章要容易）

爲什麼仍是慢呢？以前的改動至關因而把100次請求合併成1次，形成的影響是，雖然減小了網絡上的耗時，可是會增長Redis的耗時。假設以前每次請求讀10個key（mget），合併成1次請求就變成一次讀取1000個key。這塊多是問題緣由，那麼繼續定位吧。 要怎麼肯定呢？Redis並不熟，可是MySQL有Slowlog，Redis應該也有。因而找到了幾個命令:

CONFIG GET slowlog-log-slower-than  (10000us,Redis中的執行單位是微秒，至關於10ms）
CONFIG GET slowlog-max-len  （最多存儲128條慢日誌，應該是默認的吧？）
SLOWLOG LEN   (128, 靠，存滿了）
SLOWLOG GET   (默認去10條)

而後看到了慢日誌出現的頻率很是高！而且MGET命令中key的數量至關大——1w多（不是上面那個方案致使的），執行耗時在50ms左右。 好了，再次Get到問題所在，解決吧。 而後發現沒法從這個日誌上去找是哪一個項目產生的，由於Redis不記錄這個日誌產生的client ip。如今回憶知道是哪臺服務器發的請求也定位不到。由於這種錯誤的產生就不是正常業務邏輯代碼產生的。

具體調試過程簡單歸納爲：在全部可能產生巨量MGET請求前添加判斷，打印log到sentry（沒錯，咱們又上了Sentry服務），主要仍是在獲取列表的部分（其實最後查到問題的根源徹底跟列表不要緊），依然沒有捕獲到任何日誌。因而開始到Redis服務器tcpdump全部請求，定位到一臺服務器，至少知道了是哪一個項目產生的。而後就是運氣了，不斷的查看正常訪問日誌。終於發現了問題。太TMD走運了，那一刻都要哭了。這個結果徹底不在全部的預料狀況之中。

從MGET的key上能夠發現全部的新聞都是屬於某一個頻道，因此咱們的預期是這些請求必定是在訪問這些新聞所屬頻道列表頁面時產生的。最終發現跟列表頁面沒半毛錢關係。

看吧，這就是「大型」系統了，充滿了不可預測。這樣真的很差！

這個問題產生的緣由是某個頁面中有一部份內容是能夠指定獲取某頻道數據的，可是這部份內容又是存在Redis中的。好吧，以前徹底沒考慮到會有這種間接的請求。

知道具體問題了，順藤摸瓜，找到了對應的存在Redis中的內容，奇怪的是這部份內容沒有設置要從某個頻道獲取多少條數據。這個內容的模型大體是這樣的:

class Content:
    channel = int()
    data_size = int()

設置了頻道，沒設置要獲取的數量，默認是0。

故事結束，來看代碼。

假設個人這個blog系統用的是Redis，那麼怎麼處理某個頻道的分頁呢？由於是非關係型數據庫。所以在存儲數據的時候，我得這樣:

import redis

cache = redis.StrictRedis(host='localhost', port=6379)

for post in posts:
    cache.set('blog:post:%s:title' % post.id, post.title)

    cache.zadd('blog:channel:1'，time.time(), post.id)

這樣存下去若是我要從這個頻道（假設id爲1）下獲取十條數據:

start = 0
count = 10
post_ids = cache.zrange('blog:channel:1', start, start + count - 1)
post_tiltes = cache.mget(map(labda _id: 'blog:post:%s:title' % _id, post_ids))

這樣的代碼有問題嗎？

咋看之下沒有問題，由於redis的zset是從0開始計數的，獲取10個元素，那就是0到9。那麼看下這個描述:

Both start and stop are zero-based indexes, where 0 is the first element, 1 is the next element and so on. They can also be negative numbers indicating offsets from the end of the sorted set, with -1 being the last element of the sorted set, -2 the penultimate element and so on.

大意是，索引從0開始，-1表示最後的一個位置。所以若是你想獲取某個頻道（id爲1）的全部文章id就是這樣:

post_ids = cache.zrange('blog:channel:1', 0, -1)

由於-1表示最後一個元素的位置。

再回到上面故事的結尾，那塊內容要獲取的頻道新聞數量爲0，而咱們的代碼和我寫的相似，沒對這種-1可能性作判斷，所以一次就取出來頻道下的全部新聞，so，產生了那個結果。

總結時間

在複雜的業務下的複雜的系統結構中，要找到一個隱藏的問題確實不容易，由於寫代碼的人不斷的變化，負責業務的人也在不斷變化，最後都不知道這個業務爲什麼存在，是否還在使用，也不知道這段代碼是否正常，畢竟每一個人還在負責新的業務，不斷的添加新的代碼。這樣的結果就是系統進一步複雜，這樣下去的結果就是再通過幾年人員的變遷以後，任何一我的想要理解這個系統（這些系統）中的業務邏輯，代碼邏輯都將變的十分困難。

代碼應該是歷史的結果，不該該把歷史平鋪到代碼中，git log纔是歷史應該存在的地方。 說人話就是:業務的增長不只僅是增長代碼，有時也是要對現有結構進行抽象和重構。