炼数成金 门户 大数据 Mysql 查看内容

InnoDB最新版本莫名卡死问题深度解析

2017-12-6 10:03| 发布者: 炼数成金_小数| 查看: 10740| 评论: 0|原作者: 王竹峰|来自: 开源数据库论坛ODF
摘要: 今天线上遇到一个问题,MySQL版本是“5.7.19-17-log Percona Server (GPL), wsrep_29.22”,没错,是Percona Xtradb Cluster集群,这个很容易被人说是Galera的问题啊。可以看到,状态都是Killed,说明DBA已经杀过了 ...
数据库 SQL MySQL Hadoop 运维
王竹峰 去哪儿网数据库专家,擅长数据库开发、数据库管理及维护,一直致力于MySQL数据库源码的研究与探索,对数据库原理及实现具有深刻的理解。曾就职于达梦数据库,多年从事数据库内核开发的工作,后转战人人网,任职高级数据库工程师,目前在去哪儿网负责MySQL源码研究与运维、数据库管理和自动化运维平台设计开发及实践工作,是Inception开源项目及《MySQL运维内参》的作者,也是Oracle MySQL ACE。

现象
今天线上遇到一个问题,MySQL版本是“5.7.19-17-log Percona Server (GPL), wsrep_29.22”,没错,是Percona Xtradb Cluster集群,这个很容易被人说是Galera的问题啊。
问题的现象是,查询非常慢,从show processlist;中看到的是这样的:

可以看到,状态都是Killed,说明DBA已经杀过了,但是没有杀掉。时间非常长,有的达到了好几千。
不小心看到了另一种情况:

我们的监控程序,也出现在了show processlist;结果中,竟然也被卡住了。
同时自己又想了一下,发现相关语句其实不慢,之前都是非常快的,怎么现在完全动不了?所以就想着自己试试看查一行记录结果会如何,结果如下:

对应show processlist;信息如下:

结果明显,也是被卡住了,并且还发现,有一个我们的Binlog 备份程序,执行的FLUSH LOGS也被卡住了。
这什么情况?感觉整个实例都被卡死了。因为这是PXC,所以还要看看我们一般会导致问题的情况,比如flow control,结果如下:

同样的,没有任何异常。
那机器呢?当然也是没有任何异常,并且我感觉压力小的有点浪费资源了。

找原因
现在从表面是没有看出什么信息了,只能从深层次来看这个问题了。那首先我们看看堆栈信息了。
结果就是上面的样子,很多个线程,使用pt工具pt-pmp归类之后,总的结果如下(下面我只保留了有关系的堆栈):

结果稍微做一下解释,每一行表示一个堆栈,数字表示这个堆栈在所有信息中出现次数,后面的就是堆栈了,显示不是以一行一行显示,而是以逗号显示将其变为一行了。

研究问题,堆栈是非常有用的,它可以看出线程等待情况,比如死锁等问题是可以从堆栈中看出来的。这个问题的堆栈在观察一会儿之后,发现根本不会变,每次都完全一样,那这样对查问题是很有好处的,因为堆栈这个只能作为参考,如果一直变,那看到的信息就不准确,不能真实反应问题所在,而如果不变,那就好说了,因为越是固定,反应问题能力就越强。
通过研究上面堆栈图发现,被阻塞的位置有以下几个:
srv_conc_enter_innodb:os_thread_sleep,这个位置,是所有从Server层来的请求,只要进入InnoDB并发管理区,都要做的操作,在这里判断当前InnoDB的队列有多少正在执行,如果没有空闲,就要等待,队列大小就是参数innodb_thread_concurrency指定的大小。目前来看,应该是请求太多,导致没有空闲可用,所以就等待了。

get_current_log:inline_mysql_mutex_lock,这个在执行show master status;出现的等待堆栈,要等待的是Lock_log这个临界区。在等待,说明已经有线程进入了,那是谁呢?如果我们能找到谁进入了,那就可以破掉这个圈。

rotate_and_purge:pthread_mutex_lock,这个操作是备份线程做Flush Log导致的,这里也是在等待Lock_Log的临界区。从上面的堆栈图来看,有两个地方的堆栈出现了Flush Logs,并且堆栈还不一样,就是倒数第二行和倒数第三行,可以看到,倒数第三行,其实最终是等在了srv_conc_enter_innodb:os_thread_sleep处,这也说明了它已经进入了Lock_Log临界区。所以可以知道,show master status;等待的原因已经找到了,似乎他现在与问题已经没有什么关系了。

enroll_for:pthread_cond_wait,这个位置,逻辑是我们熟悉的Ordered_commit的过程,这个在《MySQL运维内参》中解释的非常详细了,这是在进入每一个队列的时候,都需要做的一个操作,就是等待流水线的前进,然后获取加工权。因为进入FLUSH队列时,需要拿到LOCK_log临界区的锁的,而从上面可以看出,FLUSH LOGS已经拿到了,并且已经被卡住了,那当然这里也是不能进入临界区的,也是被卡住了,所以这里说明,与Ordered_commit也没关系了。

