From 19c45b61f1dc830881fcb3bd0e553888f9e382d2 Mon Sep 17 00:00:00 2001 From: Venkatesh Prasad Venugopal Date: Wed, 25 Nov 2020 12:24:23 +0530 Subject: [PATCH] Bug #101717: Testcase to repeat the bug. Steps: 1. Apply this patch on the 8.0.22 code. 2. Build the server. 3. Run the rpl_gtid_bug_101717.test testcase. 4. Check slave's error logs (var/log/mysqld.2.err) for the debug prints. 5. Execute grep "Average of" var/log/mysqld.2.err for the details of the time taken by the `update_prev_gtids()` function --- .../suite/rpl_gtid/t/rpl_gtid_bug_101717.cnf | 20 +++++++++ .../suite/rpl_gtid/t/rpl_gtid_bug_101717.test | 44 +++++++++++++++++++ sql/rpl_gtid.h | 11 +++-- sql/rpl_gtid_state.cc | 1 + storage/innobase/clone/clone0repl.cc | 9 ++++ 5 files changed, 82 insertions(+), 3 deletions(-) create mode 100644 mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.cnf create mode 100644 mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.test diff --git a/mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.cnf b/mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.cnf new file mode 100644 index 00000000000..32306ff1aa8 --- /dev/null +++ b/mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.cnf @@ -0,0 +1,20 @@ +!include ../my.cnf + +[mysqld.1] +max_connections=5120 +gtid_mode = ON +enforce_gtid_consistency = ON +binlog_format = ROW + +[mysqld.2] +slave_net_timeout = 60 +slave_parallel_type = LOGICAL_CLOCK +slave_parallel_workers = 32 +slave_pending_jobs_size_max = 1G +gtid_mode = ON +enforce_gtid_consistency = ON +binlog_format = ROW +log_slave_updates = OFF + +# Uncomment the below line to disable binlog for testing +# skip-log-bin diff --git a/mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.test b/mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.test new file mode 100644 index 00000000000..797d54e3adc --- /dev/null +++ b/mysql-test/suite/rpl_gtid/t/rpl_gtid_bug_101717.test @@ -0,0 +1,44 @@ +--source include/have_debug.inc +--source include/have_debug_sync.inc + +# 1. Start two servers and setup replication. +--let $use_gtids=0 +--source include/master-slave.inc + +# 2. Enable Replication Filter on a table on slave. +--source include/rpl_connection_slave.inc +--source include/stop_slave.inc +CHANGE REPLICATION FILTER REPLICATE_WILD_IGNORE_TABLE=('db2.%'); +--source include/start_slave.inc + +# 3. Create 2 InnoDB tables on master. Since one of them is filtered on slave, +# updates on that table generates empty transactions. +--source include/rpl_connection_master.inc +CREATE DATABASE db1; +CREATE DATABASE db2; + +CREATE TABLE db1.t1(i int)engine=innodb; +CREATE TABLE db2.t1(i int)engine=innodb; + +# 4. Sync the slave. +--source include/sync_slave_sql_with_master.inc + +# 5. Insert 5k rows on each table on master +--source include/rpl_connection_master.inc +--disable_query_log +--let $iter=5000 +while ($iter) +{ + INSERT INTO db1.t1 VALUES(rand() * 10000); + INSERT INTO db2.t1 VALUES(rand() * 10000); + --dec $iter +} +--enable_query_log + +# 6. Check Slave's error logs (var/log/mysqld.2.err) + +--source include/rpl_connection_master.inc +DROP DATABASE db1; +DROP DATABASE db2; + +--source include/rpl_end.inc diff --git a/sql/rpl_gtid.h b/sql/rpl_gtid.h index 0898f83d9bc..9bebdb175ab 100644 --- a/sql/rpl_gtid.h +++ b/sql/rpl_gtid.h @@ -1811,12 +1811,15 @@ class Gtid_set { void dbug_print(const char *text MY_ATTRIBUTE((unused)) = "", bool need_lock MY_ATTRIBUTE((unused)) = false, const Gtid_set::String_format *sf MY_ATTRIBUTE((unused)) = - nullptr) const { + nullptr, + bool print_to_stderr = false) const { #ifndef DBUG_OFF char *str; to_string(&str, need_lock, sf); DBUG_PRINT("info", ("%s%s'%s'", text, *text ? ": " : "", str ? str : "out of memory in Gtid_set::dbug_print")); + if (print_to_stderr) + fprintf(stderr,"%s%s'%s\n", text, *text ? ": " : "", str ? str : "out of memory in Gtid_set::dbug_print"); my_free(str); #endif } @@ -3202,7 +3205,7 @@ class Gtid_state { /// Debug only: print this Gtid_state to stdout. void print() const { char *str = to_string(); - printf("%s", str); + fprintf(stderr,"%s\n", str); my_free(str); } #endif @@ -3210,11 +3213,13 @@ class Gtid_state { Print this Gtid_state to the trace file if debug is enabled; no-op otherwise. */ - void dbug_print(const char *text MY_ATTRIBUTE((unused)) = "") const { + void dbug_print(const char *text MY_ATTRIBUTE((unused)) = "", bool print_to_stderr = false) const { #ifndef DBUG_OFF sid_lock->assert_some_wrlock(); char *str = to_string(); DBUG_PRINT("info", ("%s%s%s", text, *text ? ": " : "", str)); + if (print_to_stderr) + fprintf(stderr,"%s%s%s", text, *text ? ": " : "", str); my_free(str); #endif } diff --git a/sql/rpl_gtid_state.cc b/sql/rpl_gtid_state.cc index 9e95c341a94..857d426d305 100644 --- a/sql/rpl_gtid_state.cc +++ b/sql/rpl_gtid_state.cc @@ -588,6 +588,7 @@ void Gtid_state::update_prev_gtids(Gtid_set *write_gtid_set) { /* Add to the list so that it won't be written again later. */ previous_gtids_logged.add_gtid_set(write_gtid_set); + previous_gtids_logged.dbug_print("[DEBUG] previous_gtids_logged in update_prev_gtids: ", false, nullptr, true/* print to stderr */); global_sid_lock->unlock(); DBUG_VOID_RETURN; diff --git a/storage/innobase/clone/clone0repl.cc b/storage/innobase/clone/clone0repl.cc index ec980e74d45..dc18d8d06d3 100644 --- a/storage/innobase/clone/clone0repl.cc +++ b/storage/innobase/clone/clone0repl.cc @@ -379,7 +379,16 @@ int Clone_persist_gtid::write_to_table(uint64_t flush_list_number, table_gtid_set.add_gtid_set(&write_gtid_set); } else { /* Handle concurrent write by other threads when binlog is enabled. */ + static int sum = 0, i = 0, sampling_rate = 100; + auto t0 = std::chrono::high_resolution_clock::now(); gtid_state->update_prev_gtids(&write_gtid_set); + auto t1 = std::chrono::high_resolution_clock::now(); + auto duration = std::chrono::duration_cast( t1 - t0 ).count(); + sum+=duration; + if (++i % sampling_rate == 0) { + std::cout << "[DEBUG] Average of last "<< sampling_rate << " calls = "<< (double)(sum / sampling_rate )<< " microseconds"<< std::endl; + sum = 0; + } } /* Write GTIDs to table. */ -- 2.25.1