記一次線上由redis導(dǎo)致的node服務(wù)不可用的過程

一， 故障現(xiàn)象

17年新年之后第一天上班，就接到運(yùn)維通知，線上有一個(gè)nodejs項(xiàng)目疑似有內(nèi)存泄漏。 如下圖所示：

集群中不正常的nodejs內(nèi)存使用量

心里頓時(shí)一驚，春節(jié)放假的時(shí)候項(xiàng)目還運(yùn)行得好好的，并且春節(jié)期間并沒有上線過什么新的功能，怎么突然就內(nèi)存泄漏了呢。正要試圖去分析研究一下nodejs怎么查內(nèi)存泄漏，運(yùn)維又告知我們使用的一個(gè)redis，io流量高得不正常。

通過zabbix對(duì)此機(jī)器io的監(jiān)控發(fā)現(xiàn)流量飆升已經(jīng)好幾天了。

zabbix IO監(jiān)控

于是查看了項(xiàng)目的監(jiān)控，這里說一下我們項(xiàng)目使用了基調(diào)網(wǎng)絡(luò)的聽云監(jiān)控，發(fā)現(xiàn)此nodejs項(xiàng)目?jī)?nèi)存飆升與redis的io流量飆升在時(shí)間上幾乎一致。于是覺得這兩者可能有什么關(guān)系。另外，還有別的應(yīng)用直接出現(xiàn)了數(shù)據(jù)在頁(yè)面上展示有延遲的現(xiàn)象，我們查到其中一個(gè)kafka的消費(fèi)者消費(fèi)能力下降了許多，有許多消息堆積了，導(dǎo)到部分業(yè)務(wù)數(shù)據(jù)更新延遲，已經(jīng)有bug上報(bào)了。而這個(gè)kafka消費(fèi)者也是需要往此redis中寫數(shù)據(jù)的，直覺告訴我們這個(gè)redis有問題。

二，故障排查過程

上面的故障主要有3個(gè)部分，我們項(xiàng)目的結(jié)構(gòu)簡(jiǎn)化之后大概如下：

項(xiàng)目結(jié)構(gòu)

1. ruby項(xiàng)目寫數(shù)據(jù)庫(kù)，同時(shí)產(chǎn)生一條消息，推送到kafka隊(duì)列中
2. java service項(xiàng)目，消費(fèi)kafka消息，同時(shí)從database中查詢數(shù)據(jù)，寫入redis中
3. nodejs項(xiàng)目強(qiáng)依賴于redis，從redis中取數(shù)據(jù)，進(jìn)行頁(yè)面渲染

我們把上面的結(jié)構(gòu)理清楚了，但排查過程卻并不順利。

1. 回滾項(xiàng)目： 首先，我們查看了離用戶最近的問題，kafka消費(fèi)延遲導(dǎo)到頁(yè)面數(shù)據(jù)更新延遲，我們發(fā)現(xiàn)其中有幾個(gè)消費(fèi)線程幾乎不消費(fèi)數(shù)據(jù)，于是找運(yùn)維使用了重啟大法，但重啟之后不久，又有消費(fèi)線程被阻塞。我們回想起春節(jié)之前有更新過kafka消費(fèi)者相關(guān)的一個(gè)功能，于是我們決定將java service項(xiàng)目進(jìn)行回滾?；貪L之后，發(fā)現(xiàn)消費(fèi)者線程已經(jīng)能順利消費(fèi)kafka數(shù)據(jù)，數(shù)據(jù)延遲問題解決。但redis飆升的io流量并沒有降低，nodejs的內(nèi)存和cpu使用量也并沒有下降。

