[Maria-developers] GTID replication and relay_log.info
Kristian, There's a well-known problem in MySQL that relay_log.info is not always in sync with the database state, and killing and restarting server at an unfortunate time will cause it to re-execute last statement and potentially break replication. Did you fix this situation with GTIDs and rpl_slave_state table? It looks like with GTIDs it's really easy to solve the problem -- rpl_slave_state has GTID of the last executed transaction, so on restart one needs just to ignore all relay logs and re-connect to master with the last GTID. Did you do that? If not are you planning to do that? Thank you, Pavel
Pavel Ivanov <pivanof@google.com> writes:
There's a well-known problem in MySQL that relay_log.info is not always in sync with the database state, and killing and restarting server at an unfortunate time will cause it to re-execute last statement and potentially break replication. Did you fix this situation with GTIDs and rpl_slave_state table? It looks like with
Yes. When using GTID, relay logs are ignored whenever slave threads are restarted, such as slave server restart, events are fetched anew from the server starting at the current GTID position. As you say, this is required for crash safety.
GTIDs it's really easy to solve the problem -- rpl_slave_state has GTID of the last executed transaction, so on restart one needs just to ignore all relay logs and re-connect to master with the last GTID. Did
Yes. That is how it's done basically. Slave restart should be crash safe with MariaDB GTID (for InnoDB DML - MyISAM DML or DDL in general is not crash safe of course, as neither MyISAM nor DDL is transactional). There is currently a bug when restarting the *master* while the slave is still scanning for the GTID start position, but this will be fixed before GA of course. - Kristian.
I'm glad to hear that. :) On Tue, May 21, 2013 at 2:31 PM, Kristian Nielsen <knielsen@knielsen-hq.org> wrote:
There is currently a bug when restarting the *master* while the slave is still scanning for the GTID start position, but this will be fixed before GA of course.
Could you please elaborate what kind of bug is that? Thank you, Pavel
Pavel Ivanov <pivanof@google.com> writes:
Could you please elaborate what kind of bug is that?
The slave connects to master with GTID. The binlog dump thread on the master starts scanning the last binlog file to find the start position. It finds the position for one replication domain, but aother domain is still scanning to find the right place to start. Then the slave looses the connection to the master, due to some network problem. It automatically reconnects. Then the slave reconnect will connect with _both_ domains at the binlog offset reached before the connect. Thus, if there were still events in the second domain to be scanned and skipped at the point of reconnect, those events might be duplicated. (This happens only with the automatic reconnect of the I/O thread, not with explicit slave thread restart). - Kristian.
Thank you for the explanation. Pavel On Tue, May 21, 2013 at 10:54 PM, Kristian Nielsen <knielsen@knielsen-hq.org> wrote:
Pavel Ivanov <pivanof@google.com> writes:
Could you please elaborate what kind of bug is that?
The slave connects to master with GTID. The binlog dump thread on the master starts scanning the last binlog file to find the start position. It finds the position for one replication domain, but aother domain is still scanning to find the right place to start.
Then the slave looses the connection to the master, due to some network problem. It automatically reconnects. Then the slave reconnect will connect with _both_ domains at the binlog offset reached before the connect. Thus, if there were still events in the second domain to be scanned and skipped at the point of reconnect, those events might be duplicated.
(This happens only with the automatic reconnect of the I/O thread, not with explicit slave thread restart).
- Kristian.
Kristian, On Tue, May 21, 2013 at 2:31 PM, Kristian Nielsen <knielsen@knielsen-hq.org> wrote:
GTIDs it's really easy to solve the problem -- rpl_slave_state has GTID of the last executed transaction, so on restart one needs just to ignore all relay logs and re-connect to master with the last GTID. Did
Yes. That is how it's done basically.
Slave restart should be crash safe with MariaDB GTID (for InnoDB DML - MyISAM DML or DDL in general is not crash safe of course, as neither MyISAM nor DDL is transactional).
It seems to me that what you said above doesn't always work quite like that. It's possible that there's something wrong with us applying GTID patch on top of 10.0.1 and maybe I'm missing something crucial (we didn't apply START SLAVE UNTIL and everything that was after that yet). But from time to time we see failures of rpl.rpl_gtid_crash test with the output like this: CURRENT_TEST: rpl.rpl_gtid_crash mysqltest: In included file "./include/wait_until_disconnected.inc": included from .../mysql-test/suite/rpl/t/rpl_gtid_crash.test at line 244: At line 24: Server failed to dissapear The result from queries just before the failure was: < snip > include/stop_slave.inc SET GLOBAL debug_dbug="+d,crash_commit_before"; START SLAVE; INSERT INTO t1 VALUES (5); include/stop_slave.inc SET GLOBAL debug_dbug="+d,crash_commit_after"; START SLAVE; INSERT INTO t1 VALUES (6); include/stop_slave.inc SET GLOBAL debug_dbug="+d,inject_crash_before_flush_rli"; START SLAVE; INSERT INTO t1 VALUES (7); Timeout in wait_condition.inc for SELECT COUNT(*) = 7 FROM t1 Id User Host db Command Time State Info Progress 2 root localhost:58472 test Query 0 init show full processlist 0.000 4 system user NULL Connect 30 Waiting for master to send event NULL 0.000 include/stop_slave.inc SET GLOBAL debug_dbug="+d,inject_crash_after_flush_rli"; START SLAVE; INSERT INTO t1 VALUES (8); More results from queries before failure can be found in .../mysql-test/var/log/rpl_gtid_crash.log - saving ... ***Warnings generated in error logs during shutdown after running tests: rpl.rpl_gtid_crash 130524 1:12:44 [Warning] Slave: Duplicate entry '7' for key 'PRIMARY' Error_code: 1062 130524 1:13:14 [Warning] Slave: Duplicate entry '7' for key 'PRIMARY' Error_code: 1062 Or another failure with this output: CURRENT_TEST: rpl.rpl_gtid_crash mysqltest: In included file "./include/check_slave_param.inc": included from ./include/check_slave_no_error.inc at line 24: included from ./include/rpl_end.inc at line 74: included from .../mysql-test/suite/rpl/t/rpl_gtid_crash.test at line 268: At line 31: Wrong value for slave parameter The result from queries just before the failure was: < snip > master-bin.000004 532 Gtid 1 574 BEGIN GTID 0-1-6 master-bin.000004 574 Query 1 666 use `test`; INSERT INTO t1 VALUES (5) master-bin.000004 666 Xid 1 697 COMMIT /* xid=35 */ master-bin.000004 697 Gtid 1 739 BEGIN GTID 0-1-7 master-bin.000004 739 Query 1 831 use `test`; INSERT INTO t1 VALUES (6) master-bin.000004 831 Xid 1 862 COMMIT /* xid=52 */ master-bin.000004 862 Gtid 1 904 BEGIN GTID 0-1-8 master-bin.000004 904 Query 1 996 use `test`; INSERT INTO t1 VALUES (7) master-bin.000004 996 Xid 1 1027 COMMIT /* xid=69 */ master-bin.000004 1027 Gtid 1 1069 BEGIN GTID 0-1-9 master-bin.000004 1069 Query 1 1161 use `test`; INSERT INTO t1 VALUES (8) master-bin.000004 1161 Xid 1 1192 COMMIT /* xid=89 */ master-bin.000004 1192 Gtid 1 1234 GTID 0-1-10 master-bin.000004 1234 Query 1 1342 use `test`; DROP TABLE `t1` /* generated by server */ **** SHOW RELAYLOG EVENTS on server_1 **** relaylog_name = 'No such row' SHOW RELAYLOG EVENTS IN 'No such row'; Log_name Pos Event_type Server_id End_log_pos Info Wrong value for Last_SQL_Errno. Expected '0', got '1062' More results from queries before failure can be found in .../mysql-test/var/log/rpl_gtid_crash.log - saving ... ***Warnings generated in error logs during shutdown after running tests: rpl.rpl_gtid_crash 130525 1:07:15 [Warning] Slave: Duplicate entry '8' for key 'PRIMARY' Error_code: 1062 Can you suggest what debugging information should I gather to understand what's happening in failures like this? Or maybe you know off the top of your head what changes were done since 10.0.1 that are required for crash recovery to work properly? Thank you, Pavel
Pavel Ivanov <pivanof@google.com> writes:
yet). But from time to time we see failures of rpl.rpl_gtid_crash test with the output like this:
Hm, strange, it does not fail in our Buildbot, which runs hundreds of tests on different hosts...
Can you suggest what debugging information should I gather to understand what's happening in failures like this? Or maybe you know
First step is to send full contents of mysqld.1.err, mysqld.2.err, and rpl_gtid_crash.log.
that. It's possible that there's something wrong with us applying GTID patch on top of 10.0.1 and maybe I'm missing something crucial (we
off the top of your head what changes were done since 10.0.1 that are required for crash recovery to work properly?
I am wondering if you mean 10.0.2 here? (Since GTID was not included in 10.0.1, only 10.0.2). There was a change to rpl.rpl_gtid_crash.test to use --append_file instead of --remove_file/--write_file. Though these failures look like something else... I can't think of anything else right now, but if you send the files then there is a good chance I can say more. - Kristian.
On Sat, May 25, 2013 at 8:51 PM, Kristian Nielsen <knielsen@knielsen-hq.org> wrote:
yet). But from time to time we see failures of rpl.rpl_gtid_crash test with the output like this:
Hm, strange, it does not fail in our Buildbot, which runs hundreds of tests on different hosts...
Well, either our build environment differs, or we induced something with our patches...
that. It's possible that there's something wrong with us applying GTID patch on top of 10.0.1 and maybe I'm missing something crucial (we
off the top of your head what changes were done since 10.0.1 that are required for crash recovery to work properly?
I am wondering if you mean 10.0.2 here? (Since GTID was not included in 10.0.1, only 10.0.2).
No, I meant 10.0.1 -- we took it and applied all that you did in 10.0-mdev26 and then in 10.0-base, but only GTID-related patches and patches fixing flakiness of tests...
There was a change to rpl.rpl_gtid_crash.test to use --append_file instead of --remove_file/--write_file. Though these failures look like something else...
We already have the --append_file change.
I can't think of anything else right now, but if you send the files then there is a good chance I can say more.
OK. I'll try to catch log files next time this happens. Pavel
I can't think of anything else right now, but if you send the files then
On Sat, May 25, 2013 at 9:06 PM, Pavel Ivanov <pivanof@google.com> wrote: there
is a good chance I can say more.
OK. I'll try to catch log files next time this happens.
See logs in attachment. It looks clear to me that relay logs get replayed after crash and don't get deleted. I'm not sure though if the reason of that can be seen in the logs. Can you point me to the code where relay logs are deleted? I'll try to check why it's not called... Pavel
Pavel Ivanov <pivanof@google.com> writes:
See logs in attachment. It looks clear to me that relay logs get replayed after crash and don't get deleted. I'm not sure though if the reason of that can be seen in the logs.
No, I agree it's not clear from the logs one way or the other, so good that you mention this.
Can you point me to the code where relay logs are deleted? I'll try to check why it's not called...
It is this, in slave.cc start_slave_threads(): if (mi->using_gtid != Master_info::USE_GTID_NO && !mi->slave_running && !mi->rli.slave_running) { purge_relay_logs(&mi->rli, NULL, 0, &errmsg); mi->master_log_name[0]= 0; mi->master_log_pos= 0; } When both slave IO and SQL threads are stopped, we purge the relay logs before starting. And surely they must be stopped when we first start them after a crash ... And then in get_master_version_and_clock(), if we deleted the relay logs then we start from the GTID position: if (mi->using_gtid != Master_info::USE_GTID_NO && !mi->master_log_name[0]) { ... I would suggest printouts to the error log around those two places in the code and check that both are executed as expected at startup. Maybe either if() condition becomes false for some reason, or purge_relay_logs() fails to purge, but I do not see how from the code at the moment. It would also help if I had implemented MDEV-4491 (https://mariadb.atlassian.net/browse/MDEV-4491), to give better printouts in the error log about where and how the slave is actually connecting to the master. I will try to get this done soon. One thing did spring to mind as I was looking at this code, the XtraDB --innodb_recovery_update_relay_log option. This can overwrite relay-log information during crash recovery, so might be able to interfere. But it is off by default and does printouts to error log that are not seen in your logs, so it seems this is not related ... Thanks for helping look into this. I actually plan to change this code to something more robust, but it would be good to find the real problem here, otherwise I may end up just hiding the bug, not fixing it ... - Kristian.
Thanks for the pointers, Kristian. It turned out that it was an incorrect merge of GTID-related changes into 10.0.1 tree. In particular I didn't quite understand the meaning of LINE_FOR_FIRST_MYSQL_5_6 in sql/rpl_mi.cc and thus left it at the value of 19. Because of that every time when master.info was read slave didn't see the value of using_gtid variable and didn't purge relay logs. Now I've got this fixed for us. BTW, while debugging I've noticed that master.info file wasn't properly truncated when it was re-written. I always saw some left-over text after the line "using_gtid=1". After finish of rpl.rpl_gtid_crash it could be even several lines of extra text with one more line "using_gtid=1" at the end. So probably you will want to fix this at some point... Pavel On Mon, May 27, 2013 at 2:11 AM, Kristian Nielsen <knielsen@knielsen-hq.org>wrote:
Pavel Ivanov <pivanof@google.com> writes:
See logs in attachment. It looks clear to me that relay logs get replayed after crash and don't get deleted. I'm not sure though if the reason of that can be seen in the logs.
No, I agree it's not clear from the logs one way or the other, so good that you mention this.
Can you point me to the code where relay logs are deleted? I'll try to check why it's not called...
It is this, in slave.cc start_slave_threads():
if (mi->using_gtid != Master_info::USE_GTID_NO && !mi->slave_running && !mi->rli.slave_running) { purge_relay_logs(&mi->rli, NULL, 0, &errmsg); mi->master_log_name[0]= 0; mi->master_log_pos= 0; }
When both slave IO and SQL threads are stopped, we purge the relay logs before starting. And surely they must be stopped when we first start them after a crash ...
And then in get_master_version_and_clock(), if we deleted the relay logs then we start from the GTID position:
if (mi->using_gtid != Master_info::USE_GTID_NO && !mi->master_log_name[0]) { ...
I would suggest printouts to the error log around those two places in the code and check that both are executed as expected at startup. Maybe either if() condition becomes false for some reason, or purge_relay_logs() fails to purge, but I do not see how from the code at the moment.
It would also help if I had implemented MDEV-4491 (https://mariadb.atlassian.net/browse/MDEV-4491), to give better printouts in the error log about where and how the slave is actually connecting to the master. I will try to get this done soon.
One thing did spring to mind as I was looking at this code, the XtraDB --innodb_recovery_update_relay_log option. This can overwrite relay-log information during crash recovery, so might be able to interfere. But it is off by default and does printouts to error log that are not seen in your logs, so it seems this is not related ...
Thanks for helping look into this. I actually plan to change this code to something more robust, but it would be good to find the real problem here, otherwise I may end up just hiding the bug, not fixing it ...
- Kristian.
Pavel Ivanov <pivanof@google.com> writes:
Thanks for the pointers, Kristian. It turned out that it was an incorrect merge of GTID-related changes into 10.0.1 tree. In particular I didn't quite understand the meaning of LINE_FOR_FIRST_MYSQL_5_6 in sql/rpl_mi.cc and thus left it at the value of 19. Because of that every time when master.info was read slave didn't see the value of using_gtid variable and didn't purge relay logs. Now I've got this fixed for us.
Ok, good that you got it tracked down.
BTW, while debugging I've noticed that master.info file wasn't properly truncated when it was re-written. I always saw some left-over text after the line "using_gtid=1". After finish of rpl.rpl_gtid_crash it could be even several lines of extra text with one more line "using_gtid=1" at the end. So probably you will want to fix this at some point...
Ah, good catch, I'll get it fixed. - Kristian.
participants (2)
-
Kristian Nielsen -
Pavel Ivanov