原创转载请注明出处
本文使用引擎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 /*!Trx 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; /*!Trx end*/ 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 /*!Trx 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; /*!Trx end*/ 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 /*!Trx 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; /*!Trx end*/ 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的内容
/**
On *pure non-transactional* workloads there is a small window
in time where a concurrent rotate might be able to close
the file before the sync is actually done. In that case,
ignore the bad file descriptor errors.
Transactional workloads (InnoDB) are not affected since the
the rotation will not happen until all transactions have
committed to the storage engine, thence decreased the XID
counters.(重点)
TODO: fix this properly even for non-transactional storage
engines.
*/
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源码注释是：
/**
Class for maintaining the commit stages for binary log group commit.
*/
而enroll_for方法的描述为：
/**
Enroll a set of sessions for a stage.
This will queue the session thread for writing and flushing.
If the thread being queued is assigned as stage leader, it will
return immediately.
If wait_if_follower is true the thread is not the stage leader,
the thread will be wait for the queue to be processed by the
leader before it returns.(重点)
In DBUG-ON version the follower marks is preempt status as ready.
@param stage Stage identifier for the queue to append to.
@param first Queue to append.
@param stage_mutex
Pointer to the currently held stage mutex, or NULL if
we're not in a stage.
@retval true Thread is stage leader.
@retval false Thread was not stage leader and processing has been done.
*/
那么确实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结束
后日志不落地是不安全的。
作者微信：