2. 從現(xiàn)象逆向分析： 經(jīng)過上面的分析以及回滾，此時(shí)已經(jīng)是下午了。但io流量居高不下，以及nodejs的cpu和內(nèi)存使用量并沒有下降，使得我們一時(shí)陷入了困境。此時(shí)我們發(fā)現(xiàn)有一個(gè)依賴于nodejs提供http接口的應(yīng)用，數(shù)據(jù)一直刷不出來，于是我們對(duì)此應(yīng)用進(jìn)行了抓包，找到http請(qǐng)求的參數(shù)，準(zhǔn)備從參數(shù)進(jìn)行分析。這里順利說明一下，此接口是按一堆商品id，返回商品各種屬性，redis中也是按商品Id，使用一個(gè)redis的hash存儲(chǔ)商品不同的屬性的。我們將此接口參數(shù)中的商品Id拿出來，一個(gè)一個(gè)直接從redis中去查詢。這個(gè)笨辦法居然奏效了，我們發(fā)現(xiàn)有一個(gè)商品id，從redis中查出來了一個(gè)巨大的hash，進(jìn)一步分析，發(fā)現(xiàn)此商品id對(duì)應(yīng)的redis hash中有一個(gè)key的值特別長(zhǎng)，目測(cè)應(yīng)該有好幾M，從redis中查詢此hash，差不多要半分鐘才會(huì)返回?cái)?shù)據(jù)，由于我們?cè)趎odejs中讀取redis時(shí)有超時(shí)設(shè)置，所以此接口基本上都不會(huì)返回?cái)?shù)據(jù)了。我們將此大hash的key刪除，接口馬上就可以正常返回?cái)?shù)據(jù)了。

3. 臨時(shí)解決： 至此我們已經(jīng)可以確定，redis中可能還存在此類超大的hash，這種hash極大的影響了redis的查詢，導(dǎo)到了許多業(yè)務(wù)商品都展示不出來?，F(xiàn)在我們能確定的是通過回滾java service項(xiàng)目，現(xiàn)在已不會(huì)再往redis中寫入這類巨大的hash。但redis中究竟有多少這種大hash，一時(shí)無法確定，而且redis中key的數(shù)量超過100w，于是我們寫了一個(gè)腳本使用scan命令，對(duì)redis中的數(shù)據(jù)進(jìn)行掃描，將這類大hash掃描出來。腳本寫出來，已經(jīng)很晚了，但腳本需要跑很長(zhǎng)時(shí)間，好在此時(shí)大部分接口可以正常返回?cái)?shù)據(jù)，并且nodejs的內(nèi)存使用量以及cpu已經(jīng)下降。于是我們讓腳本繼續(xù)跑，等第二天來查看腳本跑的結(jié)果。

4. 解決redis高io流量: 第二天，腳本順利的跑完，將超級(jí)大的hash全部找出來，大概有1W多個(gè)，于是直接將這些key刪除掉。一分鐘之后，zabbix顯示redis的流量已經(jīng)開始下降了：
   

   zabbix IO下降

三、定位問題，徹底解決問題

上面的處理只是初步解決了線上的問題，但回滾的代碼還未處理。另外，是什么原因?qū)У搅藃edis中存在巨大的hash。因?yàn)橐阎纑edis hash中具體哪個(gè)Key存在問題，很容易就查找到寫入此數(shù)據(jù)的代碼。此數(shù)據(jù)是通過商品id，查詢了另一張與商品關(guān)鍵的表（1 : N)。我們發(fā)現(xiàn)在此表中同一個(gè)id下有許多數(shù)據(jù)完全一樣的記錄，在java service項(xiàng)目寫入redis時(shí)，這些重復(fù)的記錄會(huì)被全部查出來，寫入redis。此功能也正好是春節(jié)前一天上線的。解決辦法很簡(jiǎn)單： 刪除掉此表中重復(fù)的記錄；表中增加唯一索引，以保證不會(huì)出現(xiàn)重復(fù)記錄；重新刷新redis中存在問題的數(shù)據(jù)；解決了數(shù)據(jù)重復(fù)的問題，回滾的代碼也可以重新上線了。至此問題徹底解決！

四、總結(jié)

