Bug #69097 mysqld scans all binary logs on crash recovery
Submitted: 29 Apr 2013 22:51 Modified: 26 Sep 2014 11:18
Reporter: Yoshinori Matsunobu (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.6.11 OS:Any
Assigned to: CPU Architecture:Any

[29 Apr 2013 22:51] Yoshinori Matsunobu
Description:
mysqld scans all binary log files (in reverse order) on crash recovery. This may take very long time if the mysqld has many binary logs and almost all of them are out of filesystem cache. If you allocate large enough space for binary logs, this becomes more serious.

Here is a stack and a strace result on 5.6.11. Note that I didn't set gtid-mode=on though init_gtid_sets() was called.

Thread 1 (Thread 0x7f753b74b6f0 (LWP 3870)):
#0  0x0000003b1280d69f in open64 () from /lib64/libpthread.so.0
#1  0x00000000008f2245 in my_open (FileName=0xeea5ac8 "/binlogs/binary-logs-5611.011685", Flags=0, MyFlags=16) at /pb2/build/sb_0-8905638-1365168194.91/mysql-5.6.11/mysys/my_open.c:47
#2  0x00000000008a60e7 in inline_mysql_file_open (myFlags=<optimized out>, flags=<optimized out>, filename=<optimized out>, src_line=<optimized out>, src_file=<optimized out>, key=<optimized out>) at /pb2/build/sb_0-8905638-1365168194.91/mysql-5.6.11/include/mysql/psi/mysql_file.h:1047
#3  open_binlog_file (log=0x7ffffb660fe0, log_file_name=0xeea5ac8 "/binlogs/binary-logs-5611.011685", errmsg=0x7ffffb661158) at /pb2/build/sb_0-8905638-1365168194.91/mysql-5.6.11/sql/binlog.cc:1787
#4  0x00000000008a6325 in read_gtids_from_binlog (filename=0xeea5ac8 "/binlogs/binary-logs-5611.011685", all_gtids=0x1420380, prev_gtids=0x0, verify_checksum=true) at /pb2/build/sb_0-8905638-1365168194.91/mysql-5.6.11/sql/binlog.cc:2473
#5  0x00000000008abf70 in MYSQL_BIN_LOG::init_gtid_sets (this=0x133d6c0, all_gtids=0x1420380, lost_gtids=0x1420400, verify_checksum=true, need_lock=true) at /pb2/build/sb_0-8905638-1365168194.91/mysql-5.6.11/sql/binlog.cc:2776
#6  0x00000000005836e1 in mysqld_main (argc=43, argv=0x136fbb8) at /pb2/build/sb_0-8905638-1365168194.91/mysql-5.6.11/sql/mysqld.cc:5419
#7  0x0000003b1201d8b4 in __libc_start_main () from /lib64/libc.so.6
#8  0x0000000000576869 in _start ()

.....
[pid   455] open("/binlogs/binary-logs-5611.000206", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000205", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000204", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000203", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000202", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000201", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000200", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000199", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000198", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000197", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000196", O_RDONLY) = 13
...
[pid   455] open("/binlogs/binary-logs-5611.000003", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000002", O_RDONLY) = 13
[pid   455] open("/binlogs/binary-logs-5611.000001", O_RDONLY) = 13
.....

How to repeat:
1. Start mysqld with log-bin. gtid-mode is not mandatory

2. write many many binary logs.

for i in `seq 1 10000`
do
mysql -h 127.0.0.1 -P 3306 -e "flush logs"
done
echo 3 > /proc/sys/vm/drop_caches

3. killall -9 mysqld mysqld_safe

4. Restart mysqld, and see behavior by iostat, strace, and gdb -p.

Suggested fix:
I don't think reading all binary logs is needed. Just reading the latest binary log (not closed properly on crash) should be enough.
[30 Apr 2013 3:58] MySQL Verification Team
Hello Yoshinori,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[14 Aug 2014 16:32] David Moss
The following has been added to the 5.7.5 documentation with commit 39619:
simplified_binlog_gtid_recovery
By default, when MySQL recovers from a crash it iterates through binary log files searching for GTID events starting from the oldest file, which can take a long time if you have a large number of binary log files. By enabling this option, the newest binary log file is instead searched for GTID events. If a Previous_gtids_log_event and Gtid_log_event are found, gtid_executed and gtid_purged are initialized using these events as usual during recovery. If no GTID events are found, a second scan then searches the oldest binary log file for GTID events. If neither of these files contain the GTID events, no more binary log files are searched, and gtid_executed and gtid_purged are set to the empty string.
[14 Aug 2014 16:33] David Moss
Posted by developer:
 
The following has been added to the 5.7.5 documentation with commit 39619:
simplified_binlog_gtid_recovery
By default, when MySQL recovers from a crash it iterates through binary log files searching for GTID events starting from the oldest file, which can take a long time if you have a large number of binary log files. By enabling this option, the newest binary log file is instead searched for GTID events. If a Previous_gtids_log_event and Gtid_log_event are found, gtid_executed and gtid_purged are initialized using these events as usual during recovery. If no GTID events are found, a second scan then searches the oldest binary log file for GTID events. If neither of these files contain the GTID events, no more binary log files are searched, and gtid_executed and gtid_purged are set to the empty string.
[25 Sep 2014 12:33] Laurynas Biveinis
Has this been fixed in 5.6.21 but not documented as such?

revno: 6110
committer: Bill Qu <bill.qu@Oracle.com>
branch nick: mysql-5.6
timestamp: Fri 2014-08-08 10:12:49 +0800
message:
  BUG#16741603: MYSQLD SCANS ALL BINARY LOGS ON CRASH RECOVERY
  
  Mysql server iterates backwards through binary logs, looking for
  the last binary log that contains a Previous_gtids_log_event for
  gathering the set of gtid_executed, and iterates forwards through
  binary logs, looking for the first binary log that contains both
  Previous_gtids_log_event and gtid_log_event for gathering the set
  of gtid_purged on crash recovery. Mysql server also iterates
  forwards through binary logs, looking for the first binary log
  that contains both Previous_gtids_log_event and gtid_log_event
  for gathering the set of gtid_purged when purging binary logs.
  This may take very long time if the mysql server has many binary
  logs and almost all of them are out of filesystem cache.
  
  To fix the problem, introduce an option
  'simplified-binlog-gtid-recovery', whose default value is false.
  If the option is enabled, we do this: In the first scan (where
  it iterates over binary logs from the newest to the oldest):
  If the last binary log does not contain any GTID event, do not
  read any more binary logs, and set GTID_EXECUTED = '' and
  GTID_PURGED = ''. Otherwise, initialize GTID_EXECUTED as usual.
  Then, in the second scan (where it iterates from the oldest to
  the newest): If the first binary log does not contain any GTID
  event, do not read any more binary logs, and set GTID_PURGED = ''.
[25 Sep 2014 12:48] Laurynas Biveinis
Doc bug 74071 for 5.6.
[26 Sep 2014 11:18] David Moss
In fact this was also published for 5.6.21 on the 14th August 2014 and the content is visible online here:
http://dev.mysql.com/doc/refman/5.6/en/replication-options-gtids.html#sysvar_simplified_bi...
[30 Sep 2014 14:04] David Moss
Posted by developer:
 
Also added to the release notes, visible here:
http://dev.mysql.com/doc/relnotes/mysql/5.6/en/news-5-6-21.html