这里我们可以推测出,这根本不是一个死锁,因为最终被卡住,其实只卡在了同一个地方,即srv_conc_enter_innodb:os_thread_sleep。那我们就要看看这个函数是干什么了,为什么长时间睡在这里?这个时候从MySQL之外的信息中,已经不能再看到什么有用的信息了,只能靠我们万能的能解决问题的最准确的代码了:

static
void
srv_conc_enter_innodb_with_atomics(
/*===============================*/
    trx_t*  trx)            /*!< in/out: transaction that wants
                    to enter InnoDB */
{
    for (;;) {
        ulint   sleep_in_us;
        /*如果参数innodb_thread_concurrency为0,则直接返回即可,不做处理,这也正是为什么我们可以将这个参数设置为0之后,所有问题都解决了的原因*/
        if (srv_thread_concurrency == 0) {
            if (notified_mysql) {
                (void) os_atomic_decrement_lint(&srv_conc.n_waiting, 1);
                thd_wait_end(trx->mysql_thd);
            }
            return;
        }
        /*如果当前InnoDB队列中活动事务数小于innodb_thread_concurrency,则将活动事务数加1,也就是当前事务加入到活动队列中。如果活动事务数已经达到了innodb_thread_concurrency,则需要sleep,而不会进入下面的if语句块了*/
        if (srv_conc.n_active < (lint) srv_thread_concurrency) {
            ulint   n_active;
            /* Check if there are any free tickets. */
            n_active = os_atomic_increment_lint(
                &srv_conc.n_active, 1);
            if (n_active <= srv_thread_concurrency) {
                srv_enter_innodb_with_tickets(trx);
                if (notified_mysql) {
                    (void) os_atomic_decrement_lint(&srv_conc.n_waiting, 1);
                    thd_wait_end(trx->mysql_thd);
                }
                if (srv_adaptive_max_sleep_delay > 0) {
                    if (srv_thread_sleep_delay > 20&& n_sleeps == 1) {
                        --srv_thread_sleep_delay;
                    }
                    if (srv_conc.n_waiting == 0) {
                        srv_thread_sleep_delay >>= 1;
                    }
                }
                return;
            }
            /* Since there were no free seats, we relinquish
            the overbooked ticket. */
            (void) os_atomic_decrement_lint(
                &srv_conc.n_active, 1);
        }
      /*other code*/
        sleep_in_us = srv_thread_sleep_delay;
        /* Guard against overflow when adaptive sleep delay is on. */
        if (srv_adaptive_max_sleep_delay > 0
            && sleep_in_us > srv_adaptive_max_sleep_delay) {
            sleep_in_us = srv_adaptive_max_sleep_delay;
            srv_thread_sleep_delay = static_cast<ulong>(sleep_in_us);
        }
      /*Sleep*/
        os_thread_sleep(sleep_in_us);
        trx->innodb_que_wait_timer += sleep_in_us;
        ++n_sleeps;
        if (srv_adaptive_max_sleep_delay > 0 && n_sleeps > 1) {
            ++srv_thread_sleep_delay;
        }
    }
}

从代码中可以看出,这里有些参数可以控制,并且确实有地方是在sleep,sleep的时间对应参数srv_adaptive_max_sleep_delay,我们了解到,这个参数的作用是在微调InnoDB的入队压力的,在压力大的时候,可以稍微等一下,默认值是150000,数字好大啊,这单位是秒么?其实不是,是微秒,换算为秒的话,才不到一秒钟,所以可以断定,不是等的时间太长,而是这个函数出现了死循环。所以这里原有打算修改这个参数的,将其改小一些,也无济于事了。
那我们就要认真看看这个代码了。可以看到,只要srv_thread_concurrency的值为0,那就这个函数直接return,不会再去等待了,所以现在可以猜测,解决这个问题可以通过将这个参数修改为0,但现在还不是时候。

我们又看到,有一个判断“srv_conc.n_active < (lint) srv_thread_concurrency”,如果这个值小于参数srv_thread_concurrency(对应参数innodb_thread_concurrency),则会将srv_conc.n_active计数加1,然后加1之后再判断,如果还小于srv_thread_concurrency,则结果会return,并且我们看完这个函数srv_conc_enter_innodb_with_atomics,除了为0的情况下,只有这个地方会return了,那既然没有出去,那我们猜测,这个条件是没有满足的。

那我们现在有一个办法,就是将这个参数改大,让其满足。人为构造这种场景,看看能不能结束这个死循环。

通过了解,参数srv_thread_concurrency较大值为1000,当前我们设置的是24,所以我就将其设置为1000,结果。。。
对MySQL没有任何影响。。说明有可能的情况是,srv_conc.n_active的值大于1000了都。当然这是猜测,死循环也是猜测,这里说说这个值的意义,他表示当前InnoDB中,有多少个线程正在执行。什么?那根据我们的猜测,就是说有大于1000个线程正在执行?要知道,这只是猜测。
那设置大了没用,那设置小了看看呗。设置为0吧。只能这样。
set global innodb_thread_concurrency = 0;
语句下去了,show processlist;看看如下:

