MySQL：5.6 大事务show engine innodb status故障一例

冷不防 2023-07-10 14:21 14阅读 0赞

**导读**：

> 作者：高鹏（网名八怪），《深入理解MySQL主从原理32讲》系列文的作者。

**《深入理解MySQL主从原理32讲》**

**扫码订阅：**

![format_png][]

今天遇到一个朋友的线上问题，大概意思就是说，我有一个线上的大事务大概100G左右，正在做回滚，当前看起来似乎影响了线上的业务，并且回滚很慢，是否可以减轻对线上业务的影响。并且朋友已经取消了双1设置，但是没有任何改观。版本MySQL 5.6

首先我们需要知道的是，MySQL并不适合大事务，大概列举一些MySQL中大事务的影响：

*  binlog文件作为一次写入，会在sync阶段消耗大量的IO，会导致全库hang主，状态大多为query end。
 *  大事务会造成导致主从延迟。
 *  大事务可能导致某些需要备份挂起，原因在于flush table with read lock，拿不到MDL GLOBAL 级别的锁，等待状态为 Waiting for global read lock。
 *  大事务可能导致更大Innodb row锁加锁范围，导致row锁等待问题。
 *  回滚困难。

基于如上一些不完全的列举，我们应该在线上尽可能的避免大事务。好了我们下面来进行问题讨论。

**一、问题**

前面已经说了，我们已经取消了双1设置，所谓的双1就是 sync\_binlog=1和 innodb\_flush\_log\_at\_trx\_commit=1。这两个参数线上要保证为1，前者保证binlog的安全，后者保证redo的安全，它们在数据库crash recovery的时候起到了关键做用，不设置为双1可能导致数据丢失。具体的参数含义不做过多讨论。但是这里的问题是即便取消了双1，没有任何改观，因此似乎说明IO问题不是主要瓶颈呢？下面我们来看几个截图：

*  **vmstat 截图**

![format_png 1][]

*  **iostat 截图**

![format_png 2][]

![format_png 3][]

*  **top -Hu截图**

![format_png 4][]

我们重点观察vmstat的r 和 b列发现，IO队列没有有什么问题 并且wa%并不大。我们观察iostat中的%util和读写数据大小来看问题不大，并且tps远没达到极限（SSD盘）。我们top -Hu 可以观察到 %us不小，并且有线程已经打满了（99.4%CPU）一个CPU核。

因此我们可以将方向转为研究CPU瓶颈的产生，希望能够对问题有帮助，然后从提供的perf top中我们有如下发现：

![format_png 5][]

好了我们将问题先锁定到lock\_number\_of\_rows\_locked这个函数上。

**二、函数lock\_number\_of\_rows\_locked的作用**

朋友用的5.6，但是我这里以5.7.26的版本进行描述。然后下一节描述5.6和5.7算法上的关键差异。

不知道大家是否注意过show engine innodb status中的这样一个标志：

![format_png 6][]

这个标记就来自函数lock\_number\_of\_rows\_locked，含义为当前事务加行锁的行数。而这个函数包裹在函数lock\_print\_info**\_**all\_transactions下面，lock\_print\_info\_all\_transactions函数是打印我们通常看到show engine innodb status中事务部分的核心参数。我们来看一下简单的流程：

