记一次线上由redis导致的node服务不可用的过程

一， 故障现象

17年新年之后第一天上班，就接到运维通知，线上有一个nodejs项目疑似有内存泄漏。 如下图所示：

集群中不正常的nodejs内存使用量

心里顿时一惊，春节放假的时候项目还运行得好好的，并且春节期间并没有上线过什么新的功能，怎么突然就内存泄漏了呢。正要试图去分析研究一下nodejs怎么查内存泄漏，运维又告知我们使用的一个redis，io流量高得不正常。

通过zabbix对此机器io的监控发现流量飙升已经好几天了。

zabbix IO监控

于是查看了项目的监控，这里说一下我们项目使用了基调网络的听云监控，发现此nodejs项目内存飙升与redis的io流量飙升在时间上几乎一致。于是觉得这两者可能有什么关系。另外，还有别的应用直接出现了数据在页面上展示有延迟的现象，我们查到其中一个kafka的消费者消费能力下降了许多，有许多消息堆积了，导到部分业务数据更新延迟，已经有bug上报了。而这个kafka消费者也是需要往此redis中写数据的，直觉告诉我们这个redis有问题。

二，故障排查过程

上面的故障主要有3个部分，我们项目的结构简化之后大概如下：

项目结构

1. ruby项目写数据库，同时产生一条消息，推送到kafka队列中
2. java service项目，消费kafka消息，同时从database中查询数据，写入redis中
3. nodejs项目强依赖于redis，从redis中取数据，进行页面渲染

我们把上面的结构理清楚了，但排查过程却并不顺利。

1. 回滚项目： 首先，我们查看了离用户最近的问题，kafka消费延迟导到页面数据更新延迟，我们发现其中有几个消费线程几乎不消费数据，于是找运维使用了重启大法，但重启之后不久，又有消费线程被阻塞。我们回想起春节之前有更新过kafka消费者相关的一个功能，于是我们决定将java service项目进行回滚。回滚之后，发现消费者线程已经能顺利消费kafka数据，数据延迟问题解决。但redis飙升的io流量并没有降低，nodejs的内存和cpu使用量也并没有下降。

2. 从现象逆向分析： 经过上面的分析以及回滚，此时已经是下午了。但io流量居高不下，以及nodejs的cpu和内存使用量并没有下降，使得我们一时陷入了困境。此时我们发现有一个依赖于nodejs提供http接口的应用，数据一直刷不出来，于是我们对此应用进行了抓包，找到http请求的参数，准备从参数进行分析。这里顺利说明一下，此接口是按一堆商品id，返回商品各种属性，redis中也是按商品Id，使用一个redis的hash存储商品不同的属性的。我们将此接口参数中的商品Id拿出来，一个一个直接从redis中去查询。这个笨办法居然奏效了，我们发现有一个商品id，从redis中查出来了一个巨大的hash，进一步分析，发现此商品id对应的redis hash中有一个key的值特别长，目测应该有好几M，从redis中查询此hash，差不多要半分钟才会返回数据，由于我们在nodejs中读取redis时有超时设置，所以此接口基本上都不会返回数据了。我们将此大hash的key删除，接口马上就可以正常返回数据了。

3. 临时解决： 至此我们已经可以确定，redis中可能还存在此类超大的hash，这种hash极大的影响了redis的查询，导到了许多业务商品都展示不出来。现在我们能确定的是通过回滚java service项目，现在已不会再往redis中写入这类巨大的hash。但redis中究竟有多少这种大hash，一时无法确定，而且redis中key的数量超过100w，于是我们写了一个脚本使用scan命令，对redis中的数据进行扫描，将这类大hash扫描出来。脚本写出来，已经很晚了，但脚本需要跑很长时间，好在此时大部分接口可以正常返回数据，并且nodejs的内存使用量以及cpu已经下降。于是我们让脚本继续跑，等第二天来查看脚本跑的结果。

4. 解决redis高io流量: 第二天，脚本顺利的跑完，将超级大的hash全部找出来，大概有1W多个，于是直接将这些key删除掉。一分钟之后，zabbix显示redis的流量已经开始下降了：
   

   zabbix IO下降

三、定位问题，彻底解决问题

上面的处理只是初步解决了线上的问题，但回滚的代码还未处理。另外，是什么原因导到了redis中存在巨大的hash。因为已知道redis hash中具体哪个Key存在问题，很容易就查找到写入此数据的代码。此数据是通过商品id，查询了另一张与商品关键的表（1 : N)。我们发现在此表中同一个id下有许多数据完全一样的记录，在java service项目写入redis时，这些重复的记录会被全部查出来，写入redis。此功能也正好是春节前一天上线的。解决办法很简单： 删除掉此表中重复的记录；表中增加唯一索引，以保证不会出现重复记录；重新刷新redis中存在问题的数据；解决了数据重复的问题，回滚的代码也可以重新上线了。至此问题彻底解决！

四、总结

这次遇到的问题，虽然并不是特别严重，但排查时间拖得有点长，耗费了1天半，3个以上同事一起解决，现在回过头来，发现有一些排查的时候忽略的细节，正是这个原因导到排查时间拖得很长。

1. 线上项目出问题，最大的嫌疑是最近的代码更新。有数次这样的事情出现了，一开始觉得和最近的更新不可能有关系，但进一步分析之后，最终还是定位于最近更新的代码。所以个人觉得出问题的时候，最好是先从最近的改动开始分析。

2. 此问题其实可以通过redis slowlog看出原因的，但因为我们使用了cluster集群，当时只看了其中的一部分，没有直观的看出问题来，就放弃了，错过了发现问题的机会。

3. 正确的分析问题： 有时候出问题了，一下找不到方向，匆匆忙忙到处看日志、看监控，发现这里不正常，那里也不正常，很容易陷入盲目。其实我们这个问题，3个现象，都直指redis，redis本身的io流量非常高，那么通常来说，有两种可能，一是访问量增加了好几倍，二是传输的数据量增加了好几倍。春节期间网站的访问量一般会降低，我们通过监控也看到项目的请求量其实是下降了的。那么最大的可能就是数据量增加了，这样直接查看redis中是否存在大key，就很容易发现问题了。

4. 问题的最终原因是我们数据表中存在重复的记录，其实我们的代码规范中有明确规定： 业务上要求唯一的记录，一定要在数据库建立唯一索引。不能靠代码来保证唯一性，但这次上线的代码并没有建立唯一索引。

   这里说一下，由于redis是单线程的，存在大key是非常容易影响redis性能的，一次查询需要耗费数秒乃至于数十秒，那么别的读写操作都被阻塞了，所以kafka的消费线程会不断的卡死。同样，nodejs强依赖于redis，所有的请求都阻塞了，阻塞的请求会保存其上下文环境，阻塞的多了，内存量也就飙升了几倍。

后面附上扫描redis的脚本，时间有限，但解决了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