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