问题来源
高峰盯盘期间，通过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去分析；下图是简单整理的处理逻辑：
从图中可以得到答案：
- tw接收到客户端请求时，in_queue++；
- tw将请求转发给上游redis server时，in_queue--，同时out_queue++；
- 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执行命令。
6）快命令被其他慢命令请求阻塞，如果是这样前面的慢命令请求也应该有慢查询报警，
上面简单总结了redis产生慢查询的一些case。slowlog是什么呢？他只是统计命令的执行时间，不包括命令的排队等待时间；符合slowlog这一定义的只有1、2、3以及4。5和6只是从客户端角度看，命令耗时较长而已。
然而奇怪的是，报redis slowlog的命令，还包括一些"快命令"，比如hset等。这种命令为什么会执行很长时间呢？可能是cpu切换或者其他某些原因造成的吧。
最后再扩展一下。对于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查看目前都会采样哪些事件。
有疑问加站长微信联系（非本文作者）
