本案例是一个朋友的案例他也写了出来如下:
https://mp.weixin.qq.com/s/XSnFkuYzIlGWMaXIl-oPeQ
但是和他交流后他也准备改因为分析有一些小问题。
其实本案例就是前文第七部分总结中的:
Gtid关闭,simple_recovery=flase 5.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 2017 mysql> 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的证据。
至此整个案例模拟完成。
前文已经描述过在5.7.6以上binlog_gtid_simple_recovery应该设置为true,这样可以避免可能的大量的binlog的扫描。具体分析可以参考第七节和从第六部分源码bool MYSQL_BIN_LOG::init_gtid_sets()函数的分析。
作者微信:
免责声明:本站发布的内容(图片、视频和文字)以原创、转载和分享为主,文章观点不代表本网站立场,如果涉及侵权请联系站长邮箱:is@yisu.com进行举报,并提供相关证据,一经查实,将立刻删除涉嫌侵权内容。