大数据培训班 InnoDB最新版本莫名卡死问题深度解析

光环大数据（大数据培训的专业机构），了解到今天线上遇到一个问题，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之外的信息中，已经不能再看到什么有用的信息了，只能靠我们万能的能解决问题的最准确的代码了：
staticvoidsrv_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就会有问题，与什么类型的集群架构没有关系。所以使用这个版本的同学，可能就要注意一下了。

 　   大数据+时代，大数据培训机构，就选光环大数据！

 　　原创文章，转载请注明出处：光环大数据官网。

大数据培训、人工智能培训、Python培训、大数据培训机构、大数据培训班、数据分析培训、大数据可视化培训，就选光环大数据！光环大数据，聘请专业的大数据领域知名讲师，确保教学的整体质量与教学水准。讲师团及时掌握时代潮流技术，将前沿技能融入教学中，确保学生所学知识顺应时代所需。通过深入浅出、通俗易懂的教学方式，指导学生更快的掌握技能知识，成就上万个高薪就业学子。 更多问题咨询，欢迎点击------>>>>在线客服！