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

前言

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
……

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

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

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

  1. 用于与子进程通信的pipe为何没有被关闭
  2. 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。

不改代码的规避方案:

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

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

原创声明,本文系作者授权云+社区发表,未经许可,不得转载。

如有侵权,请联系 yunjia_community@tencent.com 删除。

编辑于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏散尽浮华

Mysql优化系列(0)--总结性梳理

对于一个网站来说,在运行很长一段时间后,数据库瓶颈问题会越来越暴露出来。作为运维人员,对数据库做必要的优化十分重要! 下面总结以往查阅到的以及自己工作中的一些优...

1908

容纳有状态的应用程序

像Docker Engine这样的应用程序容器技术提供了底层应用程序组件的基于标准的打包和运行时的管理。

18610
来自专栏linjinhe的专栏

MySQL半同步复制

MySQL通过复制(Replication)实现存储系统的高可用。目前,MySQL支持的复制方式有:

2595
来自专栏Linux运维学习之路

mysql存储引擎、事务

MySQL存储引擎介绍 文件系统 操作系统组织和存取数据的一种机制。 文件系统是一种软件。 文件系统类型 ext2  ext3  ext4  xfs 数据 不管...

34914
来自专栏猿天地

solr or es 结合弥补mongodb的全文检索功能

最近将公司的solr集群升级到了最新的6.5版本。 之前用了N年的是3点多的版本,那个时候solr还不支持自带的集群,集群方式都是自己实现的。 公司里用的最多的...

38414
来自专栏linux运维学习

linux学习第五十七篇:复习扩展

不停库不锁表在线主从配置 http://seanlook.com/2015/12/14/mysql-replicas/ MySQL之间数据复制的基础是二进制日...

1796
来自专栏idba

DDL 失败案例一则

今天对线上某个业务的大表120G进行重建表操作时遇到报错,该表有个比较显著的特征是*写入量比较大,每天写入加更新的频率在数千万级别。大致的环境

672
来自专栏编程坑太多

悲观锁与乐观锁

1095
来自专栏Jackson0714

【T-SQL进阶】02.理解SQL查询的底层原理

34011
来自专栏idba

MySQL常见slave延迟原因以及解决方法

一 序言 在运维线上M-M 架构的MySQL数据库时,接收的比较多关于主备延时的报警:

873

扫码关注云+社区