转载请注明出处哈:http://carlosfu.iteye.com/blog/2240426
一、测试环境
1. Redis版本:
由于我们较早的使用了Redis-Cluster版本,所以此测试使用的是Redis 3.0.0 RC1 (version 2.9.101)
后来有开发者提出,如果是大集群的话,会造成判定失败过慢,造成failover失败,所以作者在Redis 3.0.0 RC3做了修正,当然现在的release版已经不存在这个问题了。
具体可以参考:
(1). Redis Cluster的FailOver失败案例分析 : 这篇文章分析了大集群下RedisCluster-RC1会出现由于gossip不完善造成failover失败的案例。
(2). RedisCluster-RC3优化加快了gossip的传播和失败判定。(redis release notes)
2. 机器:(5台虚机)
机器配置:CPU: 2*E5-2650,内存:24G,硬盘:120G
- 10.10.52.126
- 10.10.34.55
- 10.10.52.133
- 10.10.52.157
- 10.10.52.151
3. 每个分片128M(5台机器交叉互为主从), A1、B1、C1、D1、E1是5个Master, D2,E2,A2,B2,C2分别是5个对应的Slave。
- A1(10.10.52.126)----D2(10.10.52.157)
- B1(10.10.34.55)---E2(10.10.52.151)
- C1(10.10.52.133)---A2(10.10.52.126)
- D1(10.10.52.157)---B2(10.10.34.55)
- E1(10.10.52.151)--C2(10.10.52.133)
二、数据5个节点存储100w key-value数据
key:value为1:1 2:2..........1000000:1000000
三、客户端毫秒级间隔发送读请求
每次随机从(1-1000000)取1个key,进行get操作,记录相关日志。
package com.sohu.cc.redis.fail.test;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
/**
* 测试redis-cluster的failover
*
* @Date 2014年12月5日
* @Time 上午11:16:50
*/
public class RedisClusterFailRead extends RedisClusterFailOverBaseTest {
private static final int THREAD_SIZE = 1;
private static ExecutorService threadPool = Executors.newFixedThreadPool(THREAD_SIZE);
public static void main(String[] args) {
for (int i = 0; i < THREAD_SIZE; i++) {
threadPool.execute(new RedisClusterReadThread());
}
}
}
package com.sohu.cc.redis.fail.test;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.Random;
import java.util.concurrent.TimeUnit;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
/**
* redis get线程
* @author leifu
* @Date 2014年12月5日
* @Time 下午2:52:58
*/
public class RedisClusterReadThread extends RedisClusterFailOverBaseTest
implements Runnable {
private final Logger logger = LoggerFactory.getLogger(RedisClusterReadThread.class);
private int count = 0;
public void run() {
while (true) {
try {
int randomKey = new Random().nextInt(MAX_KEY);
String result = pipelineCluster.get(String.valueOf(randomKey));
if (result == null || "".equals(result)) {
logger.error("result is empty, randomKey is {}", randomKey);
}else{
if(count % 100 == 0){
logger.info("success data time={}", new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(new Date()));
}
}
count++;
TimeUnit.MILLISECONDS.sleep(2);
} catch (Exception e) {
logger.info("time={}", new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format(new Date()));
logger.error(e.getMessage(), e);
}
}
}
}
四、故障模拟
1. kill 掉1台机器下集群所有主从点,收集redis实例反馈日志和客户端故障&恢复时间
(1)分析:当前拓扑情况下,无论停掉哪台机器,集群都是完整的(有故障转移),不会丢失数据。
(2)以kill A节点为例子(10.10.52.126), 观察A1(10.10.52.126)-D2(10.10.52.157),C1(10.10.52.133)-A2(10.10.52.126),
涉及机器和节点如下
-
- A1(10.10.52.126)----D2(10.10.52.157)
- B1(10.10.34.55)---E2(10.10.52.151)
- C1(10.10.52.133)---A2(10.10.52.126)
- D1(10.10.52.157)---B2(10.10.34.55)
- E1(10.10.52.151)--C2(10.10.52.133)
1)redis实例日志:
D2(10.10.52.157)日志:
23706:S 17 Dec 18:51:43.380 # Connection with master lost.
23706:S 17 Dec 18:51:43.380 * Caching the disconnected master state.
23706:S 17 Dec 18:51:44.154 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:44.154 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:44.155 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:45.161 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:45.162 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:45.162 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:46.170 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:46.170 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:46.171 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:47.177 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:47.178 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:47.178 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:48.183 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:48.185 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:48.186 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:49.194 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:49.194 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:49.195 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:50.203 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:50.204 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:50.204 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:51.208 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:51.209 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:51.209 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:52.215 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:52.215 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:52.216 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:53.220 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:53.220 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:53.221 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:54.228 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:54.228 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:54.229 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:55.231 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:55.231 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:55.231 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:56.237 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:56.237 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:56.238 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:57.245 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:57.245 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:57.245 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:58.253 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:58.253 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:58.255 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:51:59.259 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:51:59.259 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:51:59.260 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:52:00.263 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:52:00.263 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:52:00.263 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:52:01.078 * FAIL message received from e6f56def9a30ee2e5e57639b76314d6970d98260 about a6e0ce48cc9a13b57a801cf7b695a4b0dad222b8
23706:S 17 Dec 18:52:01.170 # Start of election delayed for 633 milliseconds (rank #0, offset 4817).
23706:S 17 Dec 18:52:01.272 * Connecting to MASTER 10.10.52.126:6381
23706:S 17 Dec 18:52:01.272 * MASTER <-> SLAVE sync started
23706:S 17 Dec 18:52:01.272 # Error condition on socket for SYNC: Connection refused
23706:S 17 Dec 18:52:01.876 # Starting a failover election for epoch 17.
23706:S 17 Dec 18:52:01.881 * FAIL message received from 8d5358167c0539daf74481d42c9e991822a0522f about cd0837a7c88c849eac575af33458e277e65a2014
23706:S 17 Dec 18:52:01.882 # Failover election won: I'm the new master.
23706:M 17 Dec 18:52:01.882 * Discarding previously cached master state.
23706:M 17 Dec 18:52:01.883 # configEpoch set to 17 after successful failover
C1(10.10.52.133)日志
Connection with slave 10.10.52.126:6382 lost.
24901:M 17 Dec 18:52:01.093 * FAIL message received from e6f56def9a30ee2e5e57639b76314d6970d98260 about a6e0ce48cc9a13b57a801cf7b695a4b0dad222b8
24901:M 17 Dec 18:52:01.892 * FAIL message received from 8d5358167c0539daf74481d42c9e991822a0522f about cd0837a7c88c849eac575af33458e277e65a2014
24901:M 17 Dec 18:52:01.896 # Failover auth granted to 43090dceee24fd448be5688f04d200da0e8ab850 for epoch 17
其他机器:
2713:M 17 Dec 18:52:01.071 * FAIL message received from e6f56def9a30ee2e5e57639b76314d6970d98260 about a6e0ce48cc9a13b57a801cf7b695a4b0dad222b8
2713:M 17 Dec 18:52:01.869 * Marking node cd0837a7c88c849eac575af33458e277e65a2014 as failing (quorum reached).
2713:M 17 Dec 18:52:01.874 # Failover auth granted to 43090dceee24fd448be5688f04d200da0e8ab850 for epoch 17
2)客户端异常信息:
18:51:37.535 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:37
18:51:38.246 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:38
18:51:38.967 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:38
18:51:39.670 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:39
18:51:40.374 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:40
18:51:41.077 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:41
18:51:41.779 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:41
18:51:42.481 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:42
18:51:43.189 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:51:43
---------------------------------------------------发生异常----------------------------------------------------
18:51:44.560 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 18:51:44
18:51:44.568 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=386948
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=386948
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
18:51:46.680 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 18:51:46
18:51:46.680 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=869071
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=869071
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
18:51:49.871 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 18:51:49
18:51:49.871 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=900131
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=900131
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
18:51:51.979 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 18:51:51
---------------------------------------------------(重复的异常太长了不打印了)----------------------------------------------------
---------------------------------------------------故障恢复----------------------------------------------------
18:52:02.620 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:02
18:52:03.331 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:03
18:52:04.047 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:04
18:52:04.802 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:04
18:52:05.548 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:05
18:52:06.261 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:06
18:52:06.985 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:06
18:52:07.708 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 18:52:07
3)客户端故障时间&恢复时间:
客户端故障时间: 2014-12-17 18:51:43
恢复时间: 2014-12-17 18:52:02, 一共耗时19秒
2. kill 掉2台机器下集群所有主从点,收集redis实例反馈日志和客户端故障&恢复时间
(1)分析:如果kil掉两台机器,可能出现两种情况
(a) AB AE BC CD DE 集群依然完整,故障自动迁移
(b) AC AD BD BE CE 由于是涉及主从同时杀掉,会出现集群不完整情况。
下面以(a)为例子,kill掉A(10.10.52.126)和B(10.10.34.55) ((b)涉及到了集群不完整的情况(从下面3再进行分析))。
(2)客户端日志和redis服务器日志:
涉及机器和节点如下
-
- A1(10.10.52.126)----D2(10.10.52.157)
- B1(10.10.34.55)---E2(10.10.52.151)
- C1(10.10.52.133)---A2(10.10.52.126)
- D1(10.10.52.157)---B2(10.10.34.55)
- E1(10.10.52.151)--C2(10.10.52.133)
1)redis实例日志
10.10.52.157 (D2)
23756:M 17 Dec 19:07:01.198 # Connection with slave 10.10.34.55:7629 lost.
23756:M 17 Dec 19:07:14.685 * FAIL message received from 8d5358167c0539daf74481d42c9e991822a0522f about b0b4a7c5ced736127e70c9e96c91aa6b2bd632ac
23756:M 17 Dec 19:07:15.738 # Failover auth granted to 5d9125e11d1be2d389fdd9623ddeff1906204acc for epoch 18
23756:M 17 Dec 19:07:19.218 * FAIL message received from 5d9125e11d1be2d389fdd9623ddeff1906204acc about 93b5a7aab976a86ca82e2adb4d2a521c192dc56b
10.10.52.151
4529:S 17 Dec 19:06:58.086 # Connection with master lost.
4529:S 17 Dec 19:06:58.086 * Caching the disconnected master state.
4529:S 17 Dec 19:06:58.495 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:06:58.496 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:06:58.496 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:06:59.502 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:06:59.503 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:06:59.503 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:00.507 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:00.507 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:00.508 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:01.515 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:01.515 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:01.516 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:02.523 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:02.523 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:02.524 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:03.531 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:03.531 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:03.531 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:04.538 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:04.538 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:04.539 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:05.544 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:05.544 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:05.545 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:06.551 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:06.551 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:06.551 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:07.557 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:07.558 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:07.558 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:08.567 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:08.567 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:08.567 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:09.575 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:09.575 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:09.575 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:10.582 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:10.582 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:10.582 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:11.590 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:11.590 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:11.590 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:12.596 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:12.597 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:12.597 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:13.606 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:13.606 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:13.607 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:14.614 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:14.615 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:14.616 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:14.677 * FAIL message received from 8d5358167c0539daf74481d42c9e991822a0522f about b0b4a7c5ced736127e70c9e96c91aa6b2bd632ac
4529:S 17 Dec 19:07:14.716 # Start of election delayed for 947 milliseconds (rank #0, offset 2185).
4529:S 17 Dec 19:07:15.624 * Connecting to MASTER 10.10.34.55:7628
4529:S 17 Dec 19:07:15.625 * MASTER <-> SLAVE sync started
4529:S 17 Dec 19:07:15.625 # Error condition on socket for SYNC: Connection refused
4529:S 17 Dec 19:07:15.726 # Starting a failover election for epoch 18.
4529:S 17 Dec 19:07:15.730 # Failover election won: I'm the new master.
4529:M 17 Dec 19:07:15.730 * Discarding previously cached master state.
4529:M 17 Dec 19:07:15.730 # configEpoch set to 18 after successful failover
4529:M 17 Dec 19:07:19.208 * Marking node 93b5a7aab976a86ca82e2adb4d2a521c192dc56b as failing (quorum reached).
其他存活的机器:
2713:M 17 Dec 19:07:14.676 * Marking node b0b4a7c5ced736127e70c9e96c91aa6b2bd632ac as failing (quorum reached).
2713:M 17 Dec 19:07:15.729 # Failover auth granted to 5d9125e11d1be2d389fdd9623ddeff1906204acc for epoch 18
2713:M 17 Dec 19:07:19.209 * FAIL message received from 5d9125e11d1be2d389fdd9623ddeff1906204acc about 93b5a7aab976a86ca82e2adb4d2a521c192dc56b
2)客户端异常信息
19:06:48.773 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:48
19:06:49.493 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:49
19:06:50.506 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:50
19:06:51.235 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:51
19:06:51.969 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:51
19:06:52.708 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:52
19:06:53.419 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:53
19:06:54.179 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:54
19:06:54.893 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:54
19:06:55.624 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:55
19:06:56.328 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:56
19:06:57.037 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:57
19:06:57.798 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:06:57
---------------------------------------------------发生异常----------------------------------------------------
19:07:00.113 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 19:07:00
19:07:00.121 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=598260
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=598260
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
19:07:02.223 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 19:07:02
19:07:02.224 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=711411
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=711411
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
19:07:05.406 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 19:07:05
19:07:05.407 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=115983
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=115983
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
---------------------------------------------------(重复的异常太长了不打印了)----------------------------------
---------------------------------------------------故障恢复----------------------------------------------------
19:07:20.757 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:07:20
19:07:21.490 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:07:21
19:07:22.215 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:07:22
19:07:22.917 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:07:22
3)客户端故障时间&恢复时间:
客户端故障时间: 2014-12-17 19:07:00
恢复时间: 2014-12-17 19:07:20, 一共耗时20秒
3. kill 掉3台机器下集群所有主从点,收集redis实例反馈日志和客户端故障&恢复时间
(1)分析:如果kil掉两台机器,可能出现两种情况
(a) AB AE BC CD DE 集群依然完整,故障自动迁移
(b) AC AD BD BE CE 由于是涉及主从同时杀掉,会出现集群不完整情况。
以kill掉ABC为例子:
涉及到的机器
- A1(10.10.52.126)----D2(10.10.52.157)
- B1(10.10.34.55)---E2(10.10.52.151)
- C1(10.10.52.133)---A2(10.10.52.126)
- D1(10.10.52.157)---B2(10.10.34.55)
- E1(10.10.52.151)--C2(10.10.52.133)
(2)客户端日志和redis服务器日志:
1)redis实例日志
E1(10.10.52.151):
4529:M 17 Dec 19:28:41.802 * FAIL message received from e6f56def9a30ee2e5e57639b76314d6970d98260 about 6ddd2fc00bc218ac6917431daff810b9d334cd87
4529:M 17 Dec 19:28:50.535 * Marking node 6a4008414c773c5a3b66f56f7027da882f6cfee7 as failing (quorum reached).
E2(10.10.52.151):
2713:M 17 Dec 19:28:41.801 * FAIL message received from e6f56def9a30ee2e5e57639b76314d6970d98260 about 6ddd2fc00bc218ac6917431daff810b9d334cd87
2713:M 17 Dec 19:28:50.536 * FAIL message received from 5d9125e11d1be2d389fdd9623ddeff1906204acc about 6a4008414c773c5a3b66f56f7027da882f6cfee7
D1(10.10.52.157)日志:
23756:M 17 Dec 19:28:41.841 * Marking node 6ddd2fc00bc218ac6917431daff810b9d334cd87 as failing (quorum reached).
23756:M 17 Dec 19:28:50.579 * FAIL message received from 5d9125e11d1be2d389fdd9623ddeff1906204acc about 6a4008414c773c5a3b66f56f7027da882f6cfee7
D2(10.10.52.157)日志:
23706:M 17 Dec 19:28:41.842 * FAIL message received from e6f56def9a30ee2e5e57639b76314d6970d98260 about 6ddd2fc00bc218ac6917431daff810b9d334cd87
23706:M 17 Dec 19:28:50.579 * FAIL message received from 5d9125e11d1be2d389fdd9623ddeff1906204acc about 6a4008414c773c5a3b66f56f7027da882f6cfee7
2)客户端异常信息:
19:28:36.116 [main] INFO c.s.tv.builder.RedisClusterBuilder - client is up to date, Cheers!
19:28:36.233 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.265 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.290 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.316 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.348 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.373 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.405 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.432 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.457 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
19:28:36.482 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:36
---------------------------------------------------发生异常----------------------------------------------------
19:28:41.619 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 19:28:41
19:28:41.627 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=749119
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=749119
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
---------------------------------------------------正常返回----------------------------------------------------
19:28:41.633 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:41
19:28:41.658 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:41
---------------------------------------------------发生异常----------------------------------------------------
19:28:43.745 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 19:28:43
19:28:43.746 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=195338
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=195338
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
---------------------------------------------------正常返回----------------------------------------------------
19:28:43.752 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.777 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.803 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.829 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.855 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.880 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.906 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.932 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.958 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:43.985 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:43
19:28:44.010 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:44.035 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:44.061 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:44.087 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:44.113 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:44.140 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:44.165 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:44.191 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:44
19:28:51.382 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-17 19:28:51
19:28:51.382 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=537888
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=537888
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
19:28:51.389 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:51
19:28:51.415 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-17 19:28:51
---------------------------------------------------一直存在部分失败----------------------------------------------------
3)客户端故障时间&恢复时间:
客户端故障时间: 2014-12-17 19:28:41
恢复时间: 由于集群不完整,一直存在部分失败(cluster-require-full-coverage为no允许部分失败)
4. 测试cluster-require-full-coverage参数的影响
(1) 恢复上面的集群(启动所有被关闭的实例)
(2) 修改所有实例的配置cluster-require-full-coverage为yes(通过CacheCloud的实例页面进行修改配置申请)
(3) kill掉ABC机器上面的实例。
1)客户端异常信息:
16:12:19.727 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:19
16:12:19.832 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:19
16:12:19.937 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:19
16:12:20.042 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.148 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.255 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.360 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.465 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.570 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.675 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.780 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.887 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:20.994 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:20
16:12:26.265 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-18 16:12:26
16:12:26.298 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=724908
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=724908
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
16:12:26.312 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:26
16:12:30.698 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-18 16:12:30
16:12:30.698 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - Too many Cluster redirections? key=677711
redis.clients.jedis.exceptions.JedisClusterMaxRedirectionsException: Too many Cluster redirections? key=677711
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:39) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:92) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
16:12:30.705 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:30
16:12:30.810 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:30
16:12:30.915 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:30
16:12:31.021 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:31
16:12:31.127 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:31
16:12:31.234 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:31
16:12:31.339 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:31
16:12:31.444 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:31
16:12:31.550 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:31
16:12:31.656 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - success data time=2014-12-18 16:12:31
16:12:39.933 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-18 16:12:39
16:12:39.934 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
redis.clients.jedis.exceptions.JedisClusterException: CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
at redis.clients.jedis.Protocol.processError(Protocol.java:114) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.process(Protocol.java:142) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.read(Protocol.java:197) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:248) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:194) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBulkReply(Connection.java:184) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Jedis.get(Jedis.java:105) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:101) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:98) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:64) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
16:12:45.124 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-18 16:12:45
16:12:45.125 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
redis.clients.jedis.exceptions.JedisClusterException: CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
at redis.clients.jedis.Protocol.processError(Protocol.java:114) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.process(Protocol.java:142) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.read(Protocol.java:197) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:248) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:194) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBulkReply(Connection.java:184) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Jedis.get(Jedis.java:105) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:101) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:98) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:64) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
16:12:53.348 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-18 16:12:53
16:12:53.348 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
redis.clients.jedis.exceptions.JedisClusterException: CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
at redis.clients.jedis.Protocol.processError(Protocol.java:114) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.process(Protocol.java:142) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.read(Protocol.java:197) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:248) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:194) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBulkReply(Connection.java:184) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Jedis.get(Jedis.java:105) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:101) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:98) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:64) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:75) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
16:12:53.354 [pool-1-thread-1] INFO c.s.c.r.f.t.RedisClusterReadThread - time=2014-12-18 16:12:53
16:12:53.355 [pool-1-thread-1] ERROR c.s.c.r.f.t.RedisClusterReadThread - CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
redis.clients.jedis.exceptions.JedisClusterException: CLUSTERDOWN The cluster is down. Use CLUSTER INFO for more information
at redis.clients.jedis.Protocol.processError(Protocol.java:114) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.process(Protocol.java:142) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Protocol.read(Protocol.java:197) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:248) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:194) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Connection.getBulkReply(Connection.java:184) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.Jedis.get(Jedis.java:105) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:101) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster$3.execute(JedisCluster.java:98) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.runWithRetries(JedisClusterCommand.java:64) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisClusterCommand.run(JedisClusterCommand.java:33) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at redis.clients.jedis.JedisCluster.get(JedisCluster.java:97) ~[jedis-2.6.2-sohutv-SNAPSHOT.jar:na]
at com.sohu.cc.redis.fail.test.RedisClusterReadThread.run(RedisClusterReadThread.java:28) ~[test-classes/:na]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_55]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) [na:1.7.0_55]
at java.lang.Thread.run(Thread.java:745) [na:1.7.0_55]
------------------------------------------------错误一直持续下去-----------------------------------------------------------
3)客户端故障时间&恢复时间:
客户端故障时间: 故障不能恢复,设置了cluster-require-full-coverage=yes后不允许集群部分失败。
五、结论
- 部分停机能实现故障自动转移,需要时间20秒以内。(测试环境中):在3.0release中这个速度提高了一倍。
- 过多机器停机或者实例挂掉可能会造成集群不完整。
- cluster-require-full-coverage=yes不允许集群部分失败, cluster-require-full-coverage=no允许集群部分失败。