本文使用引擎INNODB版本MYSQL5.7.13
sync_binlog = 1
innodb_flush_log_at_trx_commit = 1
也就是双1设置，
本文使用通过对mysql 进行trace，gdb 自制工具infobin，以及
select * from sys.session where command<>'SLEEP' \G完成。
这里只是涉及binlog的写入问题和innodb层无关
1、问题由来
在线上环境一次同事删除了1000W的数据，在commit的时候，整个数据库
大约有几十秒的全部hang住的情况，本文就是为了深入剖析这个问题。
2、可能需要的知识
http://blog.itpub.net/7728585/viewspace-2133589/ MYSQL 什么时候同步binlog文件以及它的临时文件在哪里？
http://blog.itpub.net/7728585/viewspace-2133188/ 解析MYSQL BINLOG 二进制格式(1)--准备工作
http://blog.itpub.net/7728585/viewspace-2133189/ 解析MYSQL BINLOG 二进制格式(2)--FORMAT_DESCRIPTION_EVENT
http://blog.itpub.net/7728585/viewspace-2133321/ 解析MYSQL BINLOG 二进制格式(3)--QUERY_EVENT
http://blog.itpub.net/7728585/viewspace-2133429/ 解析MYSQL BINLOG 二进制格式(4)--TABLE_MAP_EVENT
http://blog.itpub.net/7728585/viewspace-2133463/ 解析MYSQL BINLOG 二进制格式(5)--WRITE_ROW_EVENT
http://blog.itpub.net/7728585/viewspace-2133469/ 解析MYSQL BINLOG 二进制格式(6)--UPDATE_ROW_EVENT/DELETE_ROW_EVENT
http://blog.itpub.net/7728585/viewspace-2133502/ 解析MYSQL BINLOG 二进制格式(7)--Xid_log_event/XID_EVENT
http://blog.itpub.net/7728585/viewspace-2133506/ 解析MYSQL BINLOG二进制格式(8)--GTID_LOG_EVENT/ANONYMOUS_GTID_LOG_EVENT及其他
http://blog.itpub.net/7728585/viewspace-2133534/ 解析MYSQL BINLOG二进制格式(9)--infobin解析binlog帮助文档
http://blog.itpub.net/7728585/viewspace-2133537/ 解析MYSQL BINLOG二进制格式(10)--问题解答
3、简单说明commit的时候做了什么以及为什么要上锁
在<>一文中有如下的图
其实这幅图中我已经写了需要一把锁，但是没仔细说，这把锁影响的是全部当前数据库的需要写binlog的全部语句,我们已经知道对于大事物(超过)的commit期间需要将临时
文件的中的binlog event 全部拷贝到binlog中，并且是一个事物的event必须是连续的，也就是一个事物的event中不能包含其他事物的event那么这期间需要一把mutex锁，为什
么要这把锁，这是在多线程/进程并发对同一个文件进行修改，也就是这里的binlog文件修改的，一种保护临界资源的方法，如果没有这把锁就会出现binlog中的文件出现错乱的情况。
注意这个锁是mysql层的而非innodb层。
4、模拟方法
对表test 进行删除不提交，观察临时文件大小。
关于生成临时文件的原理参考：
(http://blog.itpub.net/7728585/viewspace-2133589/ MYSQL 什么时候同步binlog文件以及它的临时文件在哪里？)
对删除delete test表commit期间马上对testsort和testsort2表插入一条数据，
这个时候可以观察到这两个插入，会被堵塞知道delete test的事物提交完成
才完成。
mysql> select count(*) from test;
+----------+
| count(*) |
+----------+
| 2621440 |
+----------+
1 row in set (3.14 sec)
及如下：
可以看到一个简单的insert居然花了10多秒，commit也是做了14秒。原因就在于需要将MLq9INFu这个临时文件同步在binlog这个过程
其他需要写入binlog的会话是堵塞的。
删除期间会看到临时文件不断增大如下：
[root@testmy ~]# lsof |grep /tmp/ML
mysqld 2095 mysql 84u REG 8,3 328560640 14680133 /tmp/MLq9INFu (deleted)
[root@testmy ~]# lsof |grep /tmp/ML
mysqld 2095 mysql 84u REG 8,3 346337280 14680133 /tmp/MLq9INFu (deleted)
[root@testmy ~]# lsof |grep /tmp/ML
mysqld 2095 mysql 84u REG 8,3 367812608 14680133 /tmp/MLq9INFu (deleted)
到了commit后这个文件变为0，但是任然存在因为这个会话线程还在：
[root@testmy ~]# lsof |grep /tmp/ML
mysqld 2095 mysql 84u REG 8,3 0 14680133 /tmp/MLq9INFu (deleted)
5、使用infobin 对binlog文件中进行验证
使用./infobin test.000211>log.log 进行分析
(可以使用mysqlbinlog但是不直观
工具可以参考
http://blog.itpub.net/7728585/viewspace-2133534/ 解析MYSQL BINLOG二进制格式(9)--infobin解析binlog帮助文档
获得)
-----delete from test; 的binlog event
>Gtid Event:Pos:368030739(0X15efb413) N_pos:368030804(0X15efb454) Time:1487197597 Event_size:65(bytes)
Gtid:4a6f2a67-5d87-11e6-a6bd-0c29a879a3:1158184
-->Query Event:Pos:368030804(0X15efb454) N_Pos:368030876(0X15efb49c) Time:1487197355 Event_size:72(bytes)
Exe_time:0 Use_db:test Statment(35b-trun):BEGIN Gno:1158184
---->Map Event:Pos368030876(0X15efb49c) N_pos:368031047(0X15efb547) Time:1487197355 Event_size:171(bytes)
TABLE_ID:129 DB_NAME:test TABLE_NAME:test Gno:1158184
------>Delete Event:Pos:368031047(0X15efb547) N_pos:368039196(0X15efd51c) Time:1487197355 Event_size:8149(bytes)
Dml on table: test.test table_id:129 Gno:1158184
....(中间省略)
------>Delete Event:Pos:736052116(0X2bdf4394) N_pos:736054135(0X2bdf4b77) Time:1487197355 Event_size:2019(bytes)
Dml on table: test.test table_id:129 Gno:1158184
>Xid Event:Pos:736054135(0X2bdf4b77) N_Pos:736054166(0X2bdf4b96) Time:1487197597 Event_size:31(bytes)
COMMIT; Gno:1158184
-----insert into testsort values(1);的binlog
>Gtid Event:Pos:736054166(0X2bdf4b96) N_pos:736054231(0X2bdf4bd7) Time:1487197599 Event_size:65(bytes)
Gtid:4a6f2a67-5d87-11e6-a6bd-0c29a879a3:1158185
-->Query Event:Pos:736054231(0X2bdf4bd7) N_Pos:736054303(0X2bdf4c1f) Time:1487197599 Event_size:72(bytes)
Exe_time:0 Use_db:test Statment(35b-trun):BEGIN Gno:1158185
---->Map Event:Pos736054303(0X2bdf4c1f) N_pos:736054358(0X2bdf4c56) Time:1487197599 Event_size:55(bytes)
TABLE_ID:187 DB_NAME:test TABLE_NAME:testsort Gno:1158185
------>Insert Event:Pos:736054358(0X2bdf4c56) N_pos:736054410(0X2bdf4c8a) Time:1487197599 Event_size:52(bytes)
Dml on table: test.testsort table_id:187 Gno:1158185
>Xid Event:Pos:736054410(0X2bdf4c8a) N_Pos:736054441(0X2bdf4ca9) Time:1487197599 Event_size:31(bytes)
COMMIT; Gno:1158185
------insert into testsort2 values(1);的binlog
>Gtid Event:Pos:736054441(0X2bdf4ca9) N_pos:736054506(0X2bdf4cea) Time:1487197600 Event_size:65(bytes)
Gtid:4a6f2a67-5d87-11e6-a6bd-0c29a879a3:1158186
-->Query Event:Pos:736054506(0X2bdf4cea) N_Pos:736054578(0X2bdf4d32) Time:1487197600 Event_size:72(bytes)
Exe_time:0 Use_db:test Statment(35b-trun):BEGIN Gno:1158186
---->Map Event:Pos736054578(0X2bdf4d32) N_pos:736054634(0X2bdf4d6a) Time:1487197600 Event_size:56(bytes)
TABLE_ID:188 DB_NAME:test TABLE_NAME:testsort2 Gno:1158186
------>Insert Event:Pos:736054634(0X2bdf4d6a) N_pos:736054686(0X2bdf4d9e) Time:1487197600 Event_size:52(bytes)
Dml on table: test.testsort2 table_id:188 Gno:1158186
>Xid Event:Pos:736054686(0X2bdf4d9e) N_Pos:736054717(0X2bdf4dbd) Time:1487197600 Event_size:31(bytes)
COMMIT; Gno:1158186
可以看到确实insert into testsort values(1)和insert into testsort2 values(1);的event确实在delete后才进入
binlog file
6、分析等待点。
那么到底在等待什么呢？这是另外一次测试的sys.session输出
mysql> select * from sys.session where command<>'SLEEP' \G
*************************** 1. row ***************************
thd_id: 28
conn_id: 3
user: root@localhost
db: test
command: Query
state: starting
time: 13
current_statement: commit
statement_latency: 12.55 s
progress: NULL
lock_latency: 0 ps
rows_examined: 0
rows_sent: 0
rows_affected: 0
tmp_tables: 0
tmp_disk_tables: 0
full_scan: NO
last_statement: NULL
last_statement_latency: NULL
current_memory: 179.02 KiB
last_wait: wait/io/file/sql/binlog
last_wait_latency: Still Waiting
source: binlog.cc:8469
trx_latency: 3.22 m
trx_state: ACTIVE
trx_autocommit: NO
pid: 5821
program_name: mysql
*************************** 2. row ***************************
thd_id: 3031
conn_id: 3006
user: root@localhost
db: test
command: Query
state: query end
time: 12
current_statement: insert into testsort3(id1,id2, ... OR((RAND()*100000)),'gaopeng')
statement_latency: 11.82 s
progress: NULL
lock_latency: 29.18 ms
rows_examined: 0
rows_sent: 0
rows_affected: 0
tmp_tables: 0
tmp_disk_tables: 0
full_scan: NO
last_statement: NULL
last_statement_latency: NULL
current_memory: 556.53 KiB
last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done
last_wait_latency: Still Waiting
source: binlog.cc:1894
trx_latency: 12.97 s
trx_state: ACTIVE
trx_autocommit: YES
pid: 15312
program_name: mysql
不难看出current_statement: commit 等待是
last_wait: wait/io/file/sql/binlog
last_wait_latency: Still Waiting
source: binlog.cc:8469
而被堵塞的insert等待是
last_wait: wait/synch/cond/sql/MYSQL_BIN_LOG::COND_done
last_wait_latency: Still Waiting
source: binlog.cc:1894
这是commit 等待的binlog.cc:8469的内容
if (DBUG_EVALUATE_IF("simulate_error_during_sync_binlog_file", 1,
mysql_file_sync(log_file.file,
MYF(MY_WME | MY_IGNORE_BADFD))))
从源码注释上可以看出原因再来看看他掉用int my_sync(File fd, myf my_flags)
既然加入文件描述符fd，应该就是在写binlog file
下面是insert等待的source: binlog.cc:1894的内容
mysql_cond_wait(&m_cond_done, &m_lock_done);
这个地方就是拿不到这把锁，他是Stage_manager::enroll_for调用的函数
而 Stage_manager源码注释是：
而enroll_for方法的描述为：
那么确实commit后binary log确实有一个写入的策略，会根据是否为leader进行写入，
如果不是leader则等到leader全部写完才进行写入，多个等待写入binlog的会话计入
一个队列中，这貌似就是并行了。
我使用GDB将断点打到
Stage_manager::enroll_for
MYSQL_BIN_LOG::sync_binlog_file
发现整个流程如下：
A会话COMMIT-->拿到锁-->进行binlog写-->commit完成
B会话COMMIT-->等待锁--------------------------->拿到锁-->进行binlog写-->commit完成
7、如何避免
没有什么好的办法如果使用innodb双1的情况下，只能每次修改少量的数据，增加修改次数
前面也说了binlog生成量大约为你修改数据量的2/3如果update是4/3那么就要评估你的I/O
性能，如果顺序写入每秒写入为X需要修改的数据量大约为Y
那么
S(秒)=(Y*(2/3))/(X/2)
控制S到一个你认为可以接受的范围内。其实可以通过copy来试试你的顺序的I/O性能。
比如我们写这样一个存储过程：
DELIMITER //
CREATE PROCEDURE d_move(in beid int,in cunt int,in rws int,in maxid int)
begin
declare num int;
declare nowid int;
set num = 1;
set nowid = beid;
while num <= cunt do
insert into test_vest_hist select * from test_vest where id>=nowid and id<nowid+rws and="" id<nowid+rws="" id<maxid;="" ="" select="" concat(now(),'="" ',row_count(),'="" insert!'); delete from test_vest where id>=nowid and id<nowid+rws and="" id<maxid;="" ="" select="" concat(now(),'="" ',row_count(),'="" delete!'); select concat(now(),' ',num,' times delete finsh!');
set nowid = nowid+rws;
set num = num+1;
select sleep(2);
end while;
end //
将rws控制到一个可以接受的范围比如5W,当然最好进行sleep(),这样给innodb引擎一个刷入脏数据的时间减少压力。
如果sync_log不设置为1，这个我做了trace确实就不会在commit的进行binlog写入了，但是这是不安全的，commit结束
后日志不落地是不安全的。
作者微信：
