导航：首页 > 数据库 >

Mysql 5.7 Gtid内部学习(九) 实际案例(一)

发表于：2024-10-01 作者：千家信息网编辑

千家信息网最后更新 2024年10月01日，简书地址：http://www.jianshu.com/p/2c25842d58d3本案例是一个朋友的案例他也写了出来如下：https://mp.weixin.qq.com/s/XSnFkuYzIlG

千家信息网最后更新 2024年10月01日Mysql 5.7 Gtid内部学习(九) 实际案例(一)简书地址：
http://www.jianshu.com/p/2c25842d58d3

本案例是一个朋友的案例他也写了出来如下：
https://mp.weixin.qq.com/s/XSnFkuYzIlGWMaXIl-oPeQ
但是和他交流后他也准备改因为分析有一些小问题。

一、触发条件

binlog_gtid_simple_recovery=false。
5.7.6以上版本。
Gtid 关闭或者Gtid中途开启有大量的未开启Gtid的binlog。

二、本案例回顾

版本：MySQL版本 5.7.19。
故障为：大概每半小时发生一次故障，整个Mysql压力巨大，很多简单的操作都相应缓慢。使用iotop，top等工具都发现Mysql某个线程有大量的I/O。
分析方法：使用strace发现有大量的binlog文件读取。
binlog_gtid_simple_recovery=false。
Gtid关闭，中途开启，但是留下了很多未开启Gtid的binlog。
数据库没有重启，但是由于expire_logs_days触发了binlog删除。

三、故障分析

其实本案例就是前文第七部分总结中的：

Gtid关闭，simple_recovery=flase5.7.6以上:这种方式一定得到正确的Gtid集合重启Mysql不扫秒全部的binlog，如果是中途打开GTID重启任然需要扫描多个binlog因为需要找到Gtid event。purge binlog或者超过参数expire_logs_days参数设置不触发全binlog扫描，如果是中途打开GTID重启任然需要扫描多个binlog因为需要找到Gtid event。

从案例中我们得知是中途开启的Gtid，但是留下了很多未开启Gtid的binlog，从第六部分源码bool MYSQL_BIN_LOG::init_gtid_sets()函数的分析，我们知道删除binlog后也会触发正向查找来获取gtid_purged(Gtid_state.lost_gtids)。当读取到第一个binlog的时候虽然获取到了PREVIOUS GTID EVENT但是没有GTID EVENT，而simple_recovery=flase所以需要继续查找下一个文件，直到找到同时包含PREVIOUS GTID EVENT和GTID EVENT的那个binlog才会停止，那么显然这种情况下那些Gtid关闭的时候生成的binlog将会全部扫描一遍，如果量大那么代价将是巨大的。
而案例中每半个小时会触发一次binlog切换，因为触发超过expire_logs_days参数设置导致binlog进行删除，触发了大量的binlog扫描。
显然有了前面的基础这个案例很容易分析。

四、案例模拟

这个案例非常好模拟。我打算直接使用strace查看。因为不是每位朋友都能方便使用GDB调试。
使用测试版本社区版本5.7.17：

+---------------+-----------+| Log_name      | File_size |+---------------+-----------+| binlog.000027 |       198 || binlog.000028 |       198 || binlog.000029 |       198 || binlog.000030 |       198 || binlog.000031 |       198 || binlog.000032 |       198 || binlog.000033 |       198 || binlog.000034 |       198 || binlog.000035 |       198 || binlog.000036 |       198 || binlog.000037 |       198 || binlog.000038 |       198 || binlog.000039 |       198 || binlog.000040 |       198 || binlog.000041 |       198 || binlog.000042 |       198 || binlog.000043 |       154 |+---------------+-----------+mysql> show variables like '%gtid%';+----------------------------------+-----------+| Variable_name                    | Value     |+----------------------------------+-----------+| binlog_gtid_simple_recovery      | OFF       || enforce_gtid_consistency         | ON        || gtid_executed_compression_period | 1000      || gtid_mode                        | OFF       || gtid_next                        | AUTOMATIC || gtid_owned                       |           || gtid_purged                      |           || session_track_gtids              | OFF       |+----------------------------------+-----------+8 rows in set (0.02 sec)mysql> show variables like '%expir%';+--------------------------------+-------+| Variable_name                  | Value |+--------------------------------+-------+| disconnect_on_expired_password | ON    || expire_logs_days               | 1     |+--------------------------------+-------+2 rows in set (0.06 sec)

然后我修改了系统时间同时Mysql开启Gtid

[root@test1 ~]# date -s '2017-12-13 10:10:10'Wed Dec 13 10:10:10 CST 2017mysql> set global gtid_mode=1;Query OK, 0 rows affected (0.02 sec)mysql> set global gtid_mode=2;Query OK, 0 rows affected (0.01 sec)mysql> set global gtid_mode=3;Query OK, 0 rows affected (0.02 sec)mysql> show variables like '%gtid_mode%';+---------------+-------+| Variable_name | Value |+---------------+-------+| gtid_mode     | ON    |+---------------+-------+1 row in set (0.02 sec)

到一步我们已经达到了触发的标准，只要手动触发一次flush binary logs，让binlog刷新就会看到。当然线上是binlog满了做的切换。
这个时候开始做strace，并且做flush tables，我们观察到

mysql> flush binary logs;Query OK, 0 rows affected (0.30 sec)strace：[pid  6551] 10:17:15.936738 read(62, "/mysql/mysql5.7.17/binlog.000027"..., 528) = 528 <0.000039>[pid  6551] 10:17:15.936834 stat("/mysql/mysql5.7.17/binlog.000027", {st_mode=S_IFREG|0640, st_size=198, ...}) = 0 <0.000025>[pid  6551] 10:17:15.936925 lseek(3, 0, SEEK_SET) = 0 <0.000017>[pid  6551] 10:17:15.936983 read(3, "/mysql/mysql5.7.17/binlog.000043"..., 165) = 165 <0.000018>[pid  6551] 10:17:15.937076 lstat("/mysql", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000020>[pid  6551] 10:17:15.937144 lstat("/mysql/mysql5.7.17", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000586>[pid  6551] 10:17:15.937819 unlink("/mysql/mysql5.7.17/binlog.000027") = 0 <0.000109>[pid  6551] 10:17:15.938009 stat("/mysql/mysql5.7.17/binlog.000028", {st_mode=S_IFREG|0640, st_size=198, ...}) = 0 <0.000021>[pid  6551] 10:17:15.938119 lstat("/mysql", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000020>[pid  6551] 10:17:15.938228 lstat("/mysql/mysql5.7.17", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000021>[pid  6551] 10:17:15.938314 unlink("/mysql/mysql5.7.17/binlog.000028") = 0 <0.000073>.....[pid  6551] 10:17:15.954677 lstat("/mysql/mysql5.7.17", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000019>[pid  6551] 10:17:15.954756 unlink("/mysql/mysql5.7.17/binlog.000041") = 0 <0.000099>[pid  6551] 10:17:15.954920 stat("/mysql/mysql5.7.17/binlog.000042", {st_mode=S_IFREG|0640, st_size=198, ...}) = 0 <0.000021>[pid  6551] 10:17:15.955022 lstat("/mysql", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000018>[pid  6551] 10:17:15.955087 lstat("/mysql/mysql5.7.17", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0 <0.000018>[pid  6551] 10:17:15.955159 unlink("/mysql/mysql5.7.17/binlog.000042") = 0 <0.000130>

受限篇幅我这里删除了一些。我们看到很多read/lseek系统调用正是读取binlog的证据。
至此整个案例模拟完成。