這次遇到的問題，雖然并不是特別嚴(yán)重，但排查時(shí)間拖得有點(diǎn)長(zhǎng)，耗費(fèi)了1天半，3個(gè)以上同事一起解決，現(xiàn)在回過頭來，發(fā)現(xiàn)有一些排查的時(shí)候忽略的細(xì)節(jié)，正是這個(gè)原因?qū)У脚挪闀r(shí)間拖得很長(zhǎng)。

1. 線上項(xiàng)目出問題，最大的嫌疑是最近的代碼更新。有數(shù)次這樣的事情出現(xiàn)了，一開始覺得和最近的更新不可能有關(guān)系，但進(jìn)一步分析之后，最終還是定位于最近更新的代碼。所以個(gè)人覺得出問題的時(shí)候，最好是先從最近的改動(dòng)開始分析。

2. 此問題其實(shí)可以通過redis slowlog看出原因的，但因?yàn)槲覀兪褂昧薱luster集群，當(dāng)時(shí)只看了其中的一部分，沒有直觀的看出問題來，就放棄了，錯(cuò)過了發(fā)現(xiàn)問題的機(jī)會(huì)。

3. 正確的分析問題： 有時(shí)候出問題了，一下找不到方向，匆匆忙忙到處看日志、看監(jiān)控，發(fā)現(xiàn)這里不正常，那里也不正常，很容易陷入盲目。其實(shí)我們這個(gè)問題，3個(gè)現(xiàn)象，都直指redis，redis本身的io流量非常高，那么通常來說，有兩種可能，一是訪問量增加了好幾倍，二是傳輸?shù)臄?shù)據(jù)量增加了好幾倍。春節(jié)期間網(wǎng)站的訪問量一般會(huì)降低，我們通過監(jiān)控也看到項(xiàng)目的請(qǐng)求量其實(shí)是下降了的。那么最大的可能就是數(shù)據(jù)量增加了，這樣直接查看redis中是否存在大key，就很容易發(fā)現(xiàn)問題了。

4. 問題的最終原因是我們數(shù)據(jù)表中存在重復(fù)的記錄，其實(shí)我們的代碼規(guī)范中有明確規(guī)定： 業(yè)務(wù)上要求唯一的記錄，一定要在數(shù)據(jù)庫(kù)建立唯一索引。不能靠代碼來保證唯一性，但這次上線的代碼并沒有建立唯一索引。

   這里說一下，由于redis是單線程的，存在大key是非常容易影響redis性能的，一次查詢需要耗費(fèi)數(shù)秒乃至于數(shù)十秒，那么別的讀寫操作都被阻塞了，所以kafka的消費(fèi)線程會(huì)不斷的卡死。同樣，nodejs強(qiáng)依賴于redis，所有的請(qǐng)求都阻塞了，阻塞的請(qǐng)求會(huì)保存其上下文環(huán)境，阻塞的多了，內(nèi)存量也就飆升了幾倍。

后面附上掃描redis的腳本，時(shí)間有限，但解決了cluster下無法直接使用scan的問題：

redis_configs = [] #cluster redis configs, '127.0.0.1:6379'
redises       = redis_configs.inject({}){|h, config| h[config] = Redis.new(url: "redis://#{config}"); h }
file          = File.open(File.join(Rails.root, 'log', 'scan_result.log'), 'w')
max_size      = 2000
long_field    = 'field'
key_partten   = "xxx:json:*"

def write_log(redis, key)
  data = redis.hget(key, long_field)
  if data.to_s.size > max_size
    file.puts key
  end
end

redises.each do | k, redis |
  current_cursor = 0
  begin
    current_cursor, keys = redis.scan(current_cursor, match: key_partten, count: 300)
    if keys.present?
      keys.each do |key|
        puts key
        begin
          write_log(redis, key)
        rescue => e
          if e.message.start_with?('MOVED')
            k = e.message.split(' ').last
            r = redises[k]
            write_log(r, key) if r.present?
          else
            puts "#{key} => #{e.message}"
          end
        end
      end
    end
  end while current_cursor.to_i != 0
end