From 22f91eddb12df78a50af147f126cf2ea05c817de Mon Sep 17 00:00:00 2001 From: unknown Date: Mon, 25 Mar 2013 12:05:27 +0100 Subject: [PATCH] MDEV-4322: Race in binlog checkpointing during server shutdown. During server shutdown, we need to wait for binlog checkpointing to finish in the binlog background thread before closing the binlog. This was not done, so we could get assert and failure to finish the final binlog checkpoint if shutdown happened in the middle. --- .../suite/binlog/r/binlog_checkpoint.result | 16 ++++ .../suite/binlog/t/binlog_checkpoint.test | 27 ++++++- sql/log.cc | 79 +++++++++++++------ sql/log.h | 2 + 4 files changed, 101 insertions(+), 23 deletions(-) diff --git a/mysql-test/suite/binlog/r/binlog_checkpoint.result b/mysql-test/suite/binlog/r/binlog_checkpoint.result index 7bfa66e4770..3e93656a208 100644 --- a/mysql-test/suite/binlog/r/binlog_checkpoint.result +++ b/mysql-test/suite/binlog/r/binlog_checkpoint.result @@ -89,6 +89,22 @@ Log_name Pos Event_type Server_id End_log_pos Info master-bin.000003 # Format_desc # # SERVER_VERSION, BINLOG_VERSION master-bin.000003 # Binlog_checkpoint # # master-bin.000001 master-bin.000003 # Binlog_checkpoint # # master-bin.000003 +*** MDEV-4322: Broken XID counting during binlog rotation *** +SET @old_dbug= @@global.DEBUG_DBUG; +SET GLOBAL debug_dbug="+d,inject_binlog_background_thread_before_mark_xid_done"; +FLUSH LOGS; +INSERT INTO t1 VALUES (30, REPEAT("x", 4100)); +SET DEBUG_SYNC= "now WAIT_FOR injected_binlog_background_thread"; +SET GLOBAL debug_dbug= @old_dbug; +INSERT INTO t1 VALUES (31, REPEAT("x", 4100)); +show binary logs; +Log_name File_size +master-bin.000001 # +master-bin.000002 # +master-bin.000003 # +master-bin.000004 # +master-bin.000005 # +master-bin.000006 # DROP TABLE t1, t2; SET GLOBAL max_binlog_size= @old_max_binlog_size; SET GLOBAL innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit; diff --git a/mysql-test/suite/binlog/t/binlog_checkpoint.test b/mysql-test/suite/binlog/t/binlog_checkpoint.test index 8c84e51c4df..4fa40b23547 100644 --- a/mysql-test/suite/binlog/t/binlog_checkpoint.test +++ b/mysql-test/suite/binlog/t/binlog_checkpoint.test @@ -113,8 +113,33 @@ connection default; --source include/show_binlog_events.inc -# Cleanup +--echo *** MDEV-4322: Broken XID counting during binlog rotation *** + +# Test that binlog shutdown waits for any pending binlog checkpoints to have time to complete. + connection default; +# We will use debug_sync to setup a wait inside the background processing +# of binlog checkpoints. The wait is newer resumed, and will eventually +# time out. If server shutdown does not wait for checkpoint processing to +# complete, we will get an assert. +# +# It is a bit tricky to inject the wait properly as it has to happen in a +# background thread during shutdown. So we first inject a DBUG to set the +# debug_sync wait in the correct thread, then wait to be signalled that +# the inject happened so that we can remove it again from DBUG (else +# check_testcase will complain). + +SET @old_dbug= @@global.DEBUG_DBUG; +SET GLOBAL debug_dbug="+d,inject_binlog_background_thread_before_mark_xid_done"; + +FLUSH LOGS; +INSERT INTO t1 VALUES (30, REPEAT("x", 4100)); +SET DEBUG_SYNC= "now WAIT_FOR injected_binlog_background_thread"; +SET GLOBAL debug_dbug= @old_dbug; +INSERT INTO t1 VALUES (31, REPEAT("x", 4100)); +--source include/show_binary_logs.inc + + DROP TABLE t1, t2; SET GLOBAL max_binlog_size= @old_max_binlog_size; SET GLOBAL innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit; diff --git a/sql/log.cc b/sql/log.cc index 0444499c72b..0c273453751 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -2952,6 +2952,19 @@ void MYSQL_BIN_LOG::cleanup() { xid_count_per_binlog *b; + /* Wait for the binlog background thread to stop. */ + if (!is_relay_log && binlog_background_thread_started) + { + mysql_mutex_lock(&LOCK_binlog_background_thread); + binlog_background_thread_stop= true; + mysql_cond_signal(&COND_binlog_background_thread); + while (binlog_background_thread_stop) + mysql_cond_wait(&COND_binlog_background_thread_end, + &LOCK_binlog_background_thread); + mysql_mutex_unlock(&LOCK_binlog_background_thread); + binlog_background_thread_started= false; + } + inited= 0; close(LOG_CLOSE_INDEX|LOG_CLOSE_STOP_EVENT); delete description_event_for_queue; @@ -2968,19 +2981,6 @@ void MYSQL_BIN_LOG::cleanup() my_free(b); } - /* Wait for the binlog background thread to stop. */ - if (!is_relay_log && binlog_background_thread_started) - { - mysql_mutex_lock(&LOCK_binlog_background_thread); - binlog_background_thread_stop= true; - mysql_cond_signal(&COND_binlog_background_thread); - while (binlog_background_thread_stop) - mysql_cond_wait(&COND_binlog_background_thread_end, - &LOCK_binlog_background_thread); - mysql_mutex_unlock(&LOCK_binlog_background_thread); - binlog_background_thread_started= false; - } - mysql_mutex_destroy(&LOCK_log); mysql_mutex_destroy(&LOCK_index); mysql_mutex_destroy(&LOCK_xid_list); @@ -3702,17 +3702,10 @@ bool MYSQL_BIN_LOG::reset_logs(THD* thd, bool create_new_log) /* Now wait for all checkpoint requests and pending unlog() to complete. */ mysql_mutex_lock(&LOCK_xid_list); - xid_count_per_binlog *b; for (;;) { - I_List_iterator it(binlog_xid_count_list); - while ((b= it++)) - { - if (b->xid_count > 0) - break; - } - if (!b) - break; /* No more pending XIDs */ + if (is_xidlist_idle_nolock()) + break; /* Wait until signalled that one more binlog dropped to zero, then check again. @@ -4490,6 +4483,32 @@ MYSQL_BIN_LOG::can_purge_log(const char *log_file_name) #endif /* HAVE_REPLICATION */ +bool +MYSQL_BIN_LOG::is_xidlist_idle() +{ + bool res; + mysql_mutex_lock(&LOCK_xid_list); + res= is_xidlist_idle_nolock(); + mysql_mutex_unlock(&LOCK_xid_list); + return res; +} + + +bool +MYSQL_BIN_LOG::is_xidlist_idle_nolock() +{ + xid_count_per_binlog *b; + + I_List_iterator it(binlog_xid_count_list); + while ((b= it++)) + { + if (b->xid_count > 0) + return false; + } + return true; +} + + /** Create a new log file name. @@ -8216,6 +8235,13 @@ binlog_background_thread(void *arg __attribute__((unused))) { stop= binlog_background_thread_stop; queue= binlog_background_thread_queue; + if (stop && !mysql_bin_log.is_xidlist_idle()) + { + /* + Delay stop until all pending binlog checkpoints have been processed. + */ + stop= false; + } if (stop || queue) break; mysql_cond_wait(&mysql_bin_log.COND_binlog_background_thread, @@ -8226,9 +8252,18 @@ binlog_background_thread(void *arg __attribute__((unused))) mysql_mutex_unlock(&mysql_bin_log.LOCK_binlog_background_thread); /* Process any incoming commit_checkpoint_notify() calls. */ + DBUG_EXECUTE_IF("inject_binlog_background_thread_before_mark_xid_done", + DBUG_ASSERT(!debug_sync_set_action( + thd, + STRING_WITH_LEN("binlog_background_thread_before_mark_xid_done " + "SIGNAL injected_binlog_background_thread " + "WAIT_FOR something_that_will_never_happen " + "TIMEOUT 2"))); + ); while (queue) { thd_proc_info(thd, "Processing binlog checkpoint notification"); + DEBUG_SYNC(current_thd, "binlog_background_thread_before_mark_xid_done"); /* Grab next pointer first, as mark_xid_done() may free the element. */ next= queue->next_in_queue; mysql_bin_log.mark_xid_done(queue->binlog_id, true); diff --git a/sql/log.h b/sql/log.h index 80fe34b5ff2..da8faa36a00 100644 --- a/sql/log.h +++ b/sql/log.h @@ -526,6 +526,7 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG int write_transaction_or_stmt(group_commit_entry *entry); bool write_transaction_to_binlog_events(group_commit_entry *entry); void trx_group_commit_leader(group_commit_entry *leader); + bool is_xidlist_idle_nolock(); public: /* @@ -771,6 +772,7 @@ public: inline IO_CACHE *get_index_file() { return &index_file;} inline uint32 get_open_count() { return open_count; } void set_status_variables(THD *thd); + bool is_xidlist_idle(); }; class Log_event_handler