Redis 源码 bug 深入定位过程分享

原创

廖可知

修改于 2017-08-17 09:52:47

6.4K0

修改于 2017-08-17 09:52:47

前言

Redis持久化包括RDB和AOF两种方式，而采用AOF方式时Redis会定期重写aof文件以优化文件结构并减少磁盘占用。为了使I/O操作不影响Redis对外提供服务，AOF重写操作由子进程完成。然而，当系统配置中"vm.overcommit_memory = 0"，且系统内存不足以fork子进程时，AOF重写就无法启动，而此之前已打开的pipe也永远不会关闭，并在下一次尝试AOF重写时又创建新的pipe，从而造成fd泄漏。

这次，我们在对访问Redis的一个服务进行升级重启后遇到问题，该服务的日志出现大量访问Redis连接错误和超时的信息。随后，使用redis-cli也无法连接到Redis服务。在进一步分析了Redis服务端日志和运行数据后，我们大致得出了问题产生的原因，并通过分析源码确认了bug的存在。以下详细描述此次问题的产生及定位过程。

故障由来

首先描述一下出现故障的Redis实例的部署运行特征。此Redis实例是用于一项离线作业的队列使用的，该作业每天跑一次。运行时，一个由crontab触发的工具作为生产者会把需要处理的号码推入Redis的list中，而另一个消费者工具则定时尝试从list中取出号码做相应处理。消费者消费速度远慢于生产者，所以期间Redis的内存占用会达到一个极值。

当天对消费者服务（以下称client）进行升级，增加了并行client数重启后（这点是问题暴漏的直接原因），发现log异常，报出很多网络连接错误或接收超时，但在升级前并没有错误。因为client数远小于Redis中maxclient=10000的设定，且使用的是TCP长连接方式，初步判断是重启连接断开后无法重新正常连接。

尝试用Redis自带客户端redis-cli查看服务器运行状态，同样报错"connect reset by peer"，看来问题可能在服务端了。

根据日志及数据定位Root Cause

首先检查Redis实例的运行情况：CPU占用几乎为0，内存占用也很低，进程启动时间表明实例没有重启。因为当时所有作业已经跑完，Redis中数据为空，所以这些指标正常。

然后查看Redis服务的log，果然Redis的log频繁报错如下图。日志很直接的给出了client连接失败的原因是FD太大。

……
9554:M 24 Mar 10:40:25.869 # Error registering fd event for the new client: Numerical result out of range (fd=10128)
9554:M 24 Mar 10:40:25.878 # Error registering fd event for the new client: Numerical result out of range (fd=10128)
9554:M 24 Mar 10:40:25.907 # Error registering fd event for the new client: Numerical result out of range (fd=10128)
……

使用lsof命令检查fd数，发现当时进程打开的fd数已经达到10128个，而其中大部分基本都是pipe：

而Redis中，pipe主要用于父子进程间通信，如AOF重写、基于socket的RDB持久化等场景。难道是与某个子进程相关的调用出了问题？继续回溯Redis服务端日志，发现果然在client升级重启前，3:45开始服务端日志已经出现异常，并在5:10左右log出现了变化：

……
9554:M 24 Mar 03:45:58.597 * Residual parent diff successfully flushed to the rewritten AOF (329.83 MB)
9554:M 24 Mar 03:45:59.308 * Background AOF rewrite finished successfully
9554:M 24 Mar 05:07:11.166 * Starting automatic rewriting of AOF on 100% growth
9554:M 24 Mar 05:07:11.183 # Can't rewrite append only file in background: fork: Cannot allocate memory
……
9554:M 24 Mar 05:09:59.734 * Starting automatic rewriting of AOF on 100% growth
9554:M 24 Mar 05:09:59.735 # Can't rewrite append only file in background: fork: Cannot allocate memory
9554:M 24 Mar 05:09:59.835 * Starting automatic rewriting of AOF on 100% growth
9554:M 24 Mar 05:09:59.836 # Can't rewrite append only file in background: fork: Cannot allocate memory
9554:M 24 Mar 05:09:59.936 * Starting automatic rewriting of AOF on 100% growth
9554:M 24 Mar 05:09:59.936 # Error opening /setting AOF rewrite IPC pipes: Numerical result out of range
9554:M 24 Mar 05:10:00.036 * Starting automatic rewriting of AOF on 100% growth
9554:M 24 Mar 05:10:00.036 # Error opening /setting AOF rewrite IPC pipes: Numerical result out of range
……

分析日志可初步推测故障发生的过程：

在离线作业运行过程中，随着list中数据量增加，Redis内存占用逐渐增加；
当系统剩余内存不足以fork子进程时，AOF重写子进程启动失败，此时错误log为“Can't rewrite append only file in background: fork: Cannot allocate memory”，而用于父子进程通信的pipe不知什么原因没有关闭；
Redis不断尝试启动AOF重写子进程，终于在数小时后将允许的fd数耗尽，此时错误log为“Error opening /setting AOF rewrite IPC pipes: Numerical result out of range”；
与此同时，随着离线作业的完成，内存占用已经下降，但由于fd不足，AOF重写子进程还是不能启动；
注意到，被client长连接占用的socket fd在此过程中是一直没有释放的。直到升级client重启，释放出了一部分fd，AOF重写子进程成功运行，不再刷AOF相关的错误log；
client升级后，我们增加了client并行数，于是需要更多的socket fd来与client通信，但是目前空闲fd仅为之前client停止时释放的数量，于是超出限制的client就无法正常运行了。所以，我们一开始就只看到“Error registering fd event for the new client”这个错误。

这里面有两个问题待确定：

用于与子进程通信的pipe为何没有被关闭
Redis中能打开的fd数量限制如何确定

随后我们直接分析源码查找答案。

源码查证

（一）fd限制

首先，我们定位到client连接报错的主要调用链为 networking.c/acceptCommonHandler => networking.c/createClient => ae.c/aeCreateFileEvent：

static void acceptCommonHandler(int fd, int flags, char *ip) {
    client *c;
    if ((c = createClient(fd)) == NULL) {
        serverLog(LL_WARNING,
            "Error registering fd event for the new client: %s (fd=%d)",
            strerror(errno),fd);
        close(fd); /* May be already closed, just ignore errors */
        return;
    }
    //……
}
int aeCreateFileEvent(aeEventLoop *eventLoop, int fd, int mask,
        aeFileProc *proc, void *clientData)
{
    if (fd >= eventLoop->setsize) {
        errno = ERANGE;
        return AE_ERR;
    }
//……
}

而eventLoop->setsize则是在server.c/initServer中被初始化和设置的，大小为maxclient+128个。而我们maxclient采用Redis默认配置10000个，所以当fd=10128时就出错了。

server.el = aeCreateEventLoop(server.maxclients+CONFIG_FDSET_INCR);

（二）aof重写子进程启动失败为何不关闭pipe

aof重写过程由server.c/serverCron定时时间事件处理函数触发，调用aof.c/rewriteAppendOnlyFileBackground启动aof重写子进程。在rewriteAppendOnlyFileBackground方法中我们注意到如果fork失败，过程就直接退出了。

int rewriteAppendOnlyFileBackground(void) {
    //……
    if (aofCreatePipes() != C_OK) return C_ERR; // 创建pipe
    //……
    if ((childpid = fork()) == 0) {
        /* Child */
        //……
    } else {
        /* Parent */
        //子进程启动出错处理
        if (childpid == -1) {
            serverLog(LL_WARNING,
                "Can't rewrite append only file in background: fork: %s",
                strerror(errno)); // 最初内存不足正是这里打出的错误log
            return C_ERR;
        }
    //……
    }
}

而关闭pipe的方法，是在server.c/serverCron => aof.c/backgroundRewriteDoneHandler 中发现AOF重写子进程退出后被调用：

//……
    /* Check if a background saving or AOF rewrite in progress terminated. */
    if (server.rdb_child_pid != -1 || server.aof_child_pid != -1 ||
        ldbPendingChildren())
    {
        //……
        //任意子进程退出时执行
        if ((pid = wait3(&statloc,WNOHANG,NULL)) != 0) {
            //……
            if (pid == -1) {
                serverLog(……);
            } else if (pid == server.rdb_child_pid) {
                backgroundSaveDoneHandler(exitcode,bysignal);
            } else if (pid == server.aof_child_pid) { //发现是aof重写子进程完成
                backgroundRewriteDoneHandler(exitcode,bysignal); //执行后续工作，包括关闭pipe
            }
            //……
        }
    }
//……

由此可见，如果aof重写子进程没有启动，则pipe将不会被关闭。而下次尝试启动aof重写时，又会调用aof.c/aofCreatePipes创建新的pipe。

解决方案

定位到问题后google相关关键字，发现这一问题早在2015年就被两次在社区上报（参考 https://github.com/antirez/redis/issues/2857），2016年有开发者提交代码修复此问题，直至2017年2月相关修复才被合入主干（参考 https://github.com/antirez/redis/pull/3408）。看来下一版本Redis才会修复此问题，真是一只长寿的bug。

Tips：这只长寿的bug在 3.2.9 版本已经修复了（｡￫‿￩｡)

其实该问题发生概率不大，如果机器内存相对数据量足够大，则无需理会。如果需要处理，一个方案可以参考官方修正方式修改代码：在aof.c/rewriteAppendOnlyFileBackground中，启动失败时调用aof.c/aofClosePipes关闭打开的pipe。

不改代码的规避方案：

设置linux系统的vm.overcommit_memory = 1（其意义可查阅man手册，本文不再展开），尽量减少子进程fork失败的情况；
设置Redis的maxmemory限制，当内存使用达到一定比例时不再接受新的数据；
使用主从备份，或bgsave持久化（RDB方式无此问题），关闭AOF持久化，等下一版本发布。

此外，还可以通过监控手段及早发现问题。目前我们主要通过模调监控Redis服务的被调情况，而对于Redis本身运行状况没有监控措施。而此类问题，其实是可以通过监控Redis本身运行状况及早发现的，这是下一步探索方向。

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

云数据库 Redis

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

云数据库 Redis

登录后参与评论

0 条评论

热度