| 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: | |
| Category: | MySQL Server: Replication | Severity: | S2 (Serious) |
| Version: | 5.6.11 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[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
[5 May 2022 9:01]
lei luo
未知错误7592
Attachment: 微信图片_20220505170006.png (image/png, text), 20.01 KiB.
[5 May 2022 9:01]
lei luo
未知错误7592
Attachment: 微信图片_20220505170006.png (image/png, text), 20.01 KiB.
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.