记一次Redis超时排查

 一、问题：

    1. 应用端使用了我们提供的一个redis-sentinel集群(1主，1从，3个sentinel)

    2. 客户端设置了超时时间为200ms, 下面是应用端提供的超时日志。注意上图对象数只有265个。

2016-02-03 14:20:42,981 [DubboServerHandler-10.16.xx.xx:20880-thread-51] WARN  com.xx.DramaTabRelatePgcComponentImpl$1 (DataComponentCommand.java:76) - commandKey=drama_tab_pgc groupKey=drama_tab_pgc_pool poolKey=drama_tab_pgc_pool timeout cost=201 ms
...................
2016-02-03 14:20:40,168 [DubboServerHandler-10.16.xx.xx:20880-thread-9] WARN  com.xx.DramaTabRelatePgcComponentImpl$1 (DataComponentCommand.java:76) - commandKey=drama_tab_pgc groupKey=drama_tab_pgc_pool poolKey=drama_tab_pgc_pool timeout cost=200 ms
2016-02-03 09:56:14,174 [DubboServerHandler-10.16.xx.xx:20880-thread-146] WARN  com.xx.DramaTabRelatePgcComponentImpl$1 (DataComponentCommand.java:76) - commandKey=drama_tab_pgc groupKey=drama_tab_pgc_pool poolKey=drama_tab_pgc_pool timeout cost=200 ms
.....................
2016-02-03 12:32:03,575 [DubboServerHandler-10.16.xx.xx:20880-thread-125] WARN  com.xx.DramaTabRelatePgcComponentImpl$1 (DataComponentCommand.java:76) - commandKey=drama_tab_pgc groupKey=drama_tab_pgc_pool poolKey=drama_tab_pgc_pool timeout cost=200 ms

二、逐个排查：

1. Redis慢查询：并没有发现慢查询，跳过

2. Redis日志：对象数只有265个，注意从2016年1月25后就没日志了，所以并没有什么异常，也没什么RDB和AOF重写。跳过

3. 机器：tsar观察cpu，内存，网络，负载，本地IO

cpu、内存、负载、本地IO比较正常。

唯一以前怀疑的是网络，按理说这个流量也不是很大，但是看了一下机房的拓扑关系以及redis-cli的测试就了解原因了，下一节进行简单分析。

三、怀疑并确认：

1. 应用端与服务器网络：

2. redis-cli

    redis-cli是个比较好的方法来测redis的延迟，为此我们用下面的api来测试，发现会出现200ms的情况。

    具体原因猜测：机房之间的带宽有限，据说只有50M，这台机器本身流量就有点大而且是台虚机。

redis-cli --latency-history -h ip -p port

[@zw-34-55 ~]# redis-cli --latency-history -h 10.11.132.xx -p 6388
min: 0, max: 1, avg: 0.48 (1290 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.87 (1264 samples) -- 15.00 seconds range
min: 0, max: 1, avg: 0.60 (1275 samples) -- 15.01 seconds range
min: 0, max: 202, avg: 0.69 (1265 samples) -- 15.00 seconds range
min: 0, max: 202, avg: 0.81 (1271 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.79 (1254 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.52 (1283 samples) -- 15.00 seconds range
min: 0, max: 1, avg: 0.50 (1288 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.89 (1260 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.57 (1277 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.52 (1284 samples) -- 15.00 seconds range
min: 0, max: 1, avg: 0.69 (1284 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.76 (1256 samples) -- 15.00 seconds range
min: 0, max: 1, avg: 0.48 (1300 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.55 (1297 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.89 (1257 samples) -- 15.01 seconds range
min: 0, max: 202, avg: 0.68 (1277 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.52 (1296 samples) -- 15.01 seconds range
min: 0, max: 1, avg: 0.74 (1278 samples) -- 15.00 seconds range
min: 0, max: 1, avg: 0.73 (1271 samples) -- 15.00 seconds rang

    还可以使用redis-cli --intrinsic-latency 100(秒)，来找到最大延迟，已经超过平均延迟的个数。

    (延迟中的一部分是来自环境的，比如操作系统内核、虚拟化环境等等。intrinsic-latency是一种基准测试的方法)

[@zw-34-55 ~]# redis-cli --intrinsic-latency 100 -h 10.11.132.xx -p 6388
Max latency so far: 6 microseconds.
Max latency so far: 11 microseconds.
Max latency so far: 16 microseconds.
Max latency so far: 174 microseconds.
Max latency so far: 184 microseconds.
Max latency so far: 193 microseconds.
Max latency so far: 195 microseconds.
Max latency so far: 203 microseconds.
Max latency so far: 264 microseconds.

31976748 total runs (avg latency: 3.1273 microseconds / 31272.72 nanoseconds per run).
Worst run took 84x longer than the average latency.

四、解决和观察：

    1. 思路：写入端是后台管理系统，流量较小，读端流量较大，为此让master改为电信机房。

    2. 解决方法：(1) 添加一个电信的slave (2) 下线老的联通slave (3) 主从做sentinel failove

    3. 总结：查询超时的基本思路 +  分配机器要考虑流量的合理性。

五、参考文献：

1. Redis latency problems troubleshooting