神奇的Redis延迟

最近在做某业务Redis的缩容工作，涉及到数据迁移，而Redis的数据迁移看起来蛮简单的，一对一的数据迁移只需要在slave行配置masterauth 和slaveof 两个参数即可，当然迁移过程中涉及到其它特殊情况需要特殊处理外。

以上几个步骤都做好后， 就等着实例的切换了，不过在实例切换前我们还要检查同步情况、数据一致性等。在检查实例同步情况的时候发现了奇怪的现象：在迁移的540个实例中有个别实例(20个) lag 比较高，而且还有增加的趋势，奇怪的是offset值一直是0。

slave0:ip=xxxx,port=xxxx,state=online,offset=0,lag=38392

经过观察一段时间后，发现这个现象并没有消失，而且 lag 也是随着时间的增加在增加，offset值始终保持0。难道这个数据slave一直没有应用？ 
cli 上 slave 后发现slave的 dbsize 和master 的dbsize 基本一致；monitor slave 也发现有命令正常同步；master set 一个key，在slave 上也能正确的读取到这个key；在看看slave 上的日志:

[13739] 10 Aug 15:49:46.017 * Connecting to MASTER xxxx.xxxx.xxx:xxx
[13739] 10 Aug 15:49:46.017 * MASTER <-> SLAVE sync started
[13739] 10 Aug 15:49:46.018 * Non blocking connect for SYNC fired the event.
[13739] 10 Aug 15:49:46.032 * Master replied to PING, replication can continue...
[13739] 10 Aug 15:49:46.092 * Partial resynchronization not possible (no cached master)
[13739] 10 Aug 15:49:46.120 # Unexpected reply to PSYNC from master: -LOADING Redis is loading the dataset in memory
[13739] 10 Aug 15:49:46.120 * Retrying with SYNC...
[13739] 10 Aug 15:49:46.641 * MASTER <-> SLAVE sync: receiving 26845995 bytes from master
[13739] 10 Aug 15:49:47.276 * MASTER <-> SLAVE sync: Flushing old data
[13739] 10 Aug 15:49:47.276 * MASTER <-> SLAVE sync: Loading DB in memory
[13739] 10 Aug 15:49:47.620 * MASTER <-> SLAVE sync: Finished with success
[13739] 10 Aug 15:49:47.621 * Background append only file rewriting started by pid 22605
[22605] 10 Aug 15:49:48.724 * SYNC append only file rewrite performed
[22605] 10 Aug 15:49:48.725 * AOF rewrite: 0 MB of memory used by copy-on-write
[13739] 10 Aug 15:49:48.822 * Background AOF rewrite terminated with success
[13739] 10 Aug 15:49:48.822 * Parent diff successfully flushed to the rewritten AOF (1148 bytes)
[13739] 10 Aug 15:49:48.822 * Background AOF rewrite finished successfully

看起来似乎好像也正常 :(

那么问题来了，既然我们的数据能正常同步，为什么master 上看到的信息显示slave一直在延迟呢？难道？ 
打开代码找到这个lag 、offset的计算方式：

    if (slave->replstate == SLAVE_STATE_ONLINE)
        lag = time(NULL) - slave->repl_ack_time;

    info = sdscatprintf(info,
"slave%d:ip=%s,port=%d,state=%s,"
"offset=%lld,lag=%ld
",
           slaveid,slaveip,slave->slave_listening_port,state,
           slave->repl_ack_off, lag);
long long repl_ack_off; /* Replication ack offset, if this is a slave. */
long long repl_ack_time;/* Replication ack time, if this is a slave. */

可以发现这个lag 是通过master 的当前时间减去slave 通过ACK上报上来的时间得到的，到这里可以怀疑是 slave 一直没有 ACK ？

这里通过到lag，offset值正常的master 节点执行 monitor 命令可以发现，这些实例的slave 确实是有发送 ACK 命令回来的 ，而这种看上去似乎异常的节点确实是没有ACK返回 。

到这里似乎找到了问题的关键了，那么为什么这种看似异常的slave 不发送ACK 给master 呢？这个还是得一层一层的扒开slave运行的面纱。

再次查看slave 运行日志，并且和其它实例对比，貌似可以发现一些不太相同的地方：

通过上图可以看到，能正常发送ACK给master实例的日志多了几行日志，而这些日志或许就是发送与不发送ACK的关键所在。

通过查看源码得到如下信息： 
replicationCron 函数每秒执行一次，如果当前实例有配置masterhost，那么会去检查同步的状态 server.repl_state ， 如果这个状态 为： REPL_STATE_CONNECT /* Must connect to master */，那么会尝试和Master 建立连接connectWithMaster()，如果连接建立正常，那么和master 进行数据同步 syncWithMaster()，并更新初次发送PING 包给Master，等待Master 会用PONG，当收到Master的回应，并且进行AUTH等操作后，slave会尝试进行部分同步，当部分同步不成功时会进行全同步slaveTryPartialResynchronization(),而这个函数里边发送的同步指令就是 PSYNC 指令，当master 回应的不是 +FULLRESYNC 或者 +CONTINUE时，那么统一的认为Master 不认识PSYNC 指令，而这时，为了兼容老版本的同步方式，这里会用SYNC指令重新发给Master。

psync_result = slaveTryPartialResynchronization(fd);
if (psync_result == PSYNC_CONTINUE) {
redisLog(REDIS_NOTICE, "MASTER <-> SLAVE sync: Master accepted a Partial Resynchronization.");
return;
}
/* Fall back to SYNC if needed. Otherwise psync_result == PSYNC_FULLRESYNC
* and the server.repl_master_runid and repl_master_initial_offset are
* already populated. */
if (psync_result == PSYNC_NOT_SUPPORTED) {
redisLog(REDIS_NOTICE,"Retrying with SYNC...");
}

执行玩指令后，如果成功了就会继续进行后面的步骤，全同步接收RDB，FLUSHDB，LOADRDB等步骤。

到这里就可以解释两个实例输出的日志不太一致的地方，可以认为一个实例使用了PSYNC的同步方式，另个一个实例使用了SYNC 的方式。使用了SYNC同步方式的实例 server.repl_master_initial_offset = -1 , 而 使用了PSYNC 同步方式的实例 server.repl_master_initial_offset = 1 。（关于这个变量可以通过 gdb 工具进行验证，gdb有风险且用且珍惜~）

而现在回到发送ACK函数的地方:

    /* Send ACK to master from time to time.
     * Note that we do not send periodic acks to masters that don't
     * support PSYNC and replication offsets. */
if (server.masterhost && server.master &&
        !(server.master->flags & CLIENT_PRE_PSYNC))
        replicationSendAck();
#define CLIENT_PRE_PSYNC (1<<16)   /* Instance don't understand PSYNC. */

也就是说使用SYNC 同步方式的实例 (server.master->flags & CLIENT_PRE_PSYNC) 这个条件是不满足的，所以这个函数不会被执行。

为什么slave 不发送ACK给 master 的根本原因找到了，是因为 slave使用的同步方式为SYNC 方式。 
那么使用PSYNC 和 SYNC 时，master 会做不同的处理么？对同步数据有什么影响？show me the code :

    {"sync",syncCommand,1,"ars",0,NULL,0,0,0,0,0},
    {"psync",syncCommand,3,"ars",0,NULL,0,0,0,0,0},

    if (!strcasecmp(c->argv[0]->ptr,"psync")) {
        if (masterTryPartialResynchronization(c) == C_OK) {
            server.stat_sync_partial_ok++;
            return; /* No full resync needed, return. */
        } else {
            char *master_replid = c->argv[1]->ptr;
            if (master_replid[0] != '?') server.stat_sync_partial_err++;
        }
    } else {
/* If a slave uses SYNC, we are dealing with an old implementation
         * of the replication protocol (like redis-cli --slave). Flag the client
         * so that we don't expect to receive REPLCONF ACK feedbacks. */  ----这里也表明，使用了SYNC 方式的，master 也不期望slave 发送 ACK 回来
        c->flags |= CLIENT_PRE_PSYNC;
    }

可以看到，master对PSYNC和SYNC 两种同步方式的入口一致，不同的就是PSYNC 可以进行部分同步，而SYNC只能进行完全同步。

小结： 
redis slave 同步数据的方式有两种，PSYNC 和 SYNC ，当slave 使用PSYNC 同步数据失败时，会尝试使用SYNC方式同步，而使用SYNC方式同步数据时，并不会给Master 发送ACK 数据，导致master 上看到slave 的lag 信息不准确。

lag 这个值不一定能用来确定一个slave 是否有延迟，延迟多长时间。我们可以根据 master_last_io_seconds 来判断这个slave是否有延迟；或者我们需要通过外围的监控来发现。