Bug #90137 | executed_gtid_set is empty after mysql crash | ||
---|---|---|---|
Submitted: | 20 Mar 2018 10:40 | Modified: | 23 May 2018 1:24 |
Reporter: | Prasad N | Email Updates: | |
Status: | Can't repeat | Impact on me: | |
Category: | MySQL Server: Replication | Severity: | S1 (Critical) |
Version: | 5.7.18 | OS: | CentOS (2.6.32-696.23.1.el6.x86_64 ) |
Assigned to: | MySQL Verification Team | CPU Architecture: | x86 |
Tags: | crash, execute_gtid_set, GTID |
[20 Mar 2018 10:40]
Prasad N
[20 Mar 2018 10:49]
Prasad N
mysqld.log
Attachment: mysqld.log (application/octet-stream, text), 68.06 KiB.
[20 Mar 2018 21:52]
MySQL Verification Team
Hi, Can you please share your config files on both master and slave? I run a sample test and was unable to reproduce the problem so I'd like to try with your config to increase likelihood of reproducability. thanks Bogdan
[21 Mar 2018 8:28]
Prasad N
Hi - Config files are same on both master and salve. You may need to crash mysql few time before we can run into this issue. Thanks Prasad
[22 Mar 2018 21:45]
MySQL Verification Team
Hi I spent day and a half and cannot reproduce this issue. If you had some crashes before maybe your data is corrupted? I did crashed mysql several times trying to reproduce this but had no luck. Please rebuild your tables to be sure your data is not currupted and try to reproduce then all best Bogdan
[23 Mar 2018 4:51]
Prasad N
Hi - did you try with continuous loading on the mysql server ? My data seems to be ok based on the random checks I did. Will it help if I zip and share binary logs from my server ? Will it help to analyze further or debug ? Thanks!
[23 Mar 2018 8:39]
Prasad N
Probably it has got to do something with the behavior mentioned in the bug fix:https://bugs.mysql.com/bug.php?id=69097 Specifically: [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.
[23 Mar 2018 8:44]
Prasad N
In my system, mysql-bin.000001 is where most of the transactions are logged. Looks like it got rotated to mysql-bin.000002 after the crash. There have been subsequent rotates as well as wee see below. Interesting point however is the size difference between the files mysql-bin.000002 and those that follow it. Is it a case that mysql did not create the new binlog file correctly after the crash ? -rw-r----- 1 mysql mysql 352921108 Mar 20 06:14 mysql-bin.000001 -rw-r----- 1 mysql mysql 123 Mar 20 06:15 mysql-bin.000002 -rw-r----- 1 mysql mysql 177 Mar 20 06:40 mysql-bin.000003 -rw-r----- 1 mysql mysql 177 Mar 20 06:45 mysql-bin.000004
[23 Mar 2018 8:49]
Prasad N
I have pasted the output of 2nd and 3rd binlog files for comparison. Please investigate. [root@vmadf0264117 mysql]# mysqlbinlog mysql-bin.000002 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #180320 6:14:02 server id 19 end_log_pos 123 CRC32 0x35bc7b93 Start: binlog v 4, server v 5.7.18-log created 180320 6:14:02 at startup ROLLBACK/*!*/; BINLOG ' qqawWg8TAAAAdwAAAHsAAAAAAAQANS43LjE4LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAACqprBaEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA AZN7vDU= '/*!*/; SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@vmadf0264117 mysql]# [root@vmadf0264117 mysql]# mysqlbinlog mysql-bin.000003 /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/; /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/; DELIMITER /*!*/; # at 4 #180320 6:15:31 server id 19 end_log_pos 123 CRC32 0x2129daba Start: binlog v 4, server v 5.7.18-log created 180320 6:15:31 at startup ROLLBACK/*!*/; BINLOG ' A6ewWg8TAAAAdwAAAHsAAAAAAAQANS43LjE4LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAADp7BaEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA AbraKSE= '/*!*/; # at 123 #180320 6:15:31 server id 19 end_log_pos 154 CRC32 0x560f7b18 Previous-GTIDs # [empty] # at 154 #180320 6:40:05 server id 19 end_log_pos 177 CRC32 0x7c916cbe Stop SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/; DELIMITER ; # End of log file /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/; [root@vmadf0264117 mysql]#
[23 Mar 2018 11:05]
MySQL Verification Team
Hi, > Hi - did you try with continuous loading on the mysql server ? yes > My data seems to be ok based on the random checks I did. if data is ok then having previous crashes should not have any effect on anything as when you start mysqld everything is "new" except the data, data is old, so unless there's something wrong with data previous state is not really relevant. when I say data, I mean anything in data-files, having bin able to do a select does not mean all data files are ok. > Will it help if I zip and share binary logs from my server ? > Will it help to analyze further or debug ? you can send and I will test but I can't promise anything, it might for sure help, especially if it's related to this gtid search you mentioned. thanks Bogdan
[4 Apr 2018 10:26]
Prasad N
I have uploaded my mysql data directory through sftp. file name is : mysql-bug-data-90137 Please check and let me know. Thanks Prasad
[21 May 2018 22:51]
MySQL Verification Team
Hi, This took a while but I can't reproduce this. Are you still hitting this issue? all best Bogdan
[23 May 2018 1:24]
Prasad N
yes we still saw this issue recently as well. this time the sequence was that mysql was crashed and started. it was taking a while to recover from the crash and there was a start attempted from another thread. Attaching the log snippet. Kindly investigate further.
[23 May 2018 1:27]
Prasad N
mysqld logs having this issue
Attachment: mysqld.log (application/octet-stream, text), 9.50 KiB.