show processlist;结果是干干净净啊,真的解决了,所以被卡住的操作都消失了,现在可以证明的是,确实卡在了这里。
然而。。。虽然证明了确实卡在这里,环境就这么一下子没了。怎么办?只好根据这种场景继续测试了。执行命令:show master status;结果,没事儿。
再执行命令:flush logs。结果,没事儿。纳闷儿了。
突然想起来,刚才将参数innodb_thread_concurrency设置为0之后,还没有设置回去,还有机会,心跳加快了。
set global innodb_thread_concurrency = 24;
继续来来来。。。这回再执行语句:

卡住了竟然。万幸啊,竟然环境还在。
现在可以证明的事情是,没有任何线程在执行语句的情况下,一个查询语句就能被锁住,而执行其它的,比如show processlist;、show master status;等是不会被锁住的。
也就是说,只要对InnoDB访问了,那就会被锁住,我们可以找到一千个理由去测试这个结果,没错的,就是这样。那我们现在可以断定了,确实是那个函数srv_conc_enter_innodb_with_atomics的问题了。
可是现在关键的问题是,当前运行是线程环境,是Release版本的,如何能知道srv_conc.n_active的值呢?因为只有知道这个值了,才可以断定这个问题的存在。从代码中看了一下,定义类型为static,想写个程序去访问也做不到了。
这个时候想到,如果InnoDB能再多显示一些信息多好啊,这样的信息,为什么不能提供出来,让我们监控到呢?这出问题了,想知道这个值,又拿不到,该如何做?

此时我找了苏斌(Oracle公司InnoDB官方开发人员),我问有没有办法输出这个值,他马上告诉我说,show engine innodb status\G里面有。呃。。。我晕了竟然,为啥断定这个值MySQL没有输出呢?
查了确实有,在信息的最下面,样子如下:

没错,就是这块儿,具体信息是:“6009 queries inside InnoDB, 3 queries in queue”,第一个数字表示的是srv_conc.n_active,第二个表示的是srv_conc.n_waiting,啊?也就是说,srv_conc.n_active的值竟然这么大?6009?怎么可能。

现在问题很明显了,srv_conc.n_active的值是6009,所以我们即使将innodb_thread_concurrency的值设置为较大值1000,也是没用的,那个代码分支根本不会进去。所以在这里面出现了死循环。

此时断定了一个问题,这是InnoDB的Bug了。肯定是计数错误,只加不减,导致了这样的问题。

那这个问题该如何解决呢?目前来看,有两种办法可以解决这个问题:
将参数innodb_thread_concurrency设置为0,这样一劳永逸。
重启数据库,将这个值清0。但。。。啥时候又会出现啊?

问题总结
这个问题很严重,非常严重,只要它的值超过了参数innodb_thread_concurrency的值,那InnoDB就完全做不了任何事情了,表现就是直接卡死,Control+C也没用。

解决方法已经有了。出现问题的版本呢,这是在MySQL5.7.19中出现的。这是目前版本。

但关键问题是,如何重现?如何条件下,可以让这个值的计数出问题?这是较大的问题,我可以从代码上分析并找到问题原因,但问题本身如何产生,这个还暂时不知道,需要分析代码才能知道了。因为只是想着通过测试来重现,这个几无可能了。

这个问题已经提交给了苏斌同学。相信这么大的问题肯定很快就会在新版本中解决掉。

对于已经上线使用的同学,可以自己通过show engine innodb status\G信息检查一下这个值,然后改将参数innodb_thread_concurrency改为0,当然不改也可以,要时刻监控srv_conc.n_active的值,然后再逐个解决。但出现原因不知道,总是有点担心的。

因为现在这个问题的起因,还不太清楚,所以我还会继续关注。

最后再想说一句话,这个问题与Galera还是没有关系的,并且在版本的MySQL5.7.19中还是存在的,只是发生在了Galera集群中,所以我猜想只要是MySQL5.7.19就会有问题,与什么类型的集群架构没有关系。所以使用这个版本的同学,可能就要注意一下了。

欢迎加入本站公开兴趣群
软件开发技术群
兴趣范围包括:Java,C/C++,Python,PHP,Ruby,shell等各种语言开发经验交流,各种框架使用,外包项目机会,学习、培训、跳槽等交流
QQ群:26931708

Hadoop源代码研究群
兴趣范围包括:Hadoop源代码解读,改进,优化,分布式系统场景定制,与Hadoop有关的各种开源项目,总之就是玩转Hadoop
QQ群:288410967 

鲜花

握手

雷人

路过

鸡蛋

相关阅读

最新评论

热门频道

  • 大数据
  • 商业智能
  • 量化投资
  • 科学探索
  • 创业

即将开课

  GMT+8, 2017-12-17 20:05 , Processed in 0.146757 second(s), 26 queries .