描述：
程序反映当一个游戏服开服一段时间后，其使用的MySQL每隔一段时间都会出现几十条慢日志，慢日志集中在1到2秒内连续刷出，卡顿平均在60秒左右。一天当中每个时间段都有概率出现，即使是半夜3,4点没什么玩家的时候。
定位(trouble troubleshooting)：
根据描述，基本排除是程序代码的问题，因为游戏高峰期打世界BOSS的时候（每天中午12点玩家最活跃的时候）都不会出现慢日志，就算再慢也不会真的有60秒的卡顿。即使如此还是先每秒执行一次show processlist命令进行监控，当慢日志出现时，可以看看是哪些sql语句在执行并且卡住。结果发现每次出现慢日志时，不管是什么sql语句，都会在执行commit阶段的时候卡住。
commit是指提交事务，每次提交事务时都会去写innodb的事务日志和binlog日志，这些日志每写到一定的大小会进行轮转，这个过程会锁住当前正在写的日志文件，把数据彻底刷到磁盘，然后新建一个日志文件并将日志写到这个新的文件中，如果这个过程持续过长，那么应用程序新产生的commit势必会卡住。故怀疑如此多的commit定时卡住跟日志文件的轮转有关，进一步调查发现每次binlog文件的轮转必定会产生的新的慢日志，当轮转结束后慢日志消失，所以问题定位在binlog的轮转上。
尝试：
一开始尝试优化binlog的相关配置参数，比如sync_binlog设为0，减轻binlog的IO压力，max_binlog_cache_size默认为1G，把它设小一些降低轮转时的IO，结果发现还是会处理慢日志，只不过卡顿时间由平均的60秒降低到10秒左右。
进一步分析，日志文件轮转这个过程无非就是把原有的文件刷到硬盘并生成一个新的，这个操作应该是比较简单且快速，也比较轻量，没有什么复杂逻辑，也不应该耗费10秒的时间。于是定时每秒使用pstack命令查看MySQL进程堆栈，看看在出现慢日志的时候MySQL做了什么。结果发现轮转的确耗时约10秒左右，MySQL是开了一个线程来做轮转，这段时间内此线程的堆栈底部大致如下：
pstack命令：https://blog.csdn.net/T146lLa128XX0x/article/details/134453431
#4 0x0000000000e78ee7 in read_gtids_from_binlog(char const*, Gtid_set*, Gtid_set*, Gtid*, Sid_map*, bool, bool) ()
#5 0x0000000000e7d1ec in MYSQL_BIN_LOG::init_gtid_sets(Gtid_set*, Gtid_set*, bool, bool, Transaction_boundary_parser*, Gtid*, bool) ()
#6 0x0000000000e7dfb3 in MYSQL_BIN_LOG::purge_logs(char const*, bool, bool, bool, unsigned long long*, bool) ()
#7 0x0000000000e7e4b9 in MYSQL_BIN_LOG::purge_logs_before_date(long, bool) ()
#8 0x0000000000e81cfe in MYSQL_BIN_LOG::ordered_commit(THD*, bool, bool) ()
#9 0x0000000000e83b45 in MYSQL_BIN_LOG::commit(THD*, bool) ()
#10 0x00000000007e40d4 in ha_commit_trans(THD*, bool, bool) ()
#11 0x0000000000d787d9 in trans_commit(THD*) ()
#12 0x0000000000cc3551 in mysql_execute_command(THD*, bool) ()
#13 0x0000000000cc5ccd in mysql_parse(THD*, Parser_state*) ()
#14 0x0000000000cc6e65 in dispatch_command(THD*, COM_DATA const*, enum_server_command) ()
#15 0x0000000000cc7924 in do_command(THD*) ()
#16 0x0000000000d92bd4 in handle_connection ()
#17 0x00000000011d9f41 in pfs_spawn_thread ()
#18 0x00007f55ac6a5aa1 in start_thread () from /lib64/libpthread.so.0
#19 0x00007f55ab60faad in clone () from /lib64/libc.so.6
可以看到gtid比较显眼，因为之前都是用5.6版本，对于gtid比较陌生，一搜才发现这是跟binlog和主从复制相关。于是怀疑与gtid有关，既然我碰到了，那么应该会有前人也碰到过，于是google一番，搜到一个官方论坛的帖子：https://bugs.mysql.com/bug.php?id=80889
大意是某人从5.6.22升级到5.7.10后，binlog日志轮换时MySQL就会卡住8到12秒，这不跟我碰到的问题一样吗？最后的官方回复是：
Thank you for your feedback, this has been fixed in upcoming versions and the following was added to the 5.7.14 changelog:
When --gtid-mode=off, issuing a PURGE BINARY LOGS TO file statement causes the system to read the whole file. Depending on the size of the file this could cause the server to stall for a few seconds.
大意是这是个bug，在5.7.14版本会修复。当gtid-mode关闭时，binlog日志轮转会导致系统读取所有的binlog文件，系统卡顿的秒数取决于binlog文件的大小。
目前线上的版本是5.7.10，看看我们的Mysql的gtid_mode是on还是off，结果是off，正好引发这个问题。
修复：
升级版本暂时不太现实，由于gtid_mode参数动态的，可以不重启MySQL动态修改，修改命令参考：
看看下一次轮转的情况，还是跟之前一样？再仔细阅读那个帖子，发现：
This was due to the way binary log files were being searched for the Previous_gtids value. The fix adds an optimization to stop the reading of the binary log file if it is supposed only to read the lost GTIDs and a Previous_gtids event is found.
好吧，把没有gtid的binlog文件清掉，使用命令：
purge binary logs to 'xxxx.log'
解析：https://blog.csdn.net/hanchao5272/article/details/79227325
再观察几天，问题消失。
教训：
线上服务端环境尽可能使用稳定的软件，比如MySQL尽量用5.6，5.7还是一个开发中的版本，5.7.10只是5.7的第10个小版本，其中可能有许多坑，谨慎使用，不然会充当别人的实验小白鼠。
————————————————
版权声明：本文为CSDN博主「array020」的原创文章，遵循 CC 4.0 BY-SA 版权协议，转载请附上原文出处链接及本声明。
原文链接：https://blog.csdn.net/damacheng/article/details/89847473
Comments | NOTHING