关于redis:Redis『慢查询』分析

问题起源

  顶峰盯盘期间，通过 kibana 查问发现不定时存在一些 redis 慢查问日志（客户端日志）；而且目前我的项目中记录 redis 慢查问日志的门限默为 300ms。这种不知起因且不定时的慢查问是十分危险的。

  注 1：redis server 实例配置的 slow log 门限为 10ms，并且存在慢查问报警。

  注 2：客户端与 redis 之间还存在 Twemproxy 代理（以下简称 tw）。

  注 2：客户端为 Golang 服务，与 tw 之间是长连贯，基于连接池实现。

【案例 1】客户端问题排查

  2020.07.29 18:19:21 左右，呈现一小波 redis 慢查问日志。

  分析表明：

• redis 并没有慢查问报警；
• tw 监控表明过后申请的 ops 没有显著变动；
• 客户端同时刻所有的慢查问日志都在一台机器；
• tw 与 redis 监控的 cpu 负载等指标没有显著异样；
• tw 客户端连接数同时刻有突增；

  联合以上景象有以下几个狐疑点：

  1）tw 代理导致的慢查问？那这样同时刻的慢查问应该比拟平均的散布到多台客户端机器，只存在一台机器并不是很正当；

  2）redis 连接池导致的，连接池通常会存在最大连接数的限度，而 tw 监控表明客户端连接数同时刻存在突增状况；

  我的项目中 redis 客户应用的是 github.com/go-redis/redis，连接池相干配置定义在 redis.Options 构造：

type Options struct {
    PoolSize int
    // 连接池大小，即最大连接数
    
    PoolTimeout time.Duration
    // 获取连贯超时工夫，当连接池所有连贯都被占用，最大等待时间；// 默认为 ReadTimeout+ 1 秒
    
    IdleTimeout time.Duration
    // 连贯闲暇超时工夫，长时间闲暇的连贯会被客户端被动开释；}

  可能『卡住』的中央就是获取连贯了，代码逻辑参照 pool.(*ConnPool).Get：

select {case p.queue <- struct{}{}:
    default:
        timer := timers.Get().(*time.Timer)
        timer.Reset(p.opt.PoolTimeout)

        select {case p.queue <- struct{}{}:
            if !timer.Stop() {<-timer.C}
            timers.Put(timer)
        case <-timer.C:
            timers.Put(timer)
            atomic.AddUint32(&p.stats.Timeouts, 1)
            return nil, false, ErrPoolTimeout
        }
    }

  p.queue 通道大小等于 poolsize，PoolTimeout 即为获取连贯的最大超时工夫，超时则返回谬误。

  查看以后服务相干配置，poolsize=100，即每个客户端最多能够和 tw 建设 100 个连贯；而 tw 客户端连接数监控远没有达到这个限度。即，tw 客户端连接数突增只是个后果，因为 redis 慢查问，导致客户端与 tw 的连贯长期不够用，须要新建连贯。

  3）客户端机器的根本指标如 cpu 负载等并无显著异样；只是同时刻的磁盘写入耗时存在对应尖峰。是他造成的吗？

  后续统计了一些 redis 慢查问的监控；发现基本上存在 redis 慢查问的时候，磁盘写入耗时都会存在对应尖峰。

  另外，多个业务的服务也常常会呈现一些接口慢申请，而且通常也随同着磁盘写入耗时的尖峰；

  并且得悉所有的磁盘都应用的是网络盘 ceph，与运维搭档沟通，ceph 集群局部节点偶然的确会存在写入耗时尖峰。初步解决，7.31 号摘除了耗时比拟显著的节点。

  ceph 存在问题的节点摘除后，接口的慢申请以及 redis 慢查问频率比以前有所改善，然而偶然还会存在。

  反思：为什么 ceph 网盘写入耗时会影响 redis 的慢查问呢？目前还短少一个较强的逻辑关系，都只是猜想罢了。

【案例 2】tw 代理问题排查

  2020.08.05 19:11 分，grouping 服务呈现 redis 慢查问 1w+；与案例 1 不同的是，这次磁盘写入耗时并没有尖峰，并且这次慢查问日志散布在所有业务机器，如图：

  剖析业务机器各监控指标，cpu 负载以及磁盘写入耗时等都没有显著异样；而且这次的慢查问日志齐全且均匀分布在所有业务机器；那么大概率并不是客户端的问题。

  另外，redis 实例并没有 slow log 的报警。

  是 tw 代理的问题吗？察看 tw 代理各项指标，in_queue 和 out_queue 同时刻都存在较显著尖峰；如图：

  tw 代理共有 4 个实例，然而只有两台机器该指标显著异样；那么是否阐明是这两台 tw 代理机器的问题呢？in_queue 和 out_queue 指标又是什么含意呢？

  tw 作为 redis 的代理，负责转发客户端申请到 redis server 以及转发 redis server 的处理结果到客户端；tw 的每个连贯对象 Conn 都保护着两个队列：imsg_q 以及 omsg_q；咱们简略看一下 Conn 对象（与上游 redis server 的连贯）上的回调 handler：

// 转发申请到上游 redis server 实现
conn->send_done = req_send_done;

// 接管上游 redis server 响应后果实现
conn->recv_done = rsp_recv_done;

//imsg_q 入队；in_queue++
conn->enqueue_inq = req_server_enqueue_imsgq;
//imsg_q 出队；in_queue--
conn->dequeue_inq = req_server_dequeue_imsgq;

//omsg_q 入队；out_queue++
conn->enqueue_outq = req_server_enqueue_omsgq;

//omsg_q 出队；out_queue--
conn->dequeue_outq = req_server_dequeue_omsgq;

  具体的解决逻辑有趣味的读者能够通过这些解决 handler 去剖析；下图是简略整顿的解决逻辑：

  从图中能够失去答案：

1. tw 接管到客户端申请时，in_queue++；
2. tw 将申请转发给上游 redis server 时，in_queue–，同时 out_queue++；
3. tw 接管到上游 redis server 的响应时，out_queue–。

  in_queue 的尖峰，意味着局部申请沉积在 tw 代理处，没有转发给上游 redis server；out_queue 的尖峰，应该是因为 tw 代理霎时转发大量申请到上游 redis server，从而导致待接管响应即 out_queue 的突增。

  依据下面的剖析，大概率是 tw 代理因为某些起因短时阻塞，影响了命令的转发。

  通过沟通，这两台机器的确是前面部署的低配机，后续布局更新两台高配机。至于 tw 代理为什么会短时阻塞，还需进一步排查，看监控过后的 cpu 负载等都没有异样。

【案例 3】redis 实例慢查问剖析

  redis server 设置的慢查问报警门限为 10ms，断断续续会收到一些慢查问报警，比方：

redis slowlog host:xxxx port:13379 time:2020-08-10 07:12:06  
cost(ms):11.657 cmd:['HMSet', 'xxxx_3_732916', '10863500', '87922'] 
source:['xxxx:61960']

  理解到该 hash 键是十分小的，而且该命令的工夫复杂度实践上只是 O(1)，为什么会产生慢查问呢？

  咱们先总结以下可能产生慢查问的起因：

  1）典型的一些慢命令，如：save 长久化数据化；keys 匹配所有的键；hgetall，smembers 等大汇合的全量操作；

  2）应用 del 命令删除一个十分大的汇合键，这一点常常被大家疏忽；只是删除一个键为什么会慢呢？起因就在于汇合键在删除的时候，须要开释每一个元素的内存空间，想想要是汇合键蕴含 1000w 个元素呢？

  目前对于汇合键的删除，redis 提供了异步删除形式，主线程中只是断开了数据库与该键的援用关系，真正的删除动作通过队列异步交由另外的子线程解决。对应的，异步删除须要应用新的删除命令 unlink。另外，工夫事件循环中也会周期性删除过期键，这里的删除也能够采纳异步删除形式，不过须要配置 lazyfree-lazy-expire=yes。

  3）bgsave 长久化，虽说是 fork 子过程执行长久化操作，但有时 fork 零碎调用同样会比拟耗时，从而阻塞主线程执行命令申请；

  4）aof 长久化，aof 写入是须要磁盘的，如果此时磁盘的负载较高（比方其余过程占用，或者 redis 过程同时在执行 bgsave），同样会阻塞
aof 的写入，从而影响命令的执行；

  5）工夫事件循环中的周期性删除过期键，在遇到大量键集中过期时，删除过期键同样会比拟耗时；另外，如果配置 lazyfree-lazy-expire=no，删除大汇合键时同样会阻塞该过程；虽说 redis 保障了周期性删除过期键不会消耗太多工夫，依据配置 hz 计算，比方 hz=10 时，阐明工夫事件循环每秒执行 10 次，限度周期性删除过期键耗时不超过 cpu 工夫的 25%，那么执行工夫应该不超过 1000 毫秒 * 25% / 10 次 = 25 毫秒；显然周期性删除过期键的耗时还是有可能超过 redis 慢查问门限的。

  6）快命令被其余慢命令申请阻塞，一来如果是这样后面的慢命令申请也应该有慢查问报警，二来这时候 redis server 统计的以后命令执行还是十分快的，不会有慢查问日志，只是从客户端角度看来，该申请执行工夫较长。

  下面简略总结了 redis 产生慢查问的一些 case，依据以后案例的现状，第 5 点是比拟可能产生的（慢查问命令复杂度很低，没有执行 bgsave，磁盘利用率不高）。同时查看 redis 监控发现，呈现 redis 慢查问时，redis 实例内存占用都会有显著降落，如图所示：

  不过目前也只是猜想，依据监控慢查问与该景象相关度较高。

  对于 redis 外部的 ” 提早 ” 如何排查呢？其实 redis 提供了一些外部延迟时间的采样能力，latency-monitor-threshold 配置提早门限，执行工夫超过该门限的事件都会被记录在一个字典，事件名称作为 key，value 存储对应工夫戳以及延迟时间（底层基于数组实现，长度最大 160，采纳循环写形式；即同一个事件的提早信息最多可记录 160 条）

  目前 redis 提供以下事件的提早记录：

• fork：零碎调用 fork 的长耗时；
• expire-cycle：工夫事件循环中删除过期间长耗时；
• eviction-cycle：缓存淘汰过程长耗时；
• aof-write：写 aof 长耗时；
• fast-command/command：命令申请长耗时；
• 等等

  提早事件采样更多信息可查看 latency.c 文件，或者搜寻 latencyAddSampleIfNeeded 查看目前都会采样哪些事件。