关于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查看目前都会采样哪些事件。