PrintNotStarted print_not_started(file);//建立一个结构体，目的是做not start 事务的打印
        ut_list_map(trx_sys->mysql_trx_list, print_not_started); //这个地方打印出那些事务状态是no start的事务。mysql_trx_list是全事务。
        const trx_t*    trx;
        TrxListIterator trx_iter; //这个迭代器是trx_sys->rw_trx_list 这个链表的迭代器
        const trx_t*    prev_trx = 0;
        /* Control whether a block should be fetched from the buffer pool. */
        bool        load_block = true;
        bool        monitor = srv_print_innodb_lock_monitor && (srv_show_locks_held != 0);
        while ((trx = trx_iter.current()) != 0) { //通过迭代器进行迭代 ，显然这里不会有只读事务的信息，全部是读写事务。
           ...
            /* If we need to print the locked record contents then we
            need to fetch the containing block from the buffer pool. */
            if (monitor) {
                /* Print the locks owned by the current transaction. */
                TrxLockIterator& lock_iter = trx_iter.lock_iter();
                if (!lock_trx_print_locks( //打印出锁的详细信息
                        file, trx, lock_iter, load_block))

简单的说就是先打印哪些处于not start的事务，然后打印那些读写事务的信息，当然我们的回滚事务肯定也包含在其中了，需要注意的是只读事务show engine不会打印。对于处于回滚状态的事务我们可以在show engine中观察到如下信息：

![format_png 7][]

函数trx\_print\_low可以看到大部分的信息，这里就不详细解释了。既然如此我们需要明白lock\_number\_of\_rows\_locked是如何计算的，下面进行讨论。

**三、函数lock\_number\_of\_rows\_locked的算法变化**

上面我们说了函数lock\_number\_of\_rows\_locked函数会打印出当前事务加行锁的行数。那么我们来看一下5.6和5.7算法的不同。

*  5.7.26

实际上只有如下一句话：

return(trx_lock->n_rec_locks);

我们可以看到这是返回了一个计数器，而这个计数器的递增就是在每行记录加锁后完成的，在函数lock\_rec\_set\_nth\_bit的末尾可以看到 ++lock->trx->lock.nreclocks ，因此这是一种预先计算的机制。

因此这样的计算代价很低，也不会由于某个事务持有了大量的锁，而导致计算代价过高。

*  5.6.22

随后我翻了一下5.6.22的代码，发现完全不同如下：

for (lock = UT_LIST_GET_FIRST(trx_lock->trx_locks); //使用for循环每个获取的锁结构
             lock != NULL;
             lock = UT_LIST_GET_NEXT(trx_locks, lock)) {
            if (lock_get_type_low(lock) == LOCK_REC) { //过滤为行锁
                ulint   n_bit;
                ulint   n_bits = lock_rec_get_n_bits(lock);
                for (n_bit = 0; n_bit < n_bits; n_bit++) {//开始循环每一个锁结构的每一个bit位进行统计
                    if (lock_rec_get_nth_bit(lock, n_bit)) {
                        n_records++;
                    }
                }
            }
        }
        return(n_records);

我们知道循环本身是一种CPU密集型的操作，这里使用了嵌套循环实现。因此如果在5.6中如果出现大事务操作了大量的行，那么获取行锁记录的个数的时候，将会出现高耗CPU的情况。

**四、原因总结和解决**

有了上面的分析我们很清楚了，触发的原因有如下几点：

*  MySQL 5.6版本
 *  有大事务的存在，大概100G左右的数据加行锁了
 *  使用了show engine innodb status

这样当在统计这个大事务行锁个数的时候，就会进行大量的循环操作。从现象上看就是线程消耗了大量的CPU资源，并且处于perf top的第一位。

知道了原因就很简单了，找出为频繁使用show engine innodb status的监控工具，随后业务全部恢复正常，IO利用率也上升了如下：

![format_png 8][]

当然如果能够使用更新的版本比如5.7及8.0 版本将不会出现这个问题，可以考虑使用更高版本。

分析性能问题需要首先找到性能的瓶颈然后进行集中突破，比如本例中CPU资源消耗更加严重。也许解决问题就在一瞬间。

**五、其他**

最后通过朋友后面查询的bug如下：https://bugs.mysql.com/bug.php?id=68647 发现印风（翟卫翔）已经在多年前提出过了这个问题，并且做出了修改意见，并且这个修改意见官方采纳了，也就是上面我们分析的算法改变。经过印风（翟卫翔）的测试有bug中有如下描述：

*  From perf top, function locknumberofrowslocked may occupy more than 20% of CPU sometimes

也就是CPU消耗会高达20%。

下面是5.7.26调用栈帧：

![format_png 9][]

**END**

--------------------

**识别下方二维码添加作者为好友**

![format_png 10][]

由叶老师主讲的知数堂「MySQL优化课」第17期即将开始，我们的课程从第15期就升级成MySQL 8.0版本了，现在上车刚刚好，一起开启MySQL 8.0的修行之旅吧。

扫码入群了解「MySQL优化」课吧，有助教妹子在等着哟

![format_png 11][]

另外，叶老师在腾讯课堂的短课程《**MySQL性能优化**》已于昨晚开课，本课程讲解读几个MySQL性能优化的核心要素：**合理利用索引，降低锁影响，提高事务并发度**。

目前已有几个录播视频，并且可以回看5-15分钟不等。

![format_png 12][]

下面是报名小程序码

![format_png 13][]

点“在看”给我一朵小黄花![format_png 14][]

![format_png 15][]

[format_png]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2pwZy9udHM1Mm5IaGVUeDlIMzlrd0ZVVmtWdWVTQUY2eGhEY1Zma2lhYm1XbkM1Y1VodFBhaWJyZVFmRFNXV05vbTdQcmc0amVWaWNaY3hFUWlhWFVDMkNnNTRIaWNnLzY0MA?x-oss-process=image/format,png
[format_png 1]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2bmtsa3pwSTFNQjhzdGx2WUQyOEJjVkFpYWlhemljZzZhRFZzTk1KOFdhemljS3NWRlhuem5QOEN3US82NDA?x-oss-process=image/format,png
[format_png 2]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2UUtWYWFYS0RSVmF6Tzk2TFoyVEpaNkNlcGJURXFpYjMyUUNGUU01YVhuWTJGYWJvRmEzc2licWcvNjQw?x-oss-process=image/format,png
[format_png 3]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2bkUxaWN6RUE5V2pMcWFLZXpmQnFwYnhSZmtKZmN4a2liWlg4c3RMZFo5RXBiSEtVRmNRZmlhaWFOQS82NDA?x-oss-process=image/format,png
[format_png 4]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2bmNMZTNTeGRzSzhmYkkxSXFRUVFBb2NPVkdpYk9QS2VsTWpMcDVaQ2FNcWNUNVJXYWN2eUZjdy82NDA?x-oss-process=image/format,png
[format_png 5]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2VkFRVzFCYXdDeEJ6Uzk3ZTBRTmtOcFF2eEZuRmx3MnUzUm5YM2lhcUVxaWNzZHByVzJzTlduZGcvNjQw?x-oss-process=image/format,png
[format_png 6]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2OENuMEdpYXVoOHpGdWw2MW5GaWFpYjB4cDNHM3FpY0JMTkZJcnpGcDd2SVVONjZ2TTNzT1pYRW95QS82NDA?x-oss-process=image/format,png
[format_png 7]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2VUhVUmhjaWJPR20yUlEyeVRNZXVmMUl6ZlJvcGNzVzRPOE1kSnVhSGJSNzRURDM2bmVXRXJoUS82NDA?x-oss-process=image/format,png
[format_png 8]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2aWFscnF2RWZOaWJTeG50YmV5MHhoVm5KdGMyQTlTT29RdzJVU2RQWGRxWUJCWmliYjNSUDlLMG5nLzY0MA?x-oss-process=image/format,png
[format_png 9]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUendpYUFBaWFsNnJFcmJjNmhuTUZoZ1A2WENRYnRWMTlZeVJFRjZrdU4yQmdwaWEzQXU2YWNUWEJZeGhkZHBpY2dnMTNYTkQ1RDBLWUZLTncvNjQw?x-oss-process=image/format,png
[format_png 10]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy83aDRpY0o0aWNzSkJqUHdoR1lzZU1hOVNkY3pSUjZGUDExWlFRYmdpYjA3ZnVQaWFLYTFCWk4xTTlRQ3NHNkw5MnpFOEt1a0VlVjd2aWNCRHV1aWFkUTdWZDczZy82NDA?x-oss-process=image/format,png
[format_png 11]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUd1ppY3FBUno0bzVzU1hEemdqZWlib09FWGtEaWN6VGtUOGljUWRFUmlhZHlJVTJ1V2dkaWN6MGVua3JWQUxFZm1SeFFNSUNoR3lNUkI2azhMZy82NDA?x-oss-process=image/format,png
[format_png 12]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X3BuZy9udHM1Mm5IaGVUd1RFNXhaMUJHMWljY1ZpYmFzc0h3TVB5cE5pY1NOYXh4NVRxaHlVNkxha0VlckM5eTFwOWpOWWxZWGJCcW12QW1yb3I5dVU5aDB1RGNTQS82NDA?x-oss-process=image/format,png
[format_png 13]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL21tYml6X2pwZy9udHM1Mm5IaGVUeUE0TWRFaWF1UDBlR1lMdVlXNXhORU9tdzNHeHlkWGxiRGcyS0Rrd2liU2lhS0lZS1Y2aFQ5MDNvcnhERmliOVZSYzFTWkRQVXUxTmJvWUEvNjQw?x-oss-process=image/format,png
[format_png 14]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X2dpZi83aDRpY0o0aWNzSkJnZUQyQ2pNaWJ0VThQRXROcW5wSGFpY3FKZHlIUFE0VWxBa1Y4aWF6b1BsRDJITEFOaWFZMWNMN2pVOUtuekhiNFVPNGszOThLazBUdDViQS82NDA?x-oss-process=image/format,png
[format_png 15]: https://imgconvert.csdnimg.cn/aHR0cHM6Ly9tbWJpei5xcGljLmNuL3N6X21tYml6X3BuZy83aDRpY0o0aWNzSkJnZUQyQ2pNaWJ0VThQRXROcW5wSGFpY3FqSGtXWHBPcGttZG5HMlFXSWxPbjJVeE9KUkNFdDNTVWdGY1FiVTlvNFdHc1p2OTVvRGhZMVEvNjQw?x-oss-process=image/format,png