From: Date: April 10 2007 3:19pm Subject: bk commit into 5.1 tree (mats:1.2546) BUG#25688 List-Archive: http://lists.mysql.com/commits/24165 X-Bug: 25688 Message-Id: <20070410131905.29D05357D@romeo> Below is the list of changes that have just been committed into a local 5.1 repository of mats. When mats does a push these changes will be propagated to the main repository and, within 24 hours after the push, to the public repository. For information on how to access the public repository see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html ChangeSet@stripped, 2007-04-10 15:18:54+02:00, mats@romeo.(none) +6 -0 BUG#25688 (RBR: circular replication may cause STMT_END_F flags to be skipped): By moving statement end actions from Rows_log_event::do_apply_event() to Rows_log_event::do_update_pos() they will always be executed, even if Rows_log_event::do_apply_event() is skipped because the event originated at the same server. This because Rows_log_event::do_update_pos() is always executed (unless Rows_log_event::do_apply_event() failed with an error, in which case the slave stops with an error anyway). Adding test case. mysql-test/r/rpl_ndb_circular_simplex.result@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +61 -0 New BitKeeper file ``mysql-test/r/rpl_ndb_circular_simplex.result'' mysql-test/r/rpl_ndb_circular_simplex.result@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +0 -0 mysql-test/t/rpl_ndb_circular_simplex.test@stripped, 2007-04-10 15:18:52+02:00, mats@romeo.(none) +77 -0 New BitKeeper file ``mysql-test/t/rpl_ndb_circular_simplex.test'' mysql-test/t/rpl_ndb_circular_simplex.test@stripped, 2007-04-10 15:18:52+02:00, mats@romeo.(none) +0 -0 sql/log_event.cc@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +52 -72 Moving statement end actions from Rows_log_event::do_apply_event() to Rows_log_event::do_update_pos(). Factoring out code to update group positions and event positions into relay log info structure. sql/log_event.h@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +2 -0 Adding Rows_log_event::do_update_pos(). sql/rpl_rli.cc@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +45 -0 Adding member function stmt_done() to do after-statement updates of the relay log info structure. sql/rpl_rli.h@stripped, 2007-04-10 15:18:51+02:00, mats@romeo.(none) +22 -0 Adding member function stmt_done() to do after-statement updates of the relay log info structure. # This is a BitKeeper patch. What follows are the unified diffs for the # set of deltas contained in the patch. The rest of the patch, the part # that BitKeeper cares about, is below these diffs. # User: mats # Host: romeo.(none) # Root: /home/bk/b25688-mysql-5.1-rpl --- 1.275/sql/log_event.cc 2007-04-10 15:19:04 +02:00 +++ 1.276/sql/log_event.cc 2007-04-10 15:19:04 +02:00 @@ -547,49 +547,7 @@ Matz: I don't think we will need this check with this refactoring. */ if (rli) - { - /* - If in a transaction, and if the slave supports transactions, just - inc_event_relay_log_pos(). We only have to check for OPTION_BEGIN - (not OPTION_NOT_AUTOCOMMIT) as transactions are logged with - BEGIN/COMMIT, not with SET AUTOCOMMIT= . - - CAUTION: opt_using_transactions means - innodb || bdb ; suppose the master supports InnoDB and BDB, - but the slave supports only BDB, problems - will arise: - - suppose an InnoDB table is created on the master, - - then it will be MyISAM on the slave - - but as opt_using_transactions is true, the slave will believe he - is transactional with the MyISAM table. And problems will come - when one does START SLAVE; STOP SLAVE; START SLAVE; (the slave - will resume at BEGIN whereas there has not been any rollback). - This is the problem of using opt_using_transactions instead of a - finer "does the slave support - _the_transactional_handler_used_on_the_master_". - - More generally, we'll have problems when a query mixes a - transactional handler and MyISAM and STOP SLAVE is issued in the - middle of the "transaction". START SLAVE will resume at BEGIN - while the MyISAM table has already been updated. - */ - if ((thd->options & OPTION_BEGIN) && opt_using_transactions) - rli->inc_event_relay_log_pos(); - else - { - rli->inc_group_relay_log_pos(log_pos); - flush_relay_log_info(rli); - /* - Note that Rotate_log_event::do_apply_event() does not call - this function, so there is no chance that a fake rotate event - resets last_master_timestamp. Note that we update without - mutex (probably ok - except in some very rare cases, only - consequence is that value may take some time to display in - Seconds_Behind_Master - not critical). - */ - rli->last_master_timestamp= when; - } - } + rli->stmt_done(thd, log_pos, when); return 0; // Cannot fail currently } @@ -6243,6 +6201,42 @@ DBUG_RETURN(error); } + /* + This code would ideally be placed in do_update_pos() instead, but + since we have no access to table there, we do the setting of + last_event_start_time here instead. + */ + if (table && (table->s->primary_key == MAX_KEY) && + !cache_stmt && get_flags(STMT_END_F) == RLE_NO_FLAGS) + { + /* + ------------ Temporary fix until WL#2975 is implemented --------- + + This event is not the last one (no STMT_END_F). If we stop now + (in case of terminate_slave_thread()), how will we restart? We + have to restart from Table_map_log_event, but as this table is + not transactional, the rows already inserted will still be + present, and idempotency is not guaranteed (no PK) so we risk + that repeating leads to double insert. So we desperately try to + continue, hope we'll eventually leave this buggy situation (by + executing the final Rows_log_event). If we are in a hopeless + wait (reached end of last relay log and nothing gets appended + there), we timeout after one minute, and notify DBA about the + problem. When WL#2975 is implemented, just remove the member + st_relay_log_info::last_event_start_time and all its occurences. + */ + const_cast(rli)->last_event_start_time= time(0); + } + + DBUG_RETURN(0); +} + +int +Rows_log_event::do_update_pos(RELAY_LOG_INFO *rli) +{ + DBUG_ENTER("Rows_log_event::do_update_pos"); + int error= 0; + if (get_flags(STMT_END_F)) { /* @@ -6261,6 +6255,7 @@ replicate-ignore rules). */ thd->binlog_flush_pending_rows_event(true); + /* If this event is not in a transaction, the call below will, if some transactional storage engines are involved, commit the statement into @@ -6271,6 +6266,7 @@ binlog. */ error= ha_autocommit_or_rollback(thd, 0); + /* Now what if this is not a transactional engine? we still need to flush the pending event to the binlog; we did it with @@ -6282,11 +6278,18 @@ */ thd->reset_current_stmt_binlog_row_based(); - const_cast(rli)->cleanup_context(thd, 0); + rli->cleanup_context(thd, 0); if (error == 0) { /* + Indicate that a statement is finished. + Step the group log position if we are not in a transaction, + otherwise increase the event log position. + */ + rli->stmt_done(thd, log_pos, when); + + /* Clear any errors pushed in thd->net.last_err* if for example "no key found" (as this is allowed). This is a safety measure; apparently those errors (e.g. when executing a Delete_rows_log_event of a @@ -6298,38 +6301,15 @@ } else slave_print_msg(ERROR_LEVEL, rli, error, - "Error in %s event: commit of row events failed, " - "table `%s`.`%s`", - get_type_str(), table->s->db.str, - table->s->table_name.str); - DBUG_RETURN(error); + "Error in %s event: commit of row events failed", + get_type_str()); } - - if (table && (table->s->primary_key == MAX_KEY) && !cache_stmt) + else { - /* - ------------ Temporary fix until WL#2975 is implemented --------- - - This event is not the last one (no STMT_END_F). If we stop now - (in case of terminate_slave_thread()), how will we restart? We - have to restart from Table_map_log_event, but as this table is - not transactional, the rows already inserted will still be - present, and idempotency is not guaranteed (no PK) so we risk - that repeating leads to double insert. So we desperately try to - continue, hope we'll eventually leave this buggy situation (by - executing the final Rows_log_event). If we are in a hopeless - wait (reached end of last relay log and nothing gets appended - there), we timeout after one minute, and notify DBA about the - problem. When WL#2975 is implemented, just remove the member - st_relay_log_info::last_event_start_time and all its occurences. - */ - const_cast(rli)->last_event_start_time= time(0); + rli->inc_event_relay_log_pos(); } - DBUG_ASSERT(error == 0); - thd->clear_error(); - - DBUG_RETURN(0); + DBUG_RETURN(error); } #endif /* !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION) */ --- 1.145/sql/log_event.h 2007-04-10 15:19:04 +02:00 +++ 1.146/sql/log_event.h 2007-04-10 15:19:04 +02:00 @@ -841,6 +841,7 @@ } protected: + /** Primitive to apply an event to the database. @@ -2242,6 +2243,7 @@ #if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION) virtual int do_apply_event(RELAY_LOG_INFO const *rli); + virtual int do_update_pos(RELAY_LOG_INFO *rli); /* Primitive to prepare for a sequence of row executions. --- 1.7/sql/rpl_rli.cc 2007-04-10 15:19:05 +02:00 +++ 1.8/sql/rpl_rli.cc 2007-04-10 15:19:05 +02:00 @@ -1086,6 +1086,51 @@ } +void st_relay_log_info::stmt_done(THD *thd, + my_off_t const event_master_log_pos, + time_t event_creation_time) +{ + /* + If in a transaction, and if the slave supports transactions, just + inc_event_relay_log_pos(). We only have to check for OPTION_BEGIN + (not OPTION_NOT_AUTOCOMMIT) as transactions are logged with + BEGIN/COMMIT, not with SET AUTOCOMMIT= . + + CAUTION: opt_using_transactions means innodb || bdb ; suppose the + master supports InnoDB and BDB, but the slave supports only BDB, + problems will arise: - suppose an InnoDB table is created on the + master, - then it will be MyISAM on the slave - but as + opt_using_transactions is true, the slave will believe he is + transactional with the MyISAM table. And problems will come when + one does START SLAVE; STOP SLAVE; START SLAVE; (the slave will + resume at BEGIN whereas there has not been any rollback). This is + the problem of using opt_using_transactions instead of a finer + "does the slave support _transactional handler used on the + master_". + + More generally, we'll have problems when a query mixes a + transactional handler and MyISAM and STOP SLAVE is issued in the + middle of the "transaction". START SLAVE will resume at BEGIN + while the MyISAM table has already been updated. + */ + if ((thd->options & OPTION_BEGIN) && opt_using_transactions) + inc_event_relay_log_pos(); + else + { + inc_group_relay_log_pos(event_master_log_pos); + flush_relay_log_info(this); + /* + Note that Rotate_log_event::do_apply_event() does not call this + function, so there is no chance that a fake rotate event resets + last_master_timestamp. Note that we update without mutex + (probably ok - except in some very rare cases, only consequence + is that value may take some time to display in + Seconds_Behind_Master - not critical). + */ + last_master_timestamp= event_creation_time; + } +} + #if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION) void st_relay_log_info::cleanup_context(THD *thd, bool error) { --- 1.11/sql/rpl_rli.h 2007-04-10 15:19:05 +02:00 +++ 1.12/sql/rpl_rli.h 2007-04-10 15:19:05 +02:00 @@ -314,6 +314,28 @@ transaction). */ time_t last_event_start_time; + + /** + Helper function to after statement completion. + + This function will complete the group by stepping the group + position if the "statement" is not inside a transaction. If the + "statement" is inside a transaction, the function will just + increase the event position. + + @param thd + Thread to use when deciding how to complete the statement + + @param event_log_pos + Master log position of the event + + @param event_creation_time + Timestamp for the creation of the event on the master side + */ + void stmt_done(THD *thd, + my_off_t event_log_pos, + time_t event_creation_time); + } RELAY_LOG_INFO; --- New file --- +++ mysql-test/r/rpl_ndb_circular_simplex.result 07/04/10 15:18:51 stop slave; drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9; reset master; reset slave; drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9; start slave; CREATE TABLE t1 (a int key, b int) ENGINE=NDB; SHOW TABLES; Tables_in_test t1 RESET MASTER; INSERT INTO t1 VALUES (1,2); INSERT INTO t1 VALUES (2,3); STOP SLAVE; CHANGE MASTER TO MASTER_HOST="127.0.0.1",MASTER_PORT=SLAVE_PORT,MASTER_USER="root"; RESET MASTER; START SLAVE; SHOW SLAVE STATUS; Slave_IO_State # Master_Host 127.0.0.1 Master_User root Master_Port 9308 Connect_Retry 60 Master_Log_File slave-bin.000001 Read_Master_Log_Pos 468 Relay_Log_File # Relay_Log_Pos # Relay_Master_Log_File slave-bin.000001 Slave_IO_Running Yes Slave_SQL_Running Yes Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno 0 Last_Error Skip_Counter 0 Exec_Master_Log_Pos 468 Relay_Log_Space # Until_Condition None Until_Log_File Until_Log_Pos 0 Master_SSL_Allowed No Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master # SELECT * FROM t1 ORDER BY a; a b 1 2 2 3 STOP SLAVE; START SLAVE; SELECT * FROM t1 ORDER BY a; a b 1 2 2 3 --- New file --- +++ mysql-test/t/rpl_ndb_circular_simplex.test 07/04/10 15:18:52 --source include/have_ndb.inc --source include/have_binlog_format_row.inc --source include/master-slave.inc connection master; CREATE TABLE t1 (a int key, b int) ENGINE=NDB; sync_slave_with_master; SHOW TABLES; # Lose the events from the slave binary log: there is no # need to re-create the table on the master. connection slave; RESET MASTER; # Insert some values on the slave and master connection master; INSERT INTO t1 VALUES (1,2); # Switch to slave once event is applied and insert a row sync_slave_with_master; connection slave; INSERT INTO t1 VALUES (2,3); # ... it is now very probable that we have a mixed event in the binary # log. If we don't, the test should still pass, but will not test the # mixed event situation. # The statement is disabled since it cannot reliably show the same # info all the time. Use it for debug purposes. #SHOW BINLOG EVENTS; # Replicate back to the master to test this mixed event on the master STOP SLAVE; connection master; --replace_result $SLAVE_MYPORT SLAVE_PORT eval CHANGE MASTER TO MASTER_HOST="127.0.0.1",MASTER_PORT=$SLAVE_MYPORT,MASTER_USER="root"; RESET MASTER; START SLAVE; connection slave; save_master_pos; connection master; sync_with_master; # The statement is disabled since it cannot reliably show the same # info all the time. Use it for debug purposes. #SHOW BINLOG EVENTS; # Check that there is no error in replication --replace_result $MASTER_MYPORT MASTER_PORT --replace_column 1 # 8 # 9 # 23 # 33 # query_vertical SHOW SLAVE STATUS; # Check that we have the data on the master SELECT * FROM t1 ORDER BY a; # We should now have another mixed event, likely with "slave" server # id last, and with the STMT_END_F flag set. # The statement is disabled since it cannot reliably show the same # info all the time. Use it for debug purposes. #SHOW BINLOG EVENTS; # now lets see that this data is applied correctly on the slave STOP SLAVE; save_master_pos; connection slave; START SLAVE; # check that we have the data on the slave sync_with_master; SELECT * FROM t1 ORDER BY a;