From 26e3117ca9f02cf3dcb424b82e93be8709cc5e91 Mon Sep 17 00:00:00 2001 From: Annamalai Gurusami Date: Tue, 20 Sep 2016 09:51:22 +1000 Subject: [PATCH 01/52] MDEV-10829: Port Innodb NUMA interleave test cases from MySQL --- mysql-test/include/have_numa.inc | 9 +++++++++ .../sys_vars/r/innodb_numa_interleave_basic.result | 10 ++++++++++ .../sys_vars/t/innodb_numa_interleave_basic.test | 14 ++++++++++++++ 3 files changed, 33 insertions(+) create mode 100644 mysql-test/include/have_numa.inc create mode 100644 mysql-test/suite/sys_vars/r/innodb_numa_interleave_basic.result create mode 100644 mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic.test diff --git a/mysql-test/include/have_numa.inc b/mysql-test/include/have_numa.inc new file mode 100644 index 00000000000..18bca99e04d --- /dev/null +++ b/mysql-test/include/have_numa.inc @@ -0,0 +1,9 @@ +let $numa_support = `SELECT COUNT(VARIABLE_VALUE) = 1 FROM + INFORMATION_SCHEMA.GLOBAL_VARIABLES + WHERE VARIABLE_NAME='innodb_numa_interleave'`; + +if ( $numa_support == 0 ) +{ + --skip Test requires: Binary must be built with NUMA support. +} + diff --git a/mysql-test/suite/sys_vars/r/innodb_numa_interleave_basic.result b/mysql-test/suite/sys_vars/r/innodb_numa_interleave_basic.result new file mode 100644 index 00000000000..21ed16c1dab --- /dev/null +++ b/mysql-test/suite/sys_vars/r/innodb_numa_interleave_basic.result @@ -0,0 +1,10 @@ +SELECT @@GLOBAL.innodb_numa_interleave; +@@GLOBAL.innodb_numa_interleave +1 +SET @@GLOBAL.innodb_numa_interleave=off; +ERROR HY000: Variable 'innodb_numa_interleave' is a read only variable +SELECT @@GLOBAL.innodb_numa_interleave; +@@GLOBAL.innodb_numa_interleave +1 +SELECT @@SESSION.innodb_numa_interleave; +ERROR HY000: Variable 'innodb_numa_interleave' is a GLOBAL variable diff --git a/mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic.test b/mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic.test new file mode 100644 index 00000000000..518b5ebba17 --- /dev/null +++ b/mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic.test @@ -0,0 +1,14 @@ +--source include/have_innodb.inc +--source include/have_numa.inc +--source include/have_64bit.inc + +SELECT @@GLOBAL.innodb_numa_interleave; + +--error ER_INCORRECT_GLOBAL_LOCAL_VAR +SET @@GLOBAL.innodb_numa_interleave=off; + +SELECT @@GLOBAL.innodb_numa_interleave; + +--error ER_INCORRECT_GLOBAL_LOCAL_VAR +SELECT @@SESSION.innodb_numa_interleave; + From 8103f6f2235b58ca09f75efe24d2731895387152 Mon Sep 17 00:00:00 2001 From: Daniel Black Date: Tue, 20 Sep 2016 10:05:10 +1000 Subject: [PATCH 02/52] MDEV-10829: Enable Innodb NUMA interleave Code was already existing within the innobase/xtradb storage engines however without this cmake code it was never enabled. num.cmake heavily based off work by Annamalai Gurusami Signed-off-by: Daniel Black --- CMakeLists.txt | 1 + cmake/numa.cmake | 38 +++++++++++++++++++ config.h.cmake | 1 + .../t/innodb_numa_interleave_basic-master.opt | 1 + storage/innobase/CMakeLists.txt | 12 +++++- storage/xtradb/CMakeLists.txt | 12 +++++- 6 files changed, 63 insertions(+), 2 deletions(-) create mode 100644 cmake/numa.cmake create mode 100644 mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic-master.opt diff --git a/CMakeLists.txt b/CMakeLists.txt index a04181fd6ea..48742995722 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -154,6 +154,7 @@ INCLUDE(install_macros) INCLUDE(systemd) INCLUDE(mysql_add_executable) INCLUDE(crc32-vpmsum) +INCLUDE(numa) # Handle options OPTION(DISABLE_SHARED diff --git a/cmake/numa.cmake b/cmake/numa.cmake new file mode 100644 index 00000000000..d5234a5ef4f --- /dev/null +++ b/cmake/numa.cmake @@ -0,0 +1,38 @@ +MACRO (MYSQL_CHECK_NUMA) + + CHECK_INCLUDE_FILES(numa.h HAVE_NUMA_H) + CHECK_INCLUDE_FILES(numaif.h HAVE_NUMAIF_H) + + IF(HAVE_NUMA_H AND HAVE_NUMAIF_H) + OPTION(WITH_NUMA "Explicitly set NUMA memory allocation policy" ON) + ELSE() + OPTION(WITH_NUMA "Explicitly set NUMA memory allocation policy" OFF) + ENDIF() + + IF(WITH_NUMA AND HAVE_NUMA_H AND HAVE_NUMAIF_H) + SET(SAVE_CMAKE_REQUIRED_LIBRARIES ${CMAKE_REQUIRED_LIBRARIES}) + SET(CMAKE_REQUIRED_LIBRARIES ${CMAKE_REQUIRED_LIBRARIES} numa) + CHECK_C_SOURCE_COMPILES( + " + #include + #include + int main() + { + struct bitmask *all_nodes= numa_all_nodes_ptr; + set_mempolicy(MPOL_DEFAULT, 0, 0); + return all_nodes != NULL; + }" + HAVE_LIBNUMA) + SET(CMAKE_REQUIRED_LIBRARIES ${SAVE_CMAKE_REQUIRED_LIBRARIES}) + ELSE() + SET(HAVE_LIBNUMA 0) + ENDIF() + + IF(WITH_NUMA AND NOT HAVE_LIBNUMA) + # Forget it in cache, abort the build. + UNSET(WITH_NUMA CACHE) + MESSAGE(FATAL_ERROR "Could not find numa headers/libraries") + ENDIF() + +ENDMACRO() + diff --git a/config.h.cmake b/config.h.cmake index 00aa03483ee..08b0422a520 100644 --- a/config.h.cmake +++ b/config.h.cmake @@ -106,6 +106,7 @@ #cmakedefine HAVE_LIBWRAP 1 #cmakedefine HAVE_SYSTEMD 1 #cmakedefine HAVE_CRC32_VPMSUM 1 +#cmakedefine HAVE_LIBNUMA 1 /* Does "struct timespec" have a "sec" and "nsec" field? */ #cmakedefine HAVE_TIMESPEC_TS_SEC 1 diff --git a/mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic-master.opt b/mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic-master.opt new file mode 100644 index 00000000000..c1c2bb26b8a --- /dev/null +++ b/mysql-test/suite/sys_vars/t/innodb_numa_interleave_basic-master.opt @@ -0,0 +1 @@ +--loose-innodb_numa_interleave=1 diff --git a/storage/innobase/CMakeLists.txt b/storage/innobase/CMakeLists.txt index 7e667d5ebb2..c80ef6f0993 100644 --- a/storage/innobase/CMakeLists.txt +++ b/storage/innobase/CMakeLists.txt @@ -29,6 +29,7 @@ MYSQL_CHECK_LZO() MYSQL_CHECK_LZMA() MYSQL_CHECK_BZIP2() MYSQL_CHECK_SNAPPY() +MYSQL_CHECK_NUMA() IF(CMAKE_CROSSCOMPILING) # Use CHECK_C_SOURCE_COMPILES instead of CHECK_C_SOURCE_RUNS when @@ -506,8 +507,17 @@ ELSE() SET(LINKER_SCRIPT) ENDIF() +UNSET(NUMA_LIBRARY) +IF(HAVE_LIBNUMA) + SET(NUMA_LIBRARY "numa") +ENDIF() + MYSQL_ADD_PLUGIN(innobase ${INNOBASE_SOURCES} STORAGE_ENGINE MODULE_ONLY MODULE_OUTPUT_NAME ha_innodb - LINK_LIBRARIES ${ZLIB_LIBRARY} ${CRC32_VPMSUM_LIBRARY} ${LINKER_SCRIPT}) + LINK_LIBRARIES + ${ZLIB_LIBRARY} + ${CRC32_VPMSUM_LIBRARY} + ${NUMA_LIBRARY} + ${LINKER_SCRIPT}) diff --git a/storage/xtradb/CMakeLists.txt b/storage/xtradb/CMakeLists.txt index 7d2a3fad56d..51e24b3cd8a 100644 --- a/storage/xtradb/CMakeLists.txt +++ b/storage/xtradb/CMakeLists.txt @@ -29,6 +29,7 @@ MYSQL_CHECK_LZO() MYSQL_CHECK_LZMA() MYSQL_CHECK_BZIP2() MYSQL_CHECK_SNAPPY() +MYSQL_CHECK_NUMA() IF(CMAKE_CROSSCOMPILING) # Use CHECK_C_SOURCE_COMPILES instead of CHECK_C_SOURCE_RUNS when @@ -496,9 +497,18 @@ SET(INNOBASE_SOURCES ut/ut0wqueue.cc ut/ut0timer.cc) +UNSET(NUMA_LIBRARY) +IF(HAVE_LIBNUMA) + SET(NUMA_LIBRARY "numa") +ENDIF() + MYSQL_ADD_PLUGIN(xtradb ${INNOBASE_SOURCES} STORAGE_ENGINE DEFAULT RECOMPILE_FOR_EMBEDDED - LINK_LIBRARIES ${ZLIB_LIBRARY} ${CRC32_VPMSUM_LIBRARY} ${LINKER_SCRIPT}) + LINK_LIBRARIES + ${ZLIB_LIBRARY} + ${CRC32_VPMSUM_LIBRARY} + ${NUMA_LIBRARY} + ${LINKER_SCRIPT}) IF(TARGET xtradb AND NOT XTRADB_OK) MESSAGE(FATAL_ERROR "Percona XtraDB is not supported on this platform") From 8b59eab7a34f5d540fdf3e88dbe5a1fcd5bbb0e5 Mon Sep 17 00:00:00 2001 From: Daniel Black Date: Fri, 23 Sep 2016 08:58:57 +1000 Subject: [PATCH 03/52] MDEV-10829: add libnuma-dev to debian packaging Signed-off-by: Daniel Black --- debian/control | 1 + 1 file changed, 1 insertion(+) diff --git a/debian/control b/debian/control index 8fa4b6e5a33..52c26597187 100644 --- a/debian/control +++ b/debian/control @@ -17,6 +17,7 @@ Build-Depends: bison, libpam0g-dev, libreadline-gplv2-dev, libssl-dev, + libnuma-dev, lsb-release, perl (>= 5.6.0), po-debconf, From 8e8e65ed1c747a9b53b07ba5147103210b517c32 Mon Sep 17 00:00:00 2001 From: Daniel Black Date: Mon, 19 Sep 2016 12:07:20 +1000 Subject: [PATCH 04/52] MDEV-10829: innodb_numa_interleave=1, use numa numa_get_mems_allowed Using numa_all_nodes_ptr was excessively optimistic. Due to constraints in systemd, containers or otherwise mysqld could of been limited to a smaller set of cpus. Use the numa_get_mems_allowed library function to see what we can interleave between before doing so. The alternative is to fail interleaving overall. Signed-off-by: Daniel Black --- storage/innobase/buf/buf0buf.cc | 11 +++++++---- storage/xtradb/buf/buf0buf.cc | 11 +++++++---- 2 files changed, 14 insertions(+), 8 deletions(-) diff --git a/storage/innobase/buf/buf0buf.cc b/storage/innobase/buf/buf0buf.cc index b3eaf4bf5a9..9ad0dd3b854 100644 --- a/storage/innobase/buf/buf0buf.cc +++ b/storage/innobase/buf/buf0buf.cc @@ -1157,10 +1157,11 @@ buf_chunk_init( #ifdef HAVE_LIBNUMA if (srv_numa_interleave) { + struct bitmask *numa_mems_allowed = numa_get_mems_allowed(); int st = mbind(chunk->mem, chunk->mem_size, MPOL_INTERLEAVE, - numa_all_nodes_ptr->maskp, - numa_all_nodes_ptr->size, + numa_mems_allowed->maskp, + numa_mems_allowed->size, MPOL_MF_MOVE); if (st != 0) { ib_logf(IB_LOG_LEVEL_WARN, @@ -1551,11 +1552,13 @@ buf_pool_init( #ifdef HAVE_LIBNUMA if (srv_numa_interleave) { + struct bitmask *numa_mems_allowed = numa_get_mems_allowed(); + ib_logf(IB_LOG_LEVEL_INFO, "Setting NUMA memory policy to MPOL_INTERLEAVE"); if (set_mempolicy(MPOL_INTERLEAVE, - numa_all_nodes_ptr->maskp, - numa_all_nodes_ptr->size) != 0) { + numa_mems_allowed->maskp, + numa_mems_allowed->size) != 0) { ib_logf(IB_LOG_LEVEL_WARN, "Failed to set NUMA memory policy to" " MPOL_INTERLEAVE (error: %s).", diff --git a/storage/xtradb/buf/buf0buf.cc b/storage/xtradb/buf/buf0buf.cc index a81d21a04b5..17f3b4fbadc 100644 --- a/storage/xtradb/buf/buf0buf.cc +++ b/storage/xtradb/buf/buf0buf.cc @@ -1235,10 +1235,11 @@ buf_chunk_init( #ifdef HAVE_LIBNUMA if (srv_numa_interleave) { + struct bitmask *numa_mems_allowed = numa_get_mems_allowed(); int st = mbind(chunk->mem, chunk->mem_size, MPOL_INTERLEAVE, - numa_all_nodes_ptr->maskp, - numa_all_nodes_ptr->size, + numa_mems_allowed->maskp, + numa_mems_allowed->size, MPOL_MF_MOVE); if (st != 0) { ib_logf(IB_LOG_LEVEL_WARN, @@ -1645,11 +1646,13 @@ buf_pool_init( #ifdef HAVE_LIBNUMA if (srv_numa_interleave) { + struct bitmask *numa_mems_allowed = numa_get_mems_allowed(); + ib_logf(IB_LOG_LEVEL_INFO, "Setting NUMA memory policy to MPOL_INTERLEAVE"); if (set_mempolicy(MPOL_INTERLEAVE, - numa_all_nodes_ptr->maskp, - numa_all_nodes_ptr->size) != 0) { + numa_mems_allowed->maskp, + numa_mems_allowed->size) != 0) { ib_logf(IB_LOG_LEVEL_WARN, "Failed to set NUMA memory policy to" " MPOL_INTERLEAVE (error: %s).", From 633e995c6299afdd2d20ea7b7a46a5359e6eb552 Mon Sep 17 00:00:00 2001 From: Daniel Black Date: Fri, 23 Sep 2016 09:09:46 +1000 Subject: [PATCH 05/52] MDEV-10829: libnuma-dev for travis Signed-off-by: Daniel Black --- .travis.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.travis.yml b/.travis.yml index b09c348dfab..4d405e339f0 100644 --- a/.travis.yml +++ b/.travis.yml @@ -32,6 +32,7 @@ addons: - libpam0g-dev - libreadline-gplv2-dev - libssl-dev + - libnuma-dev - lsb-release - perl - po-debconf From 50f19ca8099994e992e1b411c7c05287855a7bdd Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Tue, 20 Sep 2016 15:30:57 +0200 Subject: [PATCH 06/52] Remove unnecessary global mutex in parallel replication. The function apply_event_and_update_pos() is called with the rli->data_lock mutex held. However, there seems to be nothing in the function actually needing the mutex to be held. Certainly not in the parallel replication case, where sql_slave_skip_counter is always 0 since the non-zero case is handled by the SQL driver thread. So this patch makes parallel replication use a variant of apply_event_and_update_pos() without the need to take the rli->data_lock mutex. This avoids one contended global mutex for each event executed, which might improve performance on CPU-bound workloads somewhat. Signed-off-by: Kristian Nielsen --- sql/rpl_parallel.cc | 4 +- sql/slave.cc | 130 +++++++++++++++++++++++++++++++------------- sql/slave.h | 5 +- 3 files changed, 96 insertions(+), 43 deletions(-) diff --git a/sql/rpl_parallel.cc b/sql/rpl_parallel.cc index 761471fc1cb..c507a132374 100644 --- a/sql/rpl_parallel.cc +++ b/sql/rpl_parallel.cc @@ -47,9 +47,7 @@ rpt_handle_event(rpl_parallel_thread::queued_event *qev, if (!(ev->is_artificial_event() || ev->is_relay_log_event() || (ev->when == 0))) rgi->last_master_timestamp= ev->when + (time_t)ev->exec_time; - mysql_mutex_lock(&rli->data_lock); - /* Mutex will be released in apply_event_and_update_pos(). */ - err= apply_event_and_update_pos(ev, thd, rgi, rpt); + err= apply_event_and_update_pos_for_parallel(ev, thd, rgi); thread_safe_increment64(&rli->executed_entries); /* ToDo: error handling. */ diff --git a/sql/slave.cc b/sql/slave.cc index 4981819577f..a55d26b1aa0 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -3377,39 +3377,17 @@ has_temporary_error(THD *thd) } -/** - Applies the given event and advances the relay log position. +/* + First half of apply_event_and_update_pos(), see below. + Setup some THD variables for applying the event. - In essence, this function does: - - @code - ev->apply_event(rli); - ev->update_pos(rli); - @endcode - - But it also does some maintainance, such as skipping events if - needed and reporting errors. - - If the @c skip flag is set, then it is tested whether the event - should be skipped, by looking at the slave_skip_counter and the - server id. The skip flag should be set when calling this from a - replication thread but not set when executing an explicit BINLOG - statement. - - @retval 0 OK. - - @retval 1 Error calling ev->apply_event(). - - @retval 2 No error calling ev->apply_event(), but error calling - ev->update_pos(). + Split out so that it can run with rli->data_lock held in non-parallel + replication, but without the mutex held in the parallel case. */ -int apply_event_and_update_pos(Log_event* ev, THD* thd, - rpl_group_info *rgi, - rpl_parallel_thread *rpt) +static int +apply_event_and_update_pos_setup(Log_event* ev, THD* thd, rpl_group_info *rgi) { - int exec_res= 0; - Relay_log_info* rli= rgi->rli; - DBUG_ENTER("apply_event_and_update_pos"); + DBUG_ENTER("apply_event_and_update_pos_setup"); DBUG_PRINT("exec_event",("%s(type_code: %d; server_id: %d)", ev->get_type_str(), ev->get_type_code(), @@ -3459,13 +3437,23 @@ int apply_event_and_update_pos(Log_event* ev, THD* thd, (ev->flags & LOG_EVENT_SKIP_REPLICATION_F ? OPTION_SKIP_REPLICATION : 0); ev->thd = thd; // because up to this point, ev->thd == 0 - int reason= ev->shall_skip(rgi); - if (reason == Log_event::EVENT_SKIP_COUNT) - { - DBUG_ASSERT(rli->slave_skip_counter > 0); - rli->slave_skip_counter--; - } - mysql_mutex_unlock(&rli->data_lock); + DBUG_RETURN(ev->shall_skip(rgi)); +} + + +/* + Second half of apply_event_and_update_pos(), see below. + + Do the actual event apply (or skip), and position update. + */ +static int +apply_event_and_update_pos_apply(Log_event* ev, THD* thd, rpl_group_info *rgi, + int reason) +{ + int exec_res= 0; + Relay_log_info* rli= rgi->rli; + + DBUG_ENTER("apply_event_and_update_pos_apply"); DBUG_EXECUTE_IF("inject_slave_sql_before_apply_event", { DBUG_ASSERT(!debug_sync_set_action @@ -3553,6 +3541,72 @@ int apply_event_and_update_pos(Log_event* ev, THD* thd, } +/** + Applies the given event and advances the relay log position. + + In essence, this function does: + + @code + ev->apply_event(rli); + ev->update_pos(rli); + @endcode + + But it also does some maintainance, such as skipping events if + needed and reporting errors. + + If the @c skip flag is set, then it is tested whether the event + should be skipped, by looking at the slave_skip_counter and the + server id. The skip flag should be set when calling this from a + replication thread but not set when executing an explicit BINLOG + statement. + + @retval 0 OK. + + @retval 1 Error calling ev->apply_event(). + + @retval 2 No error calling ev->apply_event(), but error calling + ev->update_pos(). + + This function is only used in non-parallel replication, where it is called + with rli->data_lock held; this lock is released during this function. +*/ +int +apply_event_and_update_pos(Log_event* ev, THD* thd, rpl_group_info *rgi) +{ + Relay_log_info* rli= rgi->rli; + mysql_mutex_assert_owner(&rli->data_lock); + int reason= apply_event_and_update_pos_setup(ev, thd, rgi); + if (reason == Log_event::EVENT_SKIP_COUNT) + { + DBUG_ASSERT(rli->slave_skip_counter > 0); + rli->slave_skip_counter--; + } + mysql_mutex_unlock(&rli->data_lock); + return apply_event_and_update_pos_apply(ev, thd, rgi, reason); +} + + +/* + The version of above apply_event_and_update_pos() used in parallel + replication. Unlike the non-parallel case, this function is called without + rli->data_lock held. +*/ +int +apply_event_and_update_pos_for_parallel(Log_event* ev, THD* thd, + rpl_group_info *rgi) +{ + Relay_log_info* rli= rgi->rli; + mysql_mutex_assert_not_owner(&rli->data_lock); + int reason= apply_event_and_update_pos_setup(ev, thd, rgi); + /* + In parallel replication, sql_slave_skip_counter is handled in the SQL + driver thread, so 23 should never see EVENT_SKIP_COUNT here. + */ + DBUG_ASSERT(reason != Log_event::EVENT_SKIP_COUNT); + return apply_event_and_update_pos_apply(ev, thd, rgi, reason); +} + + /** Keep the relay log transaction state up to date. @@ -3803,7 +3857,7 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli, serial_rgi->future_event_relay_log_pos= rli->future_event_relay_log_pos; serial_rgi->event_relay_log_name= rli->event_relay_log_name; serial_rgi->event_relay_log_pos= rli->event_relay_log_pos; - exec_res= apply_event_and_update_pos(ev, thd, serial_rgi, NULL); + exec_res= apply_event_and_update_pos(ev, thd, serial_rgi); #ifdef WITH_WSREP WSREP_DEBUG("apply_event_and_update_pos() result: %d", exec_res); diff --git a/sql/slave.h b/sql/slave.h index e8a925ce560..a78ae4cff6f 100644 --- a/sql/slave.h +++ b/sql/slave.h @@ -243,8 +243,9 @@ void set_slave_thread_default_charset(THD *thd, rpl_group_info *rgi); int rotate_relay_log(Master_info* mi); int has_temporary_error(THD *thd); int apply_event_and_update_pos(Log_event* ev, THD* thd, - struct rpl_group_info *rgi, - rpl_parallel_thread *rpt); + struct rpl_group_info *rgi); +int apply_event_and_update_pos_for_parallel(Log_event* ev, THD* thd, + struct rpl_group_info *rgi); pthread_handler_t handle_slave_io(void *arg); void slave_output_error_info(rpl_group_info *rgi, THD *thd); From 19abe79fd15ab6d8ac0c2f65476bc3c7d29a008d Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Thu, 22 Sep 2016 08:26:45 +0200 Subject: [PATCH 07/52] MDEV-7145: Delayed replication, intermediate commit. Initial merge of delayed replication from MySQL git. The code from the initial push into MySQL is merged, and the associated test case passes. A number of tasks are still pending: 1. Check full test suite run for any regressions or .result file updates. 2. Extend the feature to also work for parallel replication. 3. There are some todo-comments about future refactoring left from MySQL, these should be located and merged on top. 4. There are some later related MySQL commits, these should be checked and merged. These include: e134b9362ba0b750d6ac1b444780019622d14aa5 b38f0f7857c073edfcc0a64675b7f7ede04be00f fd2b210383358fe7697f201e19ac9779879ba72a afc397376ec50e96b2918ee64e48baf4dda0d37d 5. The testcase from MySQL relies heavily on sleep and timing for testing, and seems likely to sporadically fail on heavily loaded test servers in buildbot or distro build farms. Signed-off-by: Kristian Nielsen --- .../rpl_tests/delayed_slave_wait_on_query.inc | 39 ++ mysql-test/include/check-testcase.test | 3 + .../include/show_delayed_slave_state.inc | 28 ++ mysql-test/include/sync_with_master.inc | 26 ++ .../suite/rpl/r/rpl_delayed_slave.result | 172 +++++++++ mysql-test/suite/rpl/t/rpl_delayed_slave.test | 348 ++++++++++++++++++ sql/lex.h | 1 + sql/log.cc | 8 +- sql/log_event.cc | 7 + sql/rpl_mi.cc | 2 +- sql/rpl_rli.cc | 178 ++++----- sql/rpl_rli.h | 115 +++++- sql/slave.cc | 243 +++++++++--- sql/slave.h | 18 +- sql/sql_binlog.cc | 148 +++++--- sql/sql_lex.cc | 1 - sql/sql_lex.h | 5 +- sql/sql_repl.cc | 4 + sql/sql_yacc.yy | 13 + 19 files changed, 1149 insertions(+), 210 deletions(-) create mode 100644 mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc create mode 100644 mysql-test/include/show_delayed_slave_state.inc create mode 100644 mysql-test/include/sync_with_master.inc create mode 100644 mysql-test/suite/rpl/r/rpl_delayed_slave.result create mode 100644 mysql-test/suite/rpl/t/rpl_delayed_slave.test diff --git a/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc b/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc new file mode 100644 index 00000000000..5d04d14edf3 --- /dev/null +++ b/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc @@ -0,0 +1,39 @@ +# ==== Purpose ==== +# +# Auxiliary file used by rpl_delayed_slave.test. This assumes that an +# 'INSERT INTO t1...' query has been executed on the master. It does +# this: +# +# - After half the delay, check the status. It should be delaying and +# the query should not have executed. +# +# - After one and a half delay, check the status. It should not be +# delaying and the query should be executed. +# +# ==== Usage ==== +# +# --source extra/rpl_tests/delayed_slave_wait_on_query.inc + +connection master; +--echo [on slave] +--let $slave_timeout= $time1 + +--source include/sync_slave_io_with_master.inc +--echo # sleep 1*T +--sleep $time1 + +--echo # Expect query not executed and status is 'Waiting until MASTER_DELAY...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +--source include/show_delayed_slave_state.inc + +--echo # sleep 1*T +--sleep $time1 + +--echo # sync with master (with timeout 1*T) +--source include/sync_with_master.inc + +--echo # Expect query executed and status is 'Has read all relay log...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +--source include/show_delayed_slave_state.inc + +--source include/check_slave_is_running.inc diff --git a/mysql-test/include/check-testcase.test b/mysql-test/include/check-testcase.test index 083f44ce966..abac3861c66 100644 --- a/mysql-test/include/check-testcase.test +++ b/mysql-test/include/check-testcase.test @@ -67,6 +67,9 @@ if ($tmp) --echo Replicate_Do_Domain_Ids --echo Replicate_Ignore_Domain_Ids --echo Parallel_Mode conservative + --echo SQL_Delay 0 + --echo SQL_Remaining_Delay NULL + --echo Slave_SQL_Running_State } if (!$tmp) { # Note: after WL#5177, fields 13-18 shall not be filtered-out. diff --git a/mysql-test/include/show_delayed_slave_state.inc b/mysql-test/include/show_delayed_slave_state.inc new file mode 100644 index 00000000000..8eb7232a206 --- /dev/null +++ b/mysql-test/include/show_delayed_slave_state.inc @@ -0,0 +1,28 @@ +# ==== Purpose ==== +# +# Display the delay state of the SQL thread. +# +# ==== Usage ==== +# +# --let $verbose_delayed_slave_state= [0|1] +# --source extra/rpl_tests/show_delayed_slave_state.inc +# +# By default, the output is normalized so that it does not depend on +# exact timing or exact binlog positions. If +# $verbose_delayed_slave_state is set, then it outputs exact times and +# binlog positions. This can be useful for debugging. + +--let $_delayed_slave_status= query_get_value(SHOW SLAVE STATUS, Slave_SQL_Running_State, 1) + +--let $_delayed_slave_remaining_delay= query_get_value(SHOW SLAVE STATUS, SQL_Remaining_Delay, 1) +--let $_delayed_slave_qualitative_delay= `SELECT CASE WHEN "$_delayed_slave_remaining_delay" = "NULL" THEN "NULL" WHEN "$_delayed_slave_remaining_delay" = "0" THEN "0" ELSE "greater than zero" END` + +--let $_delayed_slave_io_pos= query_get_value(SHOW SLAVE STATUS, Read_Master_Log_Pos, 1) +--let $_delayed_slave_sql_pos= query_get_value(SHOW SLAVE STATUS, Exec_Master_Log_Pos, 1) +--let $_delayed_slave_qualitative_log_pos= `SELECT IF($_delayed_slave_io_pos > $_delayed_slave_sql_pos, "behind", "in sync with")` + +--echo Slave_SQL_Running_State='$_delayed_slave_status'; SQL_Remaining_Delay is $_delayed_slave_qualitative_delay; SQL thread is $_delayed_slave_qualitative_log_pos IO thread + +if ($verbose_delayed_slave_state) { + --echo SQL_Remaining_Delay='$_delayed_slave_remaining_delay'; Read_master_log_pos='$_delayed_slave_io_pos'; Exec_Master_Log_Pos='$_delayed_slave_sql_pos' +} diff --git a/mysql-test/include/sync_with_master.inc b/mysql-test/include/sync_with_master.inc new file mode 100644 index 00000000000..dcb995a3ca9 --- /dev/null +++ b/mysql-test/include/sync_with_master.inc @@ -0,0 +1,26 @@ +# ==== Purpose ==== +# +# This file does the same as the built-in command sync_with_master, +# but can be configured to use a custom timeout. This has the benefit +# that it accepts the same $slave_timeout and $master_connection +# parameters as wait_for_slave_param.inc +# +# +# ==== Usage ==== +# +# --connection master +# --source include/save_master_pos.inc +# --connection slave +# --source include/sync_with_master.inc +# +# Parameters to this macro are $slave_timeout and +# $master_connection. See wait_for_slave_param.inc for +# descriptions. + +--let $slave_param= Relay_Master_Log_File +--let $slave_param_value= $_master_file +--source include/wait_for_slave_param.inc + +--let $slave_param= Exec_Master_Log_Pos +--let $slave_param_value= $_master_pos +--source include/wait_for_slave_param.inc diff --git a/mysql-test/suite/rpl/r/rpl_delayed_slave.result b/mysql-test/suite/rpl/r/rpl_delayed_slave.result new file mode 100644 index 00000000000..75b263b61e0 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_delayed_slave.result @@ -0,0 +1,172 @@ +include/master-slave.inc +[connection master] +call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); +call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); +[on master] +CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); +==== Normal setup ==== +[on slave] +include/stop_slave.inc +# CHANGE MASTER TO MASTER_DELAY = 2*T +# Checking that delay is what we set it to +# Expect status to be '' +SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1; +STATE + +include/start_slave.inc +[on master] +INSERT INTO t1(a) VALUES ('normal setup'); +[on slave] +include/sync_slave_io_with_master.inc +# sleep 1*T +# Expect query not executed and status is 'Waiting until MASTER_DELAY...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# sleep 1*T +# sync with master (with timeout 1*T) +include/wait_for_slave_param.inc [Relay_Master_Log_File] +include/wait_for_slave_param.inc [Exec_Master_Log_Pos] +# Expect query executed and status is 'Has read all relay log...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +normal setup 1 +Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +include/check_slave_is_running.inc +==== Slave lags "naturally" after master ==== +[on master] +# CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * T); ELSE RETURN 0; END IF; END +INSERT INTO t1(a) SELECT delay_on_slave(3); +Warnings: +Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. +Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. +INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately'); +INSERT INTO t1(a) SELECT delay_on_slave(2); +Warnings: +Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. +Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. +[on slave] +include/sync_slave_io_with_master.inc +# sleep 1*T +# Expect no query executed and status is 'Waiting until MASTER_DELAY...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +normal setup 1 +Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# wait for first query to execute +# sleep 1*T +# Expect second query executed and status is executing third query (i.e., 'User sleep') +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +slave is already lagging: this statement should execute immediately 3 +Slave_SQL_Running_State='User sleep'; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread +# sleep 2*T +# Expect query executed and status is 'Has read all relay log...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +0 4 +Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +==== Seconds_Behind_Master ==== +# Bring slave to sync. +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY = 0; +include/start_slave.inc +INSERT INTO t1(a) VALUES ('Syncing slave'); +include/stop_slave.inc +# CHANGE MASTER TO MASTER_DELAY = 2*T +include/start_slave.inc +INSERT INTO t1(a) VALUES (delay_on_slave(1)); +Warnings: +Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. +Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. +# sleep 1*T +# sleep 1*T +==== STOP SLAVE and START SLAVE ==== +include/stop_slave.inc +# CHANGE MASTER TO MASTER_DELAY = 3*T +include/start_slave.inc +# Checking that delay is what we set it to +[on master] +INSERT INTO t1(a) VALUES ('stop slave and start slave'); +[on slave] +# sleep 1*T +SET @before_stop_slave= UNIX_TIMESTAMP(); +include/stop_slave.inc +# STOP SLAVE finished in time. +# Expect query not executed and status is '' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +0 6 +Slave_SQL_Running_State=''; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread +include/start_slave.inc +# START SLAVE finished in time. +[on slave] +include/sync_slave_io_with_master.inc +# sleep 1*T +# Expect query not executed and status is 'Waiting until MASTER_DELAY...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +0 6 +Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# sleep 1*T +# sync with master (with timeout 1*T) +include/wait_for_slave_param.inc [Relay_Master_Log_File] +include/wait_for_slave_param.inc [Exec_Master_Log_Pos] +# Expect query executed and status is 'Has read all relay log...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +stop slave and start slave 7 +Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +include/check_slave_is_running.inc +==== Change back to no delay ==== +[on slave] +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY = 0; +# Expect delay is 0. +SQL_Delay='0' +include/start_slave.inc +[on master] +INSERT INTO t1(a) VALUES ('change back to no delay'); +[on slave] +include/sync_slave_io_with_master.inc +# sleep 1*T +# Expect query executed and status is 'Has read all relay log...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +a b +change back to no delay 8 +Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +==== Reset delay with RESET SLAVE ==== +include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY = 71; +include/start_slave.inc +# Expect delay is 71 +SQL_Delay='71' +include/stop_slave.inc +RESET SLAVE; +[on master] +RESET MASTER; +[on slave] +include/start_slave.inc +# Expect delay is 0 +SQL_Delay='0' +==== Set a bad value for the delay ==== +include/stop_slave.inc +# Expect error for setting negative delay +CHANGE MASTER TO MASTER_DELAY = -1; +ERROR 42000: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '-1' at line 1 +# Expect that it's ok to set delay of 2^31-1 +CHANGE MASTER TO MASTER_DELAY = 2147483647; +# Expect error for setting delay between 2^31 and 2^32-1 +CHANGE MASTER TO MASTER_DELAY = 2147483648; +ERROR HY000: The requested value 2147483648 for the master delay exceeds the maximum 2147483647 +# Expect error for setting delay to nonsense +CHANGE MASTER TO MASTER_DELAY = blah; +ERROR 42000: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near 'blah' at line 1 +CHANGE MASTER TO MASTER_DELAY = 0; +include/start_slave.inc +==== Clean up ==== +[on master] +DROP TABLE t1; +DROP FUNCTION delay_on_slave; +[on slave] +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_delayed_slave.test b/mysql-test/suite/rpl/t/rpl_delayed_slave.test new file mode 100644 index 00000000000..2fa5c81f5a5 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave.test @@ -0,0 +1,348 @@ +# ==== Purpose ==== +# +# Test the time-delayed replication feature, i.e., +# CHANGE MASTER TO MASTER_DELAY=X: +# +# - Verify that slave has executed the events after but not before the +# delay timeout. +# +# - Verify that delay is correct works when slave is already lagging +# due to slow queries. +# +# - Verify that Seconds_Behind_Master is greater than or equal to the +# delay if the slave still has unprocessed events in the relay log +# and more time than the delay has elapsed since the last event was +# executed on the master. +# +# - Verify that STOP SLAVE works instantly even during a delay, and +# that it does not cause the waited-for event to be executed too +# early on slave. +# +# - Verify that changing back to no delay works. +# +# - Verify that RESET SLAVE sets the delay to 0. +# +# - Verify that setting a bad value for the delay gives an error. +# +# ==== Implementation ==== +# +# We run the slave with 10 seconds lag. +# +# In general, to test that a query has not been executed by the slave +# before this time, we wait until the slave IO thread has received the +# event, and then 5 seconds more, and check that the table has not +# been updated. To test that a query has been executed after this +# time, we wait 10 seconds more. +# +# To simulate that the slave lags due to slow queries, we invoke a +# stored function that executes SLEEP if @@gloval.server_id==2. This +# requires that we run with binlog_format=STATEMENT. +# +# ==== Related Bugs and Worklogs ==== +# +# WL#344: Time-delayed replication +# BUG#28760: Simulating a replication lag +# [duplicate] BUG#22072: configurable delayed replication +# [duplicate] BUG#21639: Add Replication Delay parameter +# +# ==== Issues with this Test Case ==== +# +# The test is inherently timing-sensitive (i.e., contains races) and +# is likely to fail sporadically on a loaded host. +# +# The test takes a long time; it sleeps for around 20*10 seconds. + +--source include/master-slave.inc +# Needed so that sleeps get executed in the slave SQL thread. +--source include/have_binlog_format_statement.inc + + +call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); +--connection slave +call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); +--connection master + + +# We assume that any simple operation takes zero time, with an error +# margin of $time1 seconds. Hence, if we run with a delay of $time2 +# seconds, we expect that: +# - If we execute a query on master and wait $time1 seconds, then the +# query has been copied to slave but not yet executed. +# - If we execute a query on master and wait $time3 seconds, then the +# query has been executed. +--let $time1= 10 +if (`SELECT '$max_query_execution_time' > 0`) { + --let $time1= $max_query_execution_time +} +--let $time2= `SELECT 2 * $time1` +--let $time3= `SELECT 3 * $time1` + + +--echo [on master] +CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); + + +--echo ==== Normal setup ==== + +--echo [on slave] +--sync_slave_with_master + +--source include/stop_slave.inc + +--echo # CHANGE MASTER TO MASTER_DELAY = 2*T +--disable_query_log +eval CHANGE MASTER TO MASTER_DELAY = $time2; +--enable_query_log + +--echo # Checking that delay is what we set it to +--let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) +if (`SELECT $delay != $time2`) { + --echo Delay is wrong! Expected $time2, got $delay + --source include/show_rpl_debug_info.inc + --die wrong delay +} + +--echo # Expect status to be '' +SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1; + +--source include/start_slave.inc + +--echo [on master] +--connection master +INSERT INTO t1(a) VALUES ('normal setup'); + +--source extra/rpl_tests/delayed_slave_wait_on_query.inc + + +--echo ==== Slave lags "naturally" after master ==== + +--echo [on master] +--connection master + +--disable_query_log +--echo # CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * T); ELSE RETURN 0; END IF; END +--eval CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * $time1); ELSE RETURN 0; END IF; END +--enable_query_log + +INSERT INTO t1(a) SELECT delay_on_slave(3); + +--save_master_pos +INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately'); +INSERT INTO t1(a) SELECT delay_on_slave(2); + +--echo [on slave] +--source include/sync_slave_io_with_master.inc +--echo # sleep 1*T +--sleep $time1 + +--echo # Expect no query executed and status is 'Waiting until MASTER_DELAY...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +--source include/show_delayed_slave_state.inc + +--echo # wait for first query to execute +--sync_with_master + +--echo # sleep 1*T +--sleep $time1 + +--echo # Expect second query executed and status is executing third query (i.e., 'User sleep') +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +--source include/show_delayed_slave_state.inc + +--echo # sleep 2*T +--sleep $time2 + +--echo # Expect query executed and status is 'Has read all relay log...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +--source include/show_delayed_slave_state.inc + + +--echo ==== Seconds_Behind_Master ==== + +--echo # Bring slave to sync. +--source include/stop_slave.inc +eval CHANGE MASTER TO MASTER_DELAY = 0; +--source include/start_slave.inc + +--connection master +INSERT INTO t1(a) VALUES ('Syncing slave'); +--sync_slave_with_master + +--source include/stop_slave.inc +--echo # CHANGE MASTER TO MASTER_DELAY = 2*T +--disable_query_log +eval CHANGE MASTER TO MASTER_DELAY = $time2; +--enable_query_log +--source include/start_slave.inc + +--connection master +INSERT INTO t1(a) VALUES (delay_on_slave(1)); +--save_master_pos +--connection slave + +--echo # sleep 1*T +--sleep $time1 + +if ($bug_53167_is_fixed) { + +--let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1) +if (`SELECT $seconds_behind_master <= 0 OR $seconds_behind_master >= $time2`) { + --echo Seconds_Behind_Master was $seconds_behind_master. Expected that 0 < Seconds_Behind_Master < SQL_Delay = $time2 + --source include/show_rpl_debug_info.inc + --die Seconds_Behind_Master was wrong +} + +} + +--echo # sleep 1*T +--sleep $time1 + +--let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1) +if (`SELECT $seconds_behind_master < $time2`) { + --echo Seconds_Behind_Master was $seconds_behind_master. Expected it to be >= SQL_Delay = $time2 + --source include/show_rpl_debug_info.inc + --die Seconds_Behind_Master was < SQL_Delay +} + +--sync_with_master + + +--echo ==== STOP SLAVE and START SLAVE ==== + +# Set up a longer delay. +--source include/stop_slave.inc + +--echo # CHANGE MASTER TO MASTER_DELAY = 3*T +--disable_query_log +eval CHANGE MASTER TO MASTER_DELAY = $time3; +--enable_query_log + +--source include/start_slave.inc + +--echo # Checking that delay is what we set it to +--let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) +if (`SELECT $delay != $time3`) { + --echo Delay is wrong! Expected $time2, got $delay + --source include/show_rpl_debug_info.inc + --die wrong delay +} + +--echo [on master] +--connection master +INSERT INTO t1(a) VALUES ('stop slave and start slave'); + +--echo [on slave] +--connection slave +--echo # sleep 1*T +--sleep $time1 +SET @before_stop_slave= UNIX_TIMESTAMP(); +--source include/stop_slave.inc +if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`) +{ + --source include/show_rpl_debug_info.inc + --die STOP SLAVE did not finish in time +} +--echo # STOP SLAVE finished in time. + +--echo # Expect query not executed and status is '' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +--source include/show_delayed_slave_state.inc + +--source include/start_slave.inc +if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`) +{ + --source include/show_rpl_debug_info.inc + --die START SLAVE did not finish in time +} +--echo # START SLAVE finished in time. + +--source extra/rpl_tests/delayed_slave_wait_on_query.inc + + +--echo ==== Change back to no delay ==== + +--echo [on slave] +--connection slave +--source include/stop_slave.inc +eval CHANGE MASTER TO MASTER_DELAY = 0; + +--echo # Expect delay is 0. +--let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) +--echo SQL_Delay='$delay' + +--source include/start_slave.inc + +--echo [on master] +--connection master +INSERT INTO t1(a) VALUES ('change back to no delay'); + +--echo [on slave] +--source include/sync_slave_io_with_master.inc +--echo # sleep 1*T +--sleep $time1 + +--echo # Expect query executed and status is 'Has read all relay log...' +SELECT * FROM t1 ORDER BY b DESC LIMIT 1; +--source include/show_delayed_slave_state.inc + + +--echo ==== Reset delay with RESET SLAVE ==== + +--source include/stop_slave.inc +CHANGE MASTER TO MASTER_DELAY = 71; +--source include/start_slave.inc + +--echo # Expect delay is 71 +--let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) +--echo SQL_Delay='$delay' + +--source include/stop_slave.inc +RESET SLAVE; +--echo [on master] +--connection master +RESET MASTER; +--echo [on slave] +--connection slave +--source include/start_slave.inc + +--echo # Expect delay is 0 +--let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) +--echo SQL_Delay='$delay' + + +--echo ==== Set a bad value for the delay ==== + +--source include/stop_slave.inc + +--echo # Expect error for setting negative delay +--error ER_PARSE_ERROR +CHANGE MASTER TO MASTER_DELAY = -1; + +--echo # Expect that it's ok to set delay of 2^31-1 +CHANGE MASTER TO MASTER_DELAY = 2147483647; +--echo # Expect error for setting delay between 2^31 and 2^32-1 +--error ER_MASTER_DELAY_VALUE_OUT_OF_RANGE +CHANGE MASTER TO MASTER_DELAY = 2147483648; + +--echo # Expect error for setting delay to nonsense +--error ER_PARSE_ERROR +CHANGE MASTER TO MASTER_DELAY = blah; + +# todo: CHANGE MASTER TO MASTER_DELAY = 999999999999999999999999999 +# should give error + +CHANGE MASTER TO MASTER_DELAY = 0; +--source include/start_slave.inc + + +--echo ==== Clean up ==== + +--echo [on master] +--connection master +DROP TABLE t1; +DROP FUNCTION delay_on_slave; + +--echo [on slave] +--sync_slave_with_master + +--source include/rpl_end.inc diff --git a/sql/lex.h b/sql/lex.h index 85bd20a5f37..430e966eb40 100644 --- a/sql/lex.h +++ b/sql/lex.h @@ -339,6 +339,7 @@ static SYMBOL symbols[] = { { "LOW_PRIORITY", SYM(LOW_PRIORITY)}, { "MASTER", SYM(MASTER_SYM)}, { "MASTER_CONNECT_RETRY", SYM(MASTER_CONNECT_RETRY_SYM)}, + { "MASTER_DELAY", SYM(MASTER_DELAY_SYM)}, { "MASTER_GTID_POS", SYM(MASTER_GTID_POS_SYM)}, { "MASTER_HOST", SYM(MASTER_HOST_SYM)}, { "MASTER_LOG_FILE", SYM(MASTER_LOG_FILE_SYM)}, diff --git a/sql/log.cc b/sql/log.cc index be24bcd718a..e3d42a4547e 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -4292,6 +4292,10 @@ void MYSQL_BIN_LOG::wait_for_last_checkpoint_event() relay log. IMPLEMENTATION + + - You must hold rli->data_lock before calling this function, since + it writes group_relay_log_pos and similar fields of + Relay_log_info. - Protects index file with LOCK_index - Delete relevant relay log files - Copy all file names after these ones to the front of the index file @@ -4305,7 +4309,7 @@ void MYSQL_BIN_LOG::wait_for_last_checkpoint_event() read by the SQL slave thread are deleted). @note - - This is only called from the slave-execute thread when it has read + - This is only called from the slave SQL thread when it has read all commands from a relay log and want to switch to a new relay log. - When this happens, we can be in an active transaction as a transaction can span over two relay logs @@ -4336,6 +4340,8 @@ int MYSQL_BIN_LOG::purge_first_log(Relay_log_info* rli, bool included) DBUG_ASSERT(rli->slave_running == MYSQL_SLAVE_RUN_NOT_CONNECT); DBUG_ASSERT(!strcmp(rli->linfo.log_file_name,rli->event_relay_log_name)); + mysql_mutex_assert_owner(&rli->data_lock); + mysql_mutex_lock(&LOCK_index); ir= rli->inuse_relaylog_list; diff --git a/sql/log_event.cc b/sql/log_event.cc index afa58afc21d..bd8ae984c2d 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -966,6 +966,7 @@ int Log_event::do_update_pos(rpl_group_info *rgi) Relay_log_info *rli= rgi->rli; DBUG_ENTER("Log_event::do_update_pos"); + DBUG_ASSERT(!rli->belongs_to_client()); /* rli is null when (as far as I (Guilhem) know) the caller is Load_log_event::do_apply_event *and* that one is called from @@ -6400,6 +6401,9 @@ bool Rotate_log_event::write() in a A -> B -> A setup. The NOTES below is a wrong comment which will disappear when 4.1 is merged. + This must only be called from the Slave SQL thread, since it calls + flush_relay_log_info(). + @retval 0 ok */ @@ -8222,6 +8226,9 @@ void Stop_log_event::print(FILE* file, PRINT_EVENT_INFO* print_event_info) were we must do this cleaning is in Start_log_event_v3::do_apply_event(), not here. Because if we come here, the master was sane. + + This must only be called from the Slave SQL thread, since it calls + flush_relay_log_info(). */ int Stop_log_event::do_update_pos(rpl_group_info *rgi) diff --git a/sql/rpl_mi.cc b/sql/rpl_mi.cc index 6048d26998b..867ebc7167a 100644 --- a/sql/rpl_mi.cc +++ b/sql/rpl_mi.cc @@ -18,7 +18,7 @@ #include "sql_priv.h" #include #include "rpl_mi.h" -#include "slave.h" // SLAVE_MAX_HEARTBEAT_PERIOD +#include "slave.h" #include "strfunc.h" #include "sql_repl.h" diff --git a/sql/rpl_rli.cc b/sql/rpl_rli.cc index 31dd24a038d..a7d8f843688 100644 --- a/sql/rpl_rli.cc +++ b/sql/rpl_rli.cc @@ -28,6 +28,7 @@ #include "rpl_utility.h" #include "transaction.h" #include "sql_parse.h" // end_trans, ROLLBACK +#include "slave.h" #include #include @@ -41,30 +42,24 @@ rpl_slave_state *rpl_global_gtid_slave_state; /* Object used for MASTER_GTID_WAIT(). */ gtid_waiting rpl_global_gtid_waiting; - -// Defined in slave.cc -int init_intvar_from_file(int* var, IO_CACHE* f, int default_val); -int init_strvar_from_file(char *var, int max_size, IO_CACHE *f, - const char *default_val); +const char *const Relay_log_info::state_delaying_string = "Waiting until MASTER_DELAY seconds after master executed event"; Relay_log_info::Relay_log_info(bool is_slave_recovery) :Slave_reporting_capability("SQL"), - no_storage(FALSE), replicate_same_server_id(::replicate_same_server_id), + replicate_same_server_id(::replicate_same_server_id), info_fd(-1), cur_log_fd(-1), relay_log(&sync_relaylog_period), sync_counter(0), is_relay_log_recovery(is_slave_recovery), save_temporary_tables(0), mi(0), inuse_relaylog_list(0), last_inuse_relaylog(0), cur_log_old_open_count(0), group_relay_log_pos(0), event_relay_log_pos(0), -#if HAVE_valgrind - is_fake(FALSE), -#endif group_master_log_pos(0), log_space_total(0), ignore_log_space_limit(0), last_master_timestamp(0), sql_thread_caught_up(true), slave_skip_counter(0), abort_pos_wait(0), slave_run_id(0), sql_driver_thd(), gtid_skip_flag(GTID_SKIP_NOT), inited(0), abort_slave(0), stop_for_until(0), slave_running(MYSQL_SLAVE_NOT_RUN), until_condition(UNTIL_NONE), until_log_pos(0), retried_trans(0), executed_entries(0), + sql_delay(0), sql_delay_end(0), m_flags(0) { DBUG_ENTER("Relay_log_info::Relay_log_info"); @@ -115,39 +110,55 @@ Relay_log_info::~Relay_log_info() } +/** + Wrapper around Relay_log_info::init(const char *). + + @todo Remove this and replace all calls to it by calls to + Relay_log_info::init(const char *). /SVEN +*/ int init_relay_log_info(Relay_log_info* rli, const char* info_fname) +{ + return rli->init(info_fname); +} + + +/** + Read the relay_log.info file. + + @param info_fname The name of the file to read from. + @retval 0 success + @retval 1 failure +*/ +int Relay_log_info::init(const char* info_fname) { char fname[FN_REFLEN+128]; - int info_fd; const char* msg = 0; int error = 0; DBUG_ENTER("init_relay_log_info"); - DBUG_ASSERT(!rli->no_storage); // Don't init if there is no storage - if (rli->inited) // Set if this function called + if (inited) // Set if this function called DBUG_RETURN(0); fn_format(fname, info_fname, mysql_data_home, "", 4+32); - mysql_mutex_lock(&rli->data_lock); - info_fd = rli->info_fd; - rli->cur_log_fd = -1; - rli->slave_skip_counter=0; - rli->abort_pos_wait=0; - rli->log_space_limit= relay_log_space_limit; - rli->log_space_total= 0; + mysql_mutex_lock(&data_lock); + cur_log_fd = -1; + slave_skip_counter=0; + abort_pos_wait=0; + log_space_limit= relay_log_space_limit; + log_space_total= 0; char pattern[FN_REFLEN]; (void) my_realpath(pattern, slave_load_tmpdir, 0); if (fn_format(pattern, PREFIX_SQL_LOAD, pattern, "", MY_SAFE_PATH | MY_RETURN_REAL_PATH) == NullS) { - mysql_mutex_unlock(&rli->data_lock); + mysql_mutex_unlock(&data_lock); sql_print_error("Unable to use slave's temporary directory %s", slave_load_tmpdir); DBUG_RETURN(1); } - unpack_filename(rli->slave_patternload_file, pattern); - rli->slave_patternload_file_size= strlen(rli->slave_patternload_file); + unpack_filename(slave_patternload_file, pattern); + slave_patternload_file_size= strlen(slave_patternload_file); /* The relay log will now be opened, as a SEQ_READ_APPEND IO_CACHE. @@ -161,7 +172,7 @@ int init_relay_log_info(Relay_log_info* rli, if (opt_relay_logname && opt_relay_logname[strlen(opt_relay_logname) - 1] == FN_LIBCHAR) { - mysql_mutex_unlock(&rli->data_lock); + mysql_mutex_unlock(&data_lock); sql_print_error("Path '%s' is a directory name, please specify \ a file name for --relay-log option", opt_relay_logname); DBUG_RETURN(1); @@ -173,7 +184,7 @@ a file name for --relay-log option", opt_relay_logname); opt_relaylog_index_name[strlen(opt_relaylog_index_name) - 1] == FN_LIBCHAR) { - mysql_mutex_unlock(&rli->data_lock); + mysql_mutex_unlock(&data_lock); sql_print_error("Path '%s' is a directory name, please specify \ a file name for --relay-log-index option", opt_relaylog_index_name); DBUG_RETURN(1); @@ -182,7 +193,7 @@ a file name for --relay-log-index option", opt_relaylog_index_name); char buf[FN_REFLEN]; const char *ln; static bool name_warning_sent= 0; - ln= rli->relay_log.generate_name(opt_relay_logname, "-relay-bin", + ln= relay_log.generate_name(opt_relay_logname, "-relay-bin", 1, buf); /* We send the warning only at startup, not after every RESET SLAVE */ if (!opt_relay_logname && !opt_relaylog_index_name && !name_warning_sent && @@ -205,7 +216,6 @@ a file name for --relay-log-index option", opt_relaylog_index_name); } /* For multimaster, add connection name to relay log filenames */ - Master_info* mi= rli->mi; char buf_relay_logname[FN_REFLEN], buf_relaylog_index_name_buff[FN_REFLEN]; char *buf_relaylog_index_name= opt_relaylog_index_name; @@ -227,11 +237,11 @@ a file name for --relay-log-index option", opt_relaylog_index_name); note, that if open() fails, we'll still have index file open but a destructor will take care of that */ - if (rli->relay_log.open_index_file(buf_relaylog_index_name, ln, TRUE) || - rli->relay_log.open(ln, LOG_BIN, 0, 0, SEQ_READ_APPEND, - mi->rli.max_relay_log_size, 1, TRUE)) + if (relay_log.open_index_file(buf_relaylog_index_name, ln, TRUE) || + relay_log.open(ln, LOG_BIN, 0, 0, SEQ_READ_APPEND, + max_relay_log_size, 1, TRUE)) { - mysql_mutex_unlock(&rli->data_lock); + mysql_mutex_unlock(&data_lock); sql_print_error("Failed when trying to open logs for '%s' in init_relay_log_info(). Error: %M", ln, my_errno); DBUG_RETURN(1); } @@ -254,7 +264,7 @@ file '%s', errno %d)", fname, my_errno); msg= current_thd->get_stmt_da()->message(); goto err; } - if (init_io_cache(&rli->info_file, info_fd, IO_SIZE*2, READ_CACHE, 0L,0, + if (init_io_cache(&info_file, info_fd, IO_SIZE*2, READ_CACHE, 0L,0, MYF(MY_WME))) { sql_print_error("Failed to create a cache on relay log info file '%s'", @@ -264,20 +274,19 @@ file '%s', errno %d)", fname, my_errno); } /* Init relay log with first entry in the relay index file */ - if (init_relay_log_pos(rli,NullS,BIN_LOG_HEADER_SIZE,0 /* no data lock */, + if (init_relay_log_pos(this,NullS,BIN_LOG_HEADER_SIZE,0 /* no data lock */, &msg, 0)) { sql_print_error("Failed to open the relay log 'FIRST' (relay_log_pos 4)"); goto err; } - rli->group_master_log_name[0]= 0; - rli->group_master_log_pos= 0; - rli->info_fd= info_fd; + group_master_log_name[0]= 0; + group_master_log_pos= 0; } else // file exists { if (info_fd >= 0) - reinit_io_cache(&rli->info_file, READ_CACHE, 0L,0,0); + reinit_io_cache(&info_file, READ_CACHE, 0L,0,0); else { int error=0; @@ -289,7 +298,7 @@ Failed to open the existing relay log info file '%s' (errno %d)", fname, my_errno); error= 1; } - else if (init_io_cache(&rli->info_file, info_fd, + else if (init_io_cache(&info_file, info_fd, IO_SIZE*2, READ_CACHE, 0L, 0, MYF(MY_WME))) { sql_print_error("Failed to create a cache on relay log info file '%s'", @@ -300,24 +309,15 @@ Failed to open the existing relay log info file '%s' (errno %d)", { if (info_fd >= 0) mysql_file_close(info_fd, MYF(0)); - rli->info_fd= -1; - rli->relay_log.close(LOG_CLOSE_INDEX | LOG_CLOSE_STOP_EVENT); - mysql_mutex_unlock(&rli->data_lock); + info_fd= -1; + relay_log.close(LOG_CLOSE_INDEX | LOG_CLOSE_STOP_EVENT); + mysql_mutex_unlock(&data_lock); DBUG_RETURN(1); } } - rli->info_fd = info_fd; int relay_log_pos, master_log_pos, lines; char *first_non_digit; - /* - In MySQL 5.6, there is a MASTER_DELAY option to CHANGE MASTER. This is - not yet merged into MariaDB (as of 10.0.13). However, we detect the - presense of the new option in relay-log.info, as a placeholder for - possible later merge of the feature, and to maintain file format - compatibility with MySQL 5.6+. - */ - int dummy_sql_delay; /* Starting from MySQL 5.6.x, relay-log.info has a new format. @@ -342,25 +342,25 @@ Failed to open the existing relay log info file '%s' (errno %d)", it is line count and not binlog name (new format) it will be overwritten by the second row later. */ - if (init_strvar_from_file(rli->group_relay_log_name, - sizeof(rli->group_relay_log_name), - &rli->info_file, "")) + if (init_strvar_from_file(group_relay_log_name, + sizeof(group_relay_log_name), + &info_file, "")) { msg="Error reading slave log configuration"; goto err; } - lines= strtoul(rli->group_relay_log_name, &first_non_digit, 10); + lines= strtoul(group_relay_log_name, &first_non_digit, 10); - if (rli->group_relay_log_name[0] != '\0' && + if (group_relay_log_name[0] != '\0' && *first_non_digit == '\0' && lines >= LINES_IN_RELAY_LOG_INFO_WITH_DELAY) { DBUG_PRINT("info", ("relay_log_info file is in new format.")); /* Seems to be new format => read relay log name from next line */ - if (init_strvar_from_file(rli->group_relay_log_name, - sizeof(rli->group_relay_log_name), - &rli->info_file, "")) + if (init_strvar_from_file(group_relay_log_name, + sizeof(group_relay_log_name), + &info_file, "")) { msg="Error reading slave log configuration"; goto err; @@ -370,70 +370,70 @@ Failed to open the existing relay log info file '%s' (errno %d)", DBUG_PRINT("info", ("relay_log_info file is in old format.")); if (init_intvar_from_file(&relay_log_pos, - &rli->info_file, BIN_LOG_HEADER_SIZE) || - init_strvar_from_file(rli->group_master_log_name, - sizeof(rli->group_master_log_name), - &rli->info_file, "") || - init_intvar_from_file(&master_log_pos, &rli->info_file, 0) || + &info_file, BIN_LOG_HEADER_SIZE) || + init_strvar_from_file(group_master_log_name, + sizeof(group_master_log_name), + &info_file, "") || + init_intvar_from_file(&master_log_pos, &info_file, 0) || (lines >= LINES_IN_RELAY_LOG_INFO_WITH_DELAY && - init_intvar_from_file(&dummy_sql_delay, &rli->info_file, 0))) + init_intvar_from_file(&sql_delay, &info_file, 0))) { msg="Error reading slave log configuration"; goto err; } - strmake_buf(rli->event_relay_log_name,rli->group_relay_log_name); - rli->group_relay_log_pos= rli->event_relay_log_pos= relay_log_pos; - rli->group_master_log_pos= master_log_pos; + strmake_buf(event_relay_log_name,group_relay_log_name); + group_relay_log_pos= event_relay_log_pos= relay_log_pos; + group_master_log_pos= master_log_pos; - if (rli->is_relay_log_recovery && init_recovery(rli->mi, &msg)) + if (is_relay_log_recovery && init_recovery(mi, &msg)) goto err; - rli->relay_log_state.load(rpl_global_gtid_slave_state); - if (init_relay_log_pos(rli, - rli->group_relay_log_name, - rli->group_relay_log_pos, + relay_log_state.load(rpl_global_gtid_slave_state); + if (init_relay_log_pos(this, + group_relay_log_name, + group_relay_log_pos, 0 /* no data lock*/, &msg, 0)) { sql_print_error("Failed to open the relay log '%s' (relay_log_pos %llu)", - rli->group_relay_log_name, rli->group_relay_log_pos); + group_relay_log_name, group_relay_log_pos); goto err; } } - DBUG_PRINT("info", ("my_b_tell(rli->cur_log)=%llu rli->event_relay_log_pos=%llu", - my_b_tell(rli->cur_log), rli->event_relay_log_pos)); - DBUG_ASSERT(rli->event_relay_log_pos >= BIN_LOG_HEADER_SIZE); - DBUG_ASSERT(my_b_tell(rli->cur_log) == rli->event_relay_log_pos); + DBUG_PRINT("info", ("my_b_tell(cur_log)=%llu event_relay_log_pos=%llu", + my_b_tell(cur_log), event_relay_log_pos)); + DBUG_ASSERT(event_relay_log_pos >= BIN_LOG_HEADER_SIZE); + DBUG_ASSERT(my_b_tell(cur_log) == event_relay_log_pos); /* Now change the cache from READ to WRITE - must do this before flush_relay_log_info */ - reinit_io_cache(&rli->info_file, WRITE_CACHE,0L,0,1); - if ((error= flush_relay_log_info(rli))) + reinit_io_cache(&info_file, WRITE_CACHE,0L,0,1); + if ((error= flush_relay_log_info(this))) { msg= "Failed to flush relay log info file"; goto err; } - if (count_relay_log_space(rli)) + if (count_relay_log_space(this)) { msg="Error counting relay log space"; goto err; } - rli->inited= 1; - mysql_mutex_unlock(&rli->data_lock); + inited= 1; + mysql_mutex_unlock(&data_lock); DBUG_RETURN(error); err: sql_print_error("%s", msg); - end_io_cache(&rli->info_file); + end_io_cache(&info_file); if (info_fd >= 0) mysql_file_close(info_fd, MYF(0)); - rli->info_fd= -1; - rli->relay_log.close(LOG_CLOSE_INDEX | LOG_CLOSE_STOP_EVENT); - mysql_mutex_unlock(&rli->data_lock); + info_fd= -1; + relay_log.close(LOG_CLOSE_INDEX | LOG_CLOSE_STOP_EVENT); + mysql_mutex_unlock(&data_lock); DBUG_RETURN(1); } @@ -750,6 +750,8 @@ err: if (!rli->relay_log.description_event_for_exec->is_valid() && !*errmsg) *errmsg= "Invalid Format_description log event; could be out of memory"; + DBUG_PRINT("info", ("Returning %d from init_relay_log_pos", (*errmsg)?1:0)); + DBUG_RETURN ((*errmsg) ? 1 : 0); } @@ -967,8 +969,11 @@ void Relay_log_info::inc_group_relay_log_pos(ulonglong log_pos, { DBUG_ENTER("Relay_log_info::inc_group_relay_log_pos"); - if (!skip_lock) + if (skip_lock) + mysql_mutex_assert_owner(&data_lock); + else mysql_mutex_lock(&data_lock); + rgi->inc_event_relay_log_pos(); DBUG_PRINT("info", ("log_pos: %lu group_master_log_pos: %lu", (long) log_pos, (long) group_master_log_pos)); @@ -1294,6 +1299,7 @@ void Relay_log_info::stmt_done(my_off_t event_master_log_pos, THD *thd, { DBUG_ENTER("Relay_log_info::stmt_done"); + DBUG_ASSERT(!belongs_to_client()); DBUG_ASSERT(rgi->rli == this); /* If in a transaction, and if the slave supports transactions, just diff --git a/sql/rpl_rli.h b/sql/rpl_rli.h index 96c3e7c3fac..0c8f16a0d16 100644 --- a/sql/rpl_rli.h +++ b/sql/rpl_rli.h @@ -29,11 +29,6 @@ class Master_info; class Rpl_filter; -enum { - LINES_IN_RELAY_LOG_INFO_WITH_DELAY= 5 -}; - - /**************************************************************************** Replication SQL Thread @@ -78,11 +73,17 @@ public: }; /* - If flag set, then rli does not store its state in any info file. - This is the case only when we execute BINLOG SQL commands inside - a client, non-replication thread. + The SQL thread owns one Relay_log_info, and each client that has + executed a BINLOG statement owns one Relay_log_info. This function + returns zero for the Relay_log_info object that belongs to the SQL + thread and nonzero for Relay_log_info objects that belong to + clients. */ - bool no_storage; + inline bool belongs_to_client() + { + DBUG_ASSERT(sql_driver_thd); + return !sql_driver_thd->slave_thread; + } /* If true, events with the same server id should be replicated. This @@ -194,6 +195,11 @@ public: relay log and finishing (commiting) on another relay log. Case which can happen when, for example, the relay log gets rotated because of max_binlog_size. + + Note: group_relay_log_name, group_relay_log_pos must only be + written from the thread owning the Relay_log_info (SQL thread if + !belongs_to_client(); client thread executing BINLOG statement if + belongs_to_client()). */ char group_relay_log_name[FN_REFLEN]; ulonglong group_relay_log_pos; @@ -205,16 +211,17 @@ public: */ char future_event_master_log_name[FN_REFLEN]; -#ifdef HAVE_valgrind - bool is_fake; /* Mark that this is a fake relay log info structure */ -#endif - /* Original log name and position of the group we're currently executing (whose coordinates are group_relay_log_name/pos in the relay log) in the master's binlog. These concern the *group*, because in the master's binlog the log_pos that comes with each event is the position of the beginning of the group. + + Note: group_master_log_name, group_master_log_pos must only be + written from the thread owning the Relay_log_info (SQL thread if + !belongs_to_client(); client thread executing BINLOG statement if + belongs_to_client()). */ char group_master_log_name[FN_REFLEN]; volatile my_off_t group_master_log_pos; @@ -244,6 +251,15 @@ public: bool sql_thread_caught_up; void clear_until_condition(); + /** + Reset the delay. + This is used by RESET SLAVE to clear the delay. + */ + void clear_sql_delay() + { + sql_delay= 0; + } + /* Needed for problems when slave stops and we want to restart it @@ -474,8 +490,72 @@ public: m_flags&= ~flag; } + /** + Text used in THD::proc_info when the slave SQL thread is delaying. + */ + static const char *const state_delaying_string; + + bool flush(); + + /** + Reads the relay_log.info file. + */ + int init(const char* info_filename); + + /** + Indicate that a delay starts. + + This does not actually sleep; it only sets the state of this + Relay_log_info object to delaying so that the correct state can be + reported by SHOW SLAVE STATUS and SHOW PROCESSLIST. + + Requires rli->data_lock. + + @param delay_end The time when the delay shall end. + */ + void start_sql_delay(time_t delay_end) + { + mysql_mutex_assert_owner(&data_lock); + sql_delay_end= delay_end; + thd_proc_info(sql_driver_thd, state_delaying_string); + } + + int32 get_sql_delay() { return sql_delay; } + void set_sql_delay(time_t _sql_delay) { sql_delay= _sql_delay; } + time_t get_sql_delay_end() { return sql_delay_end; } + private: + + /** + Delay slave SQL thread by this amount, compared to master (in + seconds). This is set with CHANGE MASTER TO MASTER_DELAY=X. + + Guarded by data_lock. Initialized by the client thread executing + START SLAVE. Written by client threads executing CHANGE MASTER TO + MASTER_DELAY=X. Read by SQL thread and by client threads + executing SHOW SLAVE STATUS. Note: must not be written while the + slave SQL thread is running, since the SQL thread reads it without + a lock when executing flush_relay_log_info(). + */ + int sql_delay; + + /** + During a delay, specifies the point in time when the delay ends. + + This is used for the SQL_Remaining_Delay column in SHOW SLAVE STATUS. + + Guarded by data_lock. Written by the sql thread. Read by client + threads executing SHOW SLAVE STATUS. + */ + time_t sql_delay_end; + + /* + Before the MASTER_DELAY parameter was added (WL#344), + relay_log.info had 4 lines. Now it has 5 lines. + */ + static const int LINES_IN_RELAY_LOG_INFO_WITH_DELAY= 5; + /* Holds the state of the data in the relay log. We need this to ensure that we are not in the middle of a @@ -874,7 +954,14 @@ public: }; -// Defined in rpl_rli.cc +/** + Reads the relay_log.info file. + + @todo This is a wrapper around Relay_log_info::init(). It's only + kept for historical reasons. It would be good if we removed this + function and replaced all calls to it by calls to + Relay_log_info::init(). /SVEN +*/ int init_relay_log_info(Relay_log_info* rli, const char* info_fname); diff --git a/sql/slave.cc b/sql/slave.cc index a55d26b1aa0..d1d9abd4027 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -1634,8 +1634,10 @@ static int get_master_version_and_clock(MYSQL* mysql, Master_info* mi) (master_res= mysql_store_result(mysql)) && (master_row= mysql_fetch_row(master_res))) { + mysql_mutex_lock(&mi->data_lock); mi->clock_diff_with_master= (long) (time((time_t*) 0) - strtoul(master_row[0], 0, 10)); + mysql_mutex_unlock(&mi->data_lock); } else if (check_io_slave_killed(mi, NULL)) goto slave_killed_err; @@ -1647,7 +1649,9 @@ static int get_master_version_and_clock(MYSQL* mysql, Master_info* mi) } else { + mysql_mutex_lock(&mi->data_lock); mi->clock_diff_with_master= 0; /* The "most sensible" value */ + mysql_mutex_unlock(&mi->data_lock); sql_print_warning("\"SELECT UNIX_TIMESTAMP()\" failed on master, " "do not trust column Seconds_Behind_Master of SHOW " "SLAVE STATUS. Error: %s (%d)", @@ -2797,6 +2801,15 @@ void show_master_info_get_fields(THD *thd, List *field_list, Item_empty_string(thd, "Parallel_Mode", sizeof("conservative")-1), mem_root); + field_list->push_back(new (mem_root) + Item_return_int(thd, "SQL_Delay", 10, + MYSQL_TYPE_LONG)); + field_list->push_back(new (mem_root) + Item_return_int(thd, "SQL_Remaining_Delay", 8, + MYSQL_TYPE_LONG)); + field_list->push_back(new (mem_root) + Item_empty_string(thd, "Slave_SQL_Running_State", + 20)); if (full) { field_list->push_back(new (mem_root) @@ -2986,6 +2999,7 @@ static bool send_show_master_info_data(THD *thd, Master_info *mi, bool full, prot_store_ids(thd, &mi->ignore_server_ids); // Master_Server_id protocol->store((uint32) mi->master_id); + // SQL_Delay // Master_Ssl_Crl protocol->store(mi->ssl_ca, &my_charset_bin); // Master_Ssl_Crlpath @@ -3008,6 +3022,22 @@ static bool send_show_master_info_data(THD *thd, Master_info *mi, bool full, protocol->store(mode_name, strlen(mode_name), &my_charset_bin); } + protocol->store((uint32) mi->rli.get_sql_delay()); + // SQL_Remaining_Delay + // THD::proc_info is not protected by any lock, so we read it once + // to ensure that we use the same value throughout this function. + const char *slave_sql_running_state= + mi->rli.sql_driver_thd ? mi->rli.sql_driver_thd->proc_info : ""; + if (slave_sql_running_state == Relay_log_info::state_delaying_string) + { + time_t t= my_time(0), sql_delay_end= mi->rli.get_sql_delay_end(); + protocol->store((uint32)(t < sql_delay_end ? sql_delay_end - t : 0)); + } + else + protocol->store_null(); + // Slave_SQL_Running_State + protocol->store(slave_sql_running_state, &my_charset_bin); + if (full) { protocol->store((uint32) mi->rli.retried_trans); @@ -3377,6 +3407,69 @@ has_temporary_error(THD *thd) } +/** + If this is a lagging slave (specified with CHANGE MASTER TO MASTER_DELAY = X), delays accordingly. Also unlocks rli->data_lock. + + Design note: this is the place to unlock rli->data_lock here since + it should be held when reading delay info from rli, but it should + not be held while sleeping. + + @param ev Event that is about to be executed. + + @param thd The sql thread's THD object. + + @param rli The sql thread's Relay_log_info structure. +*/ +static void sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) +{ + Relay_log_info* rli= rgi->rli; + long sql_delay= rli->get_sql_delay(); + + DBUG_ENTER("sql_delay_event"); + mysql_mutex_assert_owner(&rli->data_lock); + DBUG_ASSERT(!rli->belongs_to_client()); + + int type= ev->get_type_code(); + if (sql_delay && type != ROTATE_EVENT && + type != FORMAT_DESCRIPTION_EVENT && type != START_EVENT_V3) + { + // The time when we should execute the event. + time_t sql_delay_end= + ev->when + rli->mi->clock_diff_with_master + sql_delay; + // The current time. + time_t now= my_time(0); + // The time we will have to sleep before executing the event. + unsigned long nap_time= 0; + if (sql_delay_end > now) + nap_time= sql_delay_end - now; + + DBUG_PRINT("info", ("sql_delay= %lu " + "ev->when= %lu " + "rli->mi->clock_diff_with_master= %lu " + "now= %ld " + "sql_delay_end= %lu " + "nap_time= %ld", + sql_delay, (long)ev->when, + rli->mi->clock_diff_with_master, + (long)now, sql_delay_end, (long)nap_time)); + + if (sql_delay_end > now) + { + DBUG_PRINT("info", ("delaying replication event %lu secs", + nap_time)); + rli->start_sql_delay(sql_delay_end); + mysql_mutex_unlock(&rli->data_lock); + slave_sleep(thd, nap_time, sql_slave_killed, rgi); + DBUG_VOID_RETURN; + } + } + + mysql_mutex_unlock(&rli->data_lock); + + DBUG_VOID_RETURN; +} + + /* First half of apply_event_and_update_pos(), see below. Setup some THD variables for applying the event. @@ -3500,16 +3593,16 @@ apply_event_and_update_pos_apply(Log_event* ev, THD* thd, rpl_group_info *rgi, if (exec_res == 0) { int error= ev->update_pos(rgi); -#ifdef HAVE_valgrind - if (!rli->is_fake) -#endif + #ifndef DBUG_OFF + DBUG_PRINT("info", ("update_pos error = %d", error)); + if (!rli->belongs_to_client()) { - DBUG_PRINT("info", ("update_pos error = %d", error)); DBUG_PRINT("info", ("group %llu %s", rli->group_relay_log_pos, rli->group_relay_log_name)); DBUG_PRINT("info", ("event %llu %s", rli->event_relay_log_pos, rli->event_relay_log_name)); } +#endif /* The update should not fail, so print an error message and return an error code. @@ -3544,21 +3637,39 @@ apply_event_and_update_pos_apply(Log_event* ev, THD* thd, rpl_group_info *rgi, /** Applies the given event and advances the relay log position. - In essence, this function does: + This is needed by the sql thread to execute events from the binlog, + and by clients executing BINLOG statements. Conceptually, this + function does: @code ev->apply_event(rli); ev->update_pos(rli); @endcode - But it also does some maintainance, such as skipping events if - needed and reporting errors. + It also does the following maintainance: - If the @c skip flag is set, then it is tested whether the event - should be skipped, by looking at the slave_skip_counter and the - server id. The skip flag should be set when calling this from a - replication thread but not set when executing an explicit BINLOG - statement. + - Initializes the thread's server_id and time; and the event's + thread. + + - If !rli->belongs_to_client() (i.e., if it belongs to the slave + sql thread instead of being used for executing BINLOG + statements), it does the following things: (1) skips events if it + is needed according to the server id or slave_skip_counter; (2) + unlocks rli->data_lock; (3) sleeps if required by 'CHANGE MASTER + TO MASTER_DELAY=X'; (4) maintains the running state of the sql + thread (rli->thread_state). + + - Reports errors as needed. + + @param ev The event to apply. + + @param thd The client thread that executes the event (i.e., the + slave sql thread if called from a replication slave, or the client + thread if called to execute a BINLOG statement). + + @param rli The relay log info (i.e., the slave's rli if called from + a replication slave, or the client's thd->rli_fake if called to + execute a BINLOG statement). @retval 0 OK. @@ -3581,7 +3692,15 @@ apply_event_and_update_pos(Log_event* ev, THD* thd, rpl_group_info *rgi) DBUG_ASSERT(rli->slave_skip_counter > 0); rli->slave_skip_counter--; } - mysql_mutex_unlock(&rli->data_lock); + + if (reason == Log_event::EVENT_SKIP_NOT) + { + // Sleeps if needed, and unlocks rli->data_lock. + sql_delay_event(ev, thd, rgi); + } + else + mysql_mutex_unlock(&rli->data_lock); + return apply_event_and_update_pos_apply(ev, thd, rgi, reason); } @@ -3603,6 +3722,10 @@ apply_event_and_update_pos_for_parallel(Log_event* ev, THD* thd, driver thread, so 23 should never see EVENT_SKIP_COUNT here. */ DBUG_ASSERT(reason != Log_event::EVENT_SKIP_COUNT); + /* + Calling sql_delay_event() was handled in the SQL driver thread when + doing parallel replication. + */ return apply_event_and_update_pos_apply(ev, thd, rgi, reason); } @@ -3682,7 +3805,8 @@ inline void update_state_of_relay_log(Relay_log_info *rli, Log_event *ev) /** - Top-level function for executing the next event from the relay log. + Top-level function for executing the next event in the relay log. + This is called from the SQL thread. This function reads the event from the relay log, executes it, and advances the relay log position. It also handles errors, etc. @@ -4229,8 +4353,10 @@ connected: };); #endif - // TODO: the assignment below should be under mutex (5.0) + mysql_mutex_lock(&mi->run_lock); mi->slave_running= MYSQL_SLAVE_RUN_CONNECT; + mysql_mutex_unlock(&mi->run_lock); + thd->slave_net = &mysql->net; THD_STAGE_INFO(thd, stage_checking_master_version); ret= get_master_version_and_clock(mysql, mi); @@ -6582,67 +6708,80 @@ MYSQL *rpl_connect_master(MYSQL *mysql) } #endif -/* - Store the file and position where the execute-slave thread are in the +/** + Store the file and position where the slave's SQL thread are in the relay log. - SYNOPSIS - flush_relay_log_info() - rli Relay log information + Notes: - NOTES - - As this is only called by the slave thread or on STOP SLAVE, with the - log_lock grabbed and the slave thread stopped, we don't need to have - a lock here. - - If there is an active transaction, then we don't update the position - in the relay log. This is to ensure that we re-execute statements - if we die in the middle of an transaction that was rolled back. - - As a transaction never spans binary logs, we don't have to handle the - case where we do a relay-log-rotation in the middle of the transaction. - If this would not be the case, we would have to ensure that we - don't delete the relay log file where the transaction started when - we switch to a new relay log file. + - This function should be called either from the slave SQL thread, + or when the slave thread is not running. (It reads the + group_{relay|master}_log_{pos|name} and delay fields in the rli + object. These may only be modified by the slave SQL thread or by + a client thread when the slave SQL thread is not running.) - TODO - - Change the log file information to a binary format to avoid calling - longlong2str. + - If there is an active transaction, then we do not update the + position in the relay log. This is to ensure that we re-execute + statements if we die in the middle of an transaction that was + rolled back. - RETURN VALUES - 0 ok - 1 write error + - As a transaction never spans binary logs, we don't have to handle + the case where we do a relay-log-rotation in the middle of the + transaction. If transactions could span several binlogs, we would + have to ensure that we do not delete the relay log file where the + transaction started before switching to a new relay log file. + + - Error can happen if writing to file fails or if flushing the file + fails. + + @param rli The object representing the Relay_log_info. + + @todo Change the log file information to a binary format to avoid + calling longlong2str. + + @todo Move the member function into rpl_rli.cc and get rid of the + global function. /SVEN + + @return 0 on success, 1 on error. */ - bool flush_relay_log_info(Relay_log_info* rli) +{ + return rli->flush(); +} + +bool Relay_log_info::flush() { bool error=0; - DBUG_ENTER("flush_relay_log_info"); - if (unlikely(rli->no_storage)) - DBUG_RETURN(0); - - IO_CACHE *file = &rli->info_file; - char buff[FN_REFLEN*2+22*2+4], *pos; + DBUG_ENTER("Relay_log_info::flush()"); + IO_CACHE *file = &info_file; + // 2*file name, 2*long long, 2*unsigned long, 6*'\n' + char buff[FN_REFLEN * 2 + 22 * 2 + 10 * 2 + 6], *pos; my_b_seek(file, 0L); - pos=strmov(buff, rli->group_relay_log_name); + pos= longlong10_to_str(LINES_IN_RELAY_LOG_INFO_WITH_DELAY, buff, 10); *pos++='\n'; - pos= longlong10_to_str(rli->group_relay_log_pos, pos, 10); + pos=strmov(pos, group_relay_log_name); *pos++='\n'; - pos=strmov(pos, rli->group_master_log_name); + pos=longlong10_to_str(group_relay_log_pos, pos, 10); *pos++='\n'; - pos=longlong10_to_str(rli->group_master_log_pos, pos, 10); + pos=strmov(pos, group_master_log_name); + *pos++='\n'; + pos=longlong10_to_str(group_master_log_pos, pos, 10); *pos='\n'; + pos= longlong10_to_str(sql_delay, pos, 10); + *pos= '\n'; if (my_b_write(file, (uchar*) buff, (size_t) (pos-buff)+1)) error=1; if (flush_io_cache(file)) error=1; if (sync_relayloginfo_period && !error && - ++(rli->sync_counter) >= sync_relayloginfo_period) + ++sync_counter >= sync_relayloginfo_period) { - if (my_sync(rli->info_fd, MYF(MY_WME))) + if (my_sync(info_fd, MYF(MY_WME))) error=1; - rli->sync_counter= 0; + sync_counter= 0; } /* Flushing the relay log is done by the slave I/O thread diff --git a/sql/slave.h b/sql/slave.h index a78ae4cff6f..d28048af8ea 100644 --- a/sql/slave.h +++ b/sql/slave.h @@ -17,6 +17,14 @@ #ifndef SLAVE_H #define SLAVE_H +/** + MASTER_DELAY can be at most (1 << 31) - 1. +*/ +#define MASTER_DELAY_MAX (0x7FFFFFFF) +#if INT_MAX < 0x7FFFFFFF +#error "don't support platforms where INT_MAX < 0x7FFFFFFF" +#endif + /** @defgroup Replication Replication @{ @@ -102,12 +110,14 @@ int init_dynarray_intvar_from_file(DYNAMIC_ARRAY* arr, IO_CACHE* f); In Master_info: run_lock, data_lock run_lock protects all information about the run state: slave_running, thd - and the existence of the I/O thread to stop/start it, you need this mutex). + and the existence of the I/O thread (to stop/start it, you need this mutex). data_lock protects some moving members of the struct: counters (log name, position) and relay log (MYSQL_BIN_LOG object). In Relay_log_info: run_lock, data_lock see Master_info + However, note that run_lock does not protect + Relay_log_info.run_state; that is protected by data_lock. Order of acquisition: if you want to have LOCK_active_mi and a run_lock, you must acquire LOCK_active_mi first. @@ -247,6 +257,12 @@ int apply_event_and_update_pos(Log_event* ev, THD* thd, int apply_event_and_update_pos_for_parallel(Log_event* ev, THD* thd, struct rpl_group_info *rgi); +int init_intvar_from_file(int* var, IO_CACHE* f, int default_val); +int init_floatvar_from_file(float* var, IO_CACHE* f, float default_val); +int init_strvar_from_file(char *var, int max_size, IO_CACHE *f, + const char *default_val); +int init_dynarray_intvar_from_file(DYNAMIC_ARRAY* arr, IO_CACHE* f); + pthread_handler_t handle_slave_io(void *arg); void slave_output_error_info(rpl_group_info *rgi, THD *thd); pthread_handler_t handle_slave_sql(void *arg); diff --git a/sql/sql_binlog.cc b/sql/sql_binlog.cc index f0465cdf5bf..a7beb42c315 100644 --- a/sql/sql_binlog.cc +++ b/sql/sql_binlog.cc @@ -17,18 +17,96 @@ #include #include "sql_priv.h" #include "sql_binlog.h" -#include "sql_parse.h" // check_global_access -#include "sql_acl.h" // *_ACL +#include "sql_parse.h" +#include "sql_acl.h" #include "rpl_rli.h" #include "base64.h" -#include "slave.h" // apply_event_and_update_pos -#include "log_event.h" // Format_description_log_event, - // EVENT_LEN_OFFSET, - // EVENT_TYPE_OFFSET, - // FORMAT_DESCRIPTION_LOG_EVENT, - // START_EVENT_V3, - // Log_event_type, - // Log_event +#include "slave.h" +#include "log_event.h" + + +/** + Check if the event type is allowed in a BINLOG statement. + + @retval 0 if the event type is ok. + @retval 1 if the event type is not ok. +*/ +static int check_event_type(int type, Relay_log_info *rli) +{ + Format_description_log_event *fd_event= + rli->relay_log.description_event_for_exec; + + /* + Convert event type id of certain old versions (see comment in + Format_description_log_event::Format_description_log_event(char*,...)). + */ + if (fd_event && fd_event->event_type_permutation) + { + IF_DBUG({ + int new_type= fd_event->event_type_permutation[type]; + DBUG_PRINT("info", + ("converting event type %d to %d (%s)", + type, new_type, + Log_event::get_type_str((Log_event_type)new_type))); + }, + (void)0); + type= fd_event->event_type_permutation[type]; + } + + switch (type) + { + case START_EVENT_V3: + case FORMAT_DESCRIPTION_EVENT: + /* + We need a preliminary FD event in order to parse the FD event, + if we don't already have one. + */ + if (!fd_event) + if (!(rli->relay_log.description_event_for_exec= + new Format_description_log_event(4))) + { + my_error(ER_OUTOFMEMORY, MYF(0), 1); + return 1; + } + + /* It is always allowed to execute FD events. */ + return 0; + + case TABLE_MAP_EVENT: + case WRITE_ROWS_EVENT: + case UPDATE_ROWS_EVENT: + case DELETE_ROWS_EVENT: + case PRE_GA_WRITE_ROWS_EVENT: + case PRE_GA_UPDATE_ROWS_EVENT: + case PRE_GA_DELETE_ROWS_EVENT: + /* + Row events are only allowed if a Format_description_event has + already been seen. + */ + if (fd_event) + return 0; + else + { + my_error(ER_NO_FORMAT_DESCRIPTION_EVENT_BEFORE_BINLOG_STATEMENT, + MYF(0), Log_event::get_type_str((Log_event_type)type)); + return 1; + } + break; + + default: + /* + It is not meaningful to execute other events than row-events and + FD events. It would even be dangerous to execute Stop_log_event + and Rotate_log_event since they call flush_relay_log_info, which + is not allowed to call by other threads than the slave SQL + thread when the slave SQL thread is running. + */ + my_error(ER_ONLY_FD_AND_RBR_EVENTS_ALLOWED_IN_BINLOG_STATEMENT, + MYF(0), Log_event::get_type_str((Log_event_type)type)); + return 1; + } +} + /** Execute a BINLOG statement. @@ -73,31 +151,13 @@ void mysql_client_binlog_statement(THD* thd) Allocation */ - /* - If we do not have a Format_description_event, we create a dummy - one here. In this case, the first event we read must be a - Format_description_event. - */ - my_bool have_fd_event= TRUE; int err; Relay_log_info *rli; rpl_group_info *rgi; rli= thd->rli_fake; - if (!rli) - { - rli= thd->rli_fake= new Relay_log_info(FALSE); -#ifdef HAVE_valgrind - rli->is_fake= TRUE; -#endif - have_fd_event= FALSE; - } - if (rli && !rli->relay_log.description_event_for_exec) - { - rli->relay_log.description_event_for_exec= - new Format_description_log_event(4); - have_fd_event= FALSE; - } + if (!rli && (rli= thd->rli_fake= new Relay_log_info(FALSE))) + rli->sql_driver_thd= thd; if (!(rgi= thd->rgi_fake)) rgi= thd->rgi_fake= new rpl_group_info(rli); rgi->thd= thd; @@ -109,16 +169,13 @@ void mysql_client_binlog_statement(THD* thd) /* Out of memory check */ - if (!(rli && - rli->relay_log.description_event_for_exec && - buf)) + if (!(rli && buf)) { my_error(ER_OUTOFMEMORY, MYF(ME_FATALERROR), 1); /* needed 1 bytes */ goto end; } - rli->sql_driver_thd= thd; - rli->no_storage= TRUE; + DBUG_ASSERT(rli->belongs_to_client()); for (char const *strptr= thd->lex->comment.str ; strptr < thd->lex->comment.str + thd->lex->comment.length ; ) @@ -185,23 +242,8 @@ void mysql_client_binlog_statement(THD* thd) DBUG_PRINT("info", ("event_len=%lu, bytes_decoded=%d", event_len, bytes_decoded)); - /* - If we have not seen any Format_description_event, then we must - see one; it is the only statement that can be read in base64 - without a prior Format_description_event. - */ - if (!have_fd_event) - { - int type = (uchar)bufptr[EVENT_TYPE_OFFSET]; - if (type == FORMAT_DESCRIPTION_EVENT || type == START_EVENT_V3) - have_fd_event= TRUE; - else - { - my_error(ER_NO_FORMAT_DESCRIPTION_EVENT_BEFORE_BINLOG_STATEMENT, - MYF(0), Log_event::get_type_str((Log_event_type)type)); - goto end; - } - } + if (check_event_type(bufptr[EVENT_TYPE_OFFSET], rli)) + goto end; ev= Log_event::read_log_event(bufptr, event_len, &error, rli->relay_log.description_event_for_exec, @@ -212,7 +254,7 @@ void mysql_client_binlog_statement(THD* thd) { /* This could actually be an out-of-memory, but it is more likely - causes by a bad statement + caused by a bad statement */ my_error(ER_SYNTAX_ERROR, MYF(0)); goto end; diff --git a/sql/sql_lex.cc b/sql/sql_lex.cc index b62838f46f2..15cf9a39f90 100644 --- a/sql/sql_lex.cc +++ b/sql/sql_lex.cc @@ -4831,4 +4831,3 @@ void binlog_unsafe_map_init() BINLOG_DIRECT_OFF & TRX_CACHE_NOT_EMPTY); } #endif - diff --git a/sql/sql_lex.h b/sql/sql_lex.h index 6ec112cc038..626beaa9894 100644 --- a/sql/sql_lex.h +++ b/sql/sql_lex.h @@ -240,11 +240,12 @@ struct LEX_MASTER_INFO ulong server_id; uint port, connect_retry; float heartbeat_period; + int sql_delay; /* Enum is used for making it possible to detect if the user changed variable or if it should be left at old value */ - enum {LEX_MI_UNCHANGED, LEX_MI_DISABLE, LEX_MI_ENABLE} + enum {LEX_MI_UNCHANGED= 0, LEX_MI_DISABLE, LEX_MI_ENABLE} ssl, ssl_verify_server_cert, heartbeat_opt, repl_ignore_server_ids_opt, repl_do_domain_ids_opt, repl_ignore_domain_ids_opt; enum { @@ -260,6 +261,7 @@ struct LEX_MASTER_INFO sizeof(ulong), 0, 16, MYF(0)); my_init_dynamic_array(&repl_ignore_domain_ids, sizeof(ulong), 0, 16, MYF(0)); + sql_delay= -1; } void reset(bool is_change_master) { @@ -280,6 +282,7 @@ struct LEX_MASTER_INFO repl_ignore_domain_ids_opt= LEX_MI_UNCHANGED; gtid_pos_str= null_lex_str; use_gtid_opt= LEX_GTID_UNCHANGED; + sql_delay= -1; } }; diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc index 572d08399d5..8bea280b820 100644 --- a/sql/sql_repl.cc +++ b/sql/sql_repl.cc @@ -3319,6 +3319,7 @@ int reset_slave(THD *thd, Master_info* mi) mi->clear_error(); mi->rli.clear_error(); mi->rli.clear_until_condition(); + mi->rli.clear_sql_delay(); mi->rli.slave_skip_counter= 0; // close master_info_file, relay_log_info_file, set mi->inited=rli->inited=0 @@ -3630,6 +3631,9 @@ bool change_master(THD* thd, Master_info* mi, bool *master_info_added) if (lex_mi->ssl != LEX_MASTER_INFO::LEX_MI_UNCHANGED) mi->ssl= (lex_mi->ssl == LEX_MASTER_INFO::LEX_MI_ENABLE); + if (lex_mi->sql_delay != -1) + mi->rli.set_sql_delay(lex_mi->sql_delay); + if (lex_mi->ssl_verify_server_cert != LEX_MASTER_INFO::LEX_MI_UNCHANGED) mi->ssl_verify_server_cert= (lex_mi->ssl_verify_server_cert == LEX_MASTER_INFO::LEX_MI_ENABLE); diff --git a/sql/sql_yacc.yy b/sql/sql_yacc.yy index 9131b99d95e..3b9a06d5b38 100644 --- a/sql/sql_yacc.yy +++ b/sql/sql_yacc.yy @@ -1341,6 +1341,7 @@ bool my_yyoverflow(short **a, YYSTYPE **b, ulong *yystacksize); %token LOOP_SYM %token LOW_PRIORITY %token MASTER_CONNECT_RETRY_SYM +%token MASTER_DELAY_SYM %token MASTER_GTID_POS_SYM %token MASTER_HOST_SYM %token MASTER_LOG_FILE_SYM @@ -2255,6 +2256,16 @@ master_def: { Lex->mi.connect_retry = $3; } + | MASTER_DELAY_SYM '=' ulong_num + { + if ($3 > MASTER_DELAY_MAX) + { + my_error(ER_MASTER_DELAY_VALUE_OUT_OF_RANGE, MYF(0), + $3, MASTER_DELAY_MAX); + } + else + Lex->mi.sql_delay = $3; + } | MASTER_SSL_SYM '=' ulong_num { Lex->mi.ssl= $3 ? @@ -7660,6 +7671,7 @@ slave: LEX *lex=Lex; lex->sql_command = SQLCOM_SLAVE_ALL_START; lex->type = 0; + /* If you change this code don't forget to update STOP SLAVE too */ } {} | STOP_SYM SLAVE optional_connection_name slave_thread_opts @@ -14099,6 +14111,7 @@ keyword_sp: | MASTER_PASSWORD_SYM {} | MASTER_SERVER_ID_SYM {} | MASTER_CONNECT_RETRY_SYM {} + | MASTER_DELAY_SYM {} | MASTER_SSL_SYM {} | MASTER_SSL_CA_SYM {} | MASTER_SSL_CAPATH_SYM {} From a9fb480fd614031e2e372b1fb8d7e4c858954ac6 Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Thu, 22 Sep 2016 12:23:32 +0200 Subject: [PATCH 08/52] MDEV-7145: Delayed replication, fixing test failures. Two merge error fixed, and testsuite updated to removed some other test failues. Signed-off-by: Kristian Nielsen --- mysql-test/include/relocate_binlogs.inc | 6 ++--- .../suite/multi_source/info_logs.result | 12 +++++----- .../suite/multi_source/reset_slave.result | 8 +++---- mysql-test/suite/multi_source/simple.result | 23 +++++++++++-------- mysql-test/suite/multi_source/syntax.result | 6 ++--- .../r/start_server_low_digest.result | 4 ++-- .../perfschema/t/start_server_low_digest.test | 3 +++ sql/slave.cc | 6 ++--- sql/sql_binlog.cc | 3 +++ tests/mysql_client_test.c | 2 +- 10 files changed, 41 insertions(+), 32 deletions(-) diff --git a/mysql-test/include/relocate_binlogs.inc b/mysql-test/include/relocate_binlogs.inc index d5d1135dda3..593ea0e9fbf 100644 --- a/mysql-test/include/relocate_binlogs.inc +++ b/mysql-test/include/relocate_binlogs.inc @@ -101,16 +101,16 @@ if ($relocate_index_file) --eval LOAD DATA INFILE '$relocate_fix_relay_log_info' INTO TABLE tmp (entry) --let $count= `SELECT count(*) FROM tmp` - --let $_curr_entry= `SELECT entry FROM tmp WHERE id=1` + --let $_curr_entry= `SELECT entry FROM tmp WHERE id=2` --let $_curr_entry_basename= `SELECT RIGHT(RTRIM("$_curr_entry"), LOCATE("$_path_separator",REVERSE(RTRIM("$_curr_entry"))) -1)` if ($relocate_is_windows) { - --eval UPDATE tmp SET entry='$_to\$_curr_entry_basename' WHERE id=1 + --eval UPDATE tmp SET entry='$_to\$_curr_entry_basename' WHERE id=2 } if (!$relocate_is_windows) { - --eval UPDATE tmp SET entry='$_to/$_curr_entry_basename' WHERE id=1 + --eval UPDATE tmp SET entry='$_to/$_curr_entry_basename' WHERE id=2 } --remove_file $relocate_fix_relay_log_info diff --git a/mysql-test/suite/multi_source/info_logs.result b/mysql-test/suite/multi_source/info_logs.result index d644939bd6f..34f83ed43f9 100644 --- a/mysql-test/suite/multi_source/info_logs.result +++ b/mysql-test/suite/multi_source/info_logs.result @@ -84,17 +84,17 @@ MASTER 2.2 # EOF # show all slaves status; -Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos - Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_1 60 master-bin.000001 relay.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 1 No conservative 0 1073741824 7 0 60.000 -MASTER 2.2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 relay-master@00202@002e2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 1073741824 7 0 60.000 +Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos + Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_1 60 master-bin.000001 relay.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 1 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 7 0 60.000 +MASTER 2.2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 relay-master@00202@002e2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 7 0 60.000 include/wait_for_slave_to_start.inc set default_master_connection = 'MASTER 2.2'; include/wait_for_slave_to_start.inc set default_master_connection = ''; show all slaves status; -Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos - Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_1 60 master-bin.000001 relay.000004 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 1 No conservative 0 1073741824 6 0 60.000 -MASTER 2.2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 relay-master@00202@002e2.000004 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 1073741824 6 0 60.000 +Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos + Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_1 60 master-bin.000001 relay.000004 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 1 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 6 0 60.000 +MASTER 2.2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 relay-master@00202@002e2.000004 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 6 0 60.000 # # List of files matching '*info*' pattern # after slave server restart diff --git a/mysql-test/suite/multi_source/reset_slave.result b/mysql-test/suite/multi_source/reset_slave.result index 6a9dbcdc561..f5217a6cdaf 100644 --- a/mysql-test/suite/multi_source/reset_slave.result +++ b/mysql-test/suite/multi_source/reset_slave.result @@ -10,15 +10,15 @@ create table t1 (i int) engine=MyISAM; insert into t1 values (1),(2); stop slave 'master1'; show slave 'master1' status; -Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode - 127.0.0.1 root MYPORT_1 60 master-bin.000001 mysqld-relay-bin-master1.000002 master-bin.000001 No No 0 0 None 0 No NULL No 0 0 1 No conservative +Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State + 127.0.0.1 root MYPORT_1 60 master-bin.000001 mysqld-relay-bin-master1.000002 master-bin.000001 No No 0 0 None 0 No NULL No 0 0 1 No conservative 0 NULL mysqld-relay-bin-master1.000001 mysqld-relay-bin-master1.000002 mysqld-relay-bin-master1.index reset slave 'master1'; show slave 'master1' status; -Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode - 127.0.0.1 root MYPORT_1 60 4 No No 0 0 0 None 0 No NULL No 0 0 1 No conservative +Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State + 127.0.0.1 root MYPORT_1 60 4 No No 0 0 0 None 0 No NULL No 0 0 1 No conservative 0 NULL reset slave 'master1' all; show slave 'master1' status; ERROR HY000: There is no master connection 'master1' diff --git a/mysql-test/suite/multi_source/simple.result b/mysql-test/suite/multi_source/simple.result index 3bf25e8d788..ee53e648d32 100644 --- a/mysql-test/suite/multi_source/simple.result +++ b/mysql-test/suite/multi_source/simple.result @@ -10,9 +10,9 @@ Note 1937 SLAVE 'slave2' started include/wait_for_slave_to_start.inc set default_master_connection = ''; show all slaves status; -Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos -slave1 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_1 60 master-bin.000001 mysqld-relay-bin-slave1.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 1 No conservative 0 1073741824 7 0 60.000 -slave2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 1073741824 7 0 60.000 +Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos +slave1 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_1 60 master-bin.000001 mysqld-relay-bin-slave1.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 1 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 7 0 60.000 +slave2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 7 0 60.000 start all slaves; stop slave 'slave1'; show slave 'slave1' status; @@ -63,21 +63,24 @@ Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode conservative +SQL_Delay 0 +SQL_Remaining_Delay NULL +Slave_SQL_Running_State reset slave 'slave1'; show all slaves status; -Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos -slave1 127.0.0.1 root MYPORT_1 60 4 No No 0 0 0 None 0 No NULL No 0 0 1 No conservative 0 1073741824 7 0 60.000 -slave2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 1073741824 7 0 60.000 +Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos +slave1 127.0.0.1 root MYPORT_1 60 4 No No 0 0 0 None 0 No NULL No 0 0 1 No conservative 0 NULL 0 1073741824 7 0 60.000 +slave2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 7 0 60.000 reset slave 'slave1' all; show all slaves status; -Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos -slave2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 1073741824 7 0 60.000 +Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos +slave2 Slave has read all relay log; waiting for the slave I/O thread to update it Waiting for master to send event 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 Yes Yes 0 0 None 0 No 0 No 0 0 2 No conservative 0 NULL Slave has read all relay log; waiting for the slave I/O thread to update it 0 1073741824 7 0 60.000 stop all slaves; Warnings: Note 1938 SLAVE 'slave2' stopped show all slaves status; -Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos -slave2 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 No No 0 0 None 0 No NULL No 0 0 2 No conservative 0 1073741824 7 0 60.000 +Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos +slave2 127.0.0.1 root MYPORT_2 60 master-bin.000001 mysqld-relay-bin-slave2.000002 master-bin.000001 No No 0 0 None 0 No NULL No 0 0 2 No conservative 0 NULL 0 1073741824 7 0 60.000 stop all slaves; include/reset_master_slave.inc include/reset_master_slave.inc diff --git a/mysql-test/suite/multi_source/syntax.result b/mysql-test/suite/multi_source/syntax.result index 55b124bf5a1..238244fa298 100644 --- a/mysql-test/suite/multi_source/syntax.result +++ b/mysql-test/suite/multi_source/syntax.result @@ -1,11 +1,11 @@ include/master-slave.inc [connection master] show slave status; -Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode +Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State show slave '' status; -Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode +Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State show all slaves status; -Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos +Connection_name Slave_SQL_State Slave_IO_State Master_Host Master_User Master_Port Connect_Retry Master_Log_File Read_Master_Log_Pos Relay_Log_File Relay_Log_Pos Relay_Master_Log_File Slave_IO_Running Slave_SQL_Running Replicate_Do_DB Replicate_Ignore_DB Replicate_Do_Table Replicate_Ignore_Table Replicate_Wild_Do_Table Replicate_Wild_Ignore_Table Last_Errno Last_Error Skip_Counter Exec_Master_Log_Pos Relay_Log_Space Until_Condition Until_Log_File Until_Log_Pos Master_SSL_Allowed Master_SSL_CA_File Master_SSL_CA_Path Master_SSL_Cert Master_SSL_Cipher Master_SSL_Key Seconds_Behind_Master Master_SSL_Verify_Server_Cert Last_IO_Errno Last_IO_Error Last_SQL_Errno Last_SQL_Error Replicate_Ignore_Server_Ids Master_Server_Id Master_SSL_Crl Master_SSL_Crlpath Using_Gtid Gtid_IO_Pos Replicate_Do_Domain_Ids Replicate_Ignore_Domain_Ids Parallel_Mode SQL_Delay SQL_Remaining_Delay Slave_SQL_Running_State Retried_transactions Max_relay_log_size Executed_log_entries Slave_received_heartbeats Slave_heartbeat_period Gtid_Slave_Pos # # Check error handling # diff --git a/mysql-test/suite/perfschema/r/start_server_low_digest.result b/mysql-test/suite/perfschema/r/start_server_low_digest.result index 8cc92f21964..6fc41fbb715 100644 --- a/mysql-test/suite/perfschema/r/start_server_low_digest.result +++ b/mysql-test/suite/perfschema/r/start_server_low_digest.result @@ -8,5 +8,5 @@ SELECT 1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1 #################################### SELECT event_name, digest, digest_text, sql_text FROM events_statements_history_long; event_name digest digest_text sql_text -statement/sql/truncate e1c917a43f978456fab15240f89372ca TRUNCATE TABLE truncate table events_statements_history_long -statement/sql/select 3f7ca34376814d0e985337bd588b5ffd SELECT ? + ? + SELECT 1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1 +statement/sql/truncate 6206ac02a54d832f55015e480e6f2213 TRUNCATE TABLE truncate table events_statements_history_long +statement/sql/select 4cc1c447d79877c4e8df0423fd0cde9a SELECT ? + ? + SELECT 1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1 diff --git a/mysql-test/suite/perfschema/t/start_server_low_digest.test b/mysql-test/suite/perfschema/t/start_server_low_digest.test index 6f06def169b..630de2e242d 100644 --- a/mysql-test/suite/perfschema/t/start_server_low_digest.test +++ b/mysql-test/suite/perfschema/t/start_server_low_digest.test @@ -12,6 +12,9 @@ truncate table events_statements_history_long; # ----------------------------------------------------------------------- # Test to show how the digest behaves with low value of # - performance_schema_max_digest_length +# +# Note that the digest values in the .result file will need updating +# whenever eg. a new keyword is added to the parser. # ----------------------------------------------------------------------- SELECT 1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1; diff --git a/sql/slave.cc b/sql/slave.cc index d1d9abd4027..a63fc9c005d 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -6768,10 +6768,10 @@ bool Relay_log_info::flush() pos=strmov(pos, group_master_log_name); *pos++='\n'; pos=longlong10_to_str(group_master_log_pos, pos, 10); - *pos='\n'; + *pos++='\n'; pos= longlong10_to_str(sql_delay, pos, 10); - *pos= '\n'; - if (my_b_write(file, (uchar*) buff, (size_t) (pos-buff)+1)) + *pos++= '\n'; + if (my_b_write(file, (uchar*) buff, (size_t) (pos-buff))) error=1; if (flush_io_cache(file)) error=1; diff --git a/sql/sql_binlog.cc b/sql/sql_binlog.cc index a7beb42c315..0543cd2434e 100644 --- a/sql/sql_binlog.cc +++ b/sql/sql_binlog.cc @@ -73,6 +73,9 @@ static int check_event_type(int type, Relay_log_info *rli) return 0; case TABLE_MAP_EVENT: + case WRITE_ROWS_EVENT_V1: + case UPDATE_ROWS_EVENT_V1: + case DELETE_ROWS_EVENT_V1: case WRITE_ROWS_EVENT: case UPDATE_ROWS_EVENT: case DELETE_ROWS_EVENT: diff --git a/tests/mysql_client_test.c b/tests/mysql_client_test.c index b95127f954f..74c6d684295 100644 --- a/tests/mysql_client_test.c +++ b/tests/mysql_client_test.c @@ -447,7 +447,7 @@ static void test_prepare_simple() strmov(query, "SHOW SLAVE STATUS"); stmt= mysql_simple_prepare(mysql, query); check_stmt(stmt); - DIE_UNLESS(mysql_stmt_field_count(stmt) == 47); + DIE_UNLESS(mysql_stmt_field_count(stmt) == 50); mysql_stmt_close(stmt); /* show master status */ From b2bc6dadeeaa16fc7da845cfbeb8bb61042683ac Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Thu, 22 Sep 2016 13:36:45 +0200 Subject: [PATCH 09/52] MDEV-7145: Delayed replication, cleanup some code The original MySQL patch left some refactoring todo's, possibly because of known conflicts with other parallel development (like info-repository feature perhaps). This patch fixes those todos/refactorings. Signed-off-by: Kristian Nielsen --- sql/log.cc | 2 +- sql/log_event.cc | 8 ++-- sql/rpl_mi.cc | 2 +- sql/rpl_rli.cc | 104 ++++++++++++++++++++++++++++++++++++---------- sql/rpl_rli.h | 15 +------ sql/slave.cc | 88 ++------------------------------------- sql/slave.h | 1 - sql/sql_binlog.cc | 2 +- sql/sql_repl.cc | 4 +- 9 files changed, 97 insertions(+), 129 deletions(-) diff --git a/sql/log.cc b/sql/log.cc index e3d42a4547e..fd4ceb72164 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -4400,7 +4400,7 @@ int MYSQL_BIN_LOG::purge_first_log(Relay_log_info* rli, bool included) } /* Store where we are in the new file for the execution thread */ - flush_relay_log_info(rli); + rli->flush(); DBUG_EXECUTE_IF("crash_before_purge_logs", DBUG_SUICIDE();); diff --git a/sql/log_event.cc b/sql/log_event.cc index bd8ae984c2d..f6b129d34b2 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -6402,7 +6402,7 @@ bool Rotate_log_event::write() The NOTES below is a wrong comment which will disappear when 4.1 is merged. This must only be called from the Slave SQL thread, since it calls - flush_relay_log_info(). + Relay_log_info::flush(). @retval 0 ok @@ -6457,7 +6457,7 @@ int Rotate_log_event::do_update_pos(rpl_group_info *rgi) (ulong) rli->group_master_log_pos)); mysql_mutex_unlock(&rli->data_lock); rpl_global_gtid_slave_state->record_and_update_gtid(thd, rgi); - flush_relay_log_info(rli); + rli->flush(); /* Reset thd->variables.option_bits and sql_mode etc, because this could @@ -8228,7 +8228,7 @@ void Stop_log_event::print(FILE* file, PRINT_EVENT_INFO* print_event_info) here, the master was sane. This must only be called from the Slave SQL thread, since it calls - flush_relay_log_info(). + Relay_log_info::flush(). */ int Stop_log_event::do_update_pos(rpl_group_info *rgi) @@ -8248,7 +8248,7 @@ int Stop_log_event::do_update_pos(rpl_group_info *rgi) { rpl_global_gtid_slave_state->record_and_update_gtid(thd, rgi); rli->inc_group_relay_log_pos(0, rgi); - flush_relay_log_info(rli); + rli->flush(); } DBUG_RETURN(0); } diff --git a/sql/rpl_mi.cc b/sql/rpl_mi.cc index 867ebc7167a..fd04e233d35 100644 --- a/sql/rpl_mi.cc +++ b/sql/rpl_mi.cc @@ -647,7 +647,7 @@ file '%s')", fname); (ulong) mi->master_log_pos)); mi->rli.mi= mi; - if (init_relay_log_info(&mi->rli, slave_info_fname)) + if (mi->rli.init(slave_info_fname)) goto err; mi->inited = 1; diff --git a/sql/rpl_rli.cc b/sql/rpl_rli.cc index a7d8f843688..e917e9527ad 100644 --- a/sql/rpl_rli.cc +++ b/sql/rpl_rli.cc @@ -110,19 +110,6 @@ Relay_log_info::~Relay_log_info() } -/** - Wrapper around Relay_log_info::init(const char *). - - @todo Remove this and replace all calls to it by calls to - Relay_log_info::init(const char *). /SVEN -*/ -int init_relay_log_info(Relay_log_info* rli, - const char* info_fname) -{ - return rli->init(info_fname); -} - - /** Read the relay_log.info file. @@ -135,7 +122,7 @@ int Relay_log_info::init(const char* info_fname) char fname[FN_REFLEN+128]; const char* msg = 0; int error = 0; - DBUG_ENTER("init_relay_log_info"); + DBUG_ENTER("Relay_log_info::init"); if (inited) // Set if this function called DBUG_RETURN(0); @@ -242,7 +229,7 @@ a file name for --relay-log-index option", opt_relaylog_index_name); max_relay_log_size, 1, TRUE)) { mysql_mutex_unlock(&data_lock); - sql_print_error("Failed when trying to open logs for '%s' in init_relay_log_info(). Error: %M", ln, my_errno); + sql_print_error("Failed when trying to open logs for '%s' in Relay_log_info::init(). Error: %M", ln, my_errno); DBUG_RETURN(1); } } @@ -409,10 +396,10 @@ Failed to open the existing relay log info file '%s' (errno %d)", /* Now change the cache from READ to WRITE - must do this - before flush_relay_log_info + before Relay_log_info::flush() */ reinit_io_cache(&info_file, WRITE_CACHE,0L,0,1); - if ((error= flush_relay_log_info(this))) + if ((error= flush())) { msg= "Failed to flush relay log info file"; goto err; @@ -1108,10 +1095,10 @@ int purge_relay_logs(Relay_log_info* rli, THD *thd, bool just_reset, Indeed, rli->inited==0 does not imply that they already are empty. It could be that slave's info initialization partly succeeded : for example if relay-log.info existed but *relay-bin*.* - have been manually removed, init_relay_log_info reads the old - relay-log.info and fills rli->master_log_*, then init_relay_log_info + have been manually removed, Relay_log_info::init() reads the old + relay-log.info and fills rli->master_log_*, then Relay_log_info::init() checks for the existence of the relay log, this fails and - init_relay_log_info leaves rli->inited to 0. + Relay_log_info::init() leaves rli->inited to 0. In that pathological case, rli->master_log_pos* will be properly reinited at the next START SLAVE (as RESET SLAVE or CHANGE MASTER, the callers of purge_relay_logs, will delete bogus *.info files @@ -1349,7 +1336,7 @@ void Relay_log_info::stmt_done(my_off_t event_master_log_pos, THD *thd, } DBUG_EXECUTE_IF("inject_crash_before_flush_rli", DBUG_SUICIDE();); if (mi->using_gtid == Master_info::USE_GTID_NO) - flush_relay_log_info(this); + flush(); DBUG_EXECUTE_IF("inject_crash_after_flush_rli", DBUG_SUICIDE();); } DBUG_VOID_RETURN; @@ -2010,4 +1997,79 @@ bool rpl_sql_thread_info::cached_charset_compare(char *charset) const DBUG_RETURN(0); } + +/** + Store the file and position where the slave's SQL thread are in the + relay log. + + Notes: + + - This function should be called either from the slave SQL thread, + or when the slave thread is not running. (It reads the + group_{relay|master}_log_{pos|name} and delay fields in the rli + object. These may only be modified by the slave SQL thread or by + a client thread when the slave SQL thread is not running.) + + - If there is an active transaction, then we do not update the + position in the relay log. This is to ensure that we re-execute + statements if we die in the middle of an transaction that was + rolled back. + + - As a transaction never spans binary logs, we don't have to handle + the case where we do a relay-log-rotation in the middle of the + transaction. If transactions could span several binlogs, we would + have to ensure that we do not delete the relay log file where the + transaction started before switching to a new relay log file. + + - Error can happen if writing to file fails or if flushing the file + fails. + + @param rli The object representing the Relay_log_info. + + @todo Change the log file information to a binary format to avoid + calling longlong2str. + + @return 0 on success, 1 on error. +*/ +bool Relay_log_info::flush() +{ + bool error=0; + + DBUG_ENTER("Relay_log_info::flush()"); + + IO_CACHE *file = &info_file; + // 2*file name, 2*long long, 2*unsigned long, 6*'\n' + char buff[FN_REFLEN * 2 + 22 * 2 + 10 * 2 + 6], *pos; + my_b_seek(file, 0L); + pos= longlong10_to_str(LINES_IN_RELAY_LOG_INFO_WITH_DELAY, buff, 10); + *pos++='\n'; + pos=strmov(pos, group_relay_log_name); + *pos++='\n'; + pos=longlong10_to_str(group_relay_log_pos, pos, 10); + *pos++='\n'; + pos=strmov(pos, group_master_log_name); + *pos++='\n'; + pos=longlong10_to_str(group_master_log_pos, pos, 10); + *pos++='\n'; + pos= longlong10_to_str(sql_delay, pos, 10); + *pos++= '\n'; + if (my_b_write(file, (uchar*) buff, (size_t) (pos-buff))) + error=1; + if (flush_io_cache(file)) + error=1; + if (sync_relayloginfo_period && + !error && + ++sync_counter >= sync_relayloginfo_period) + { + if (my_sync(info_fd, MYF(MY_WME))) + error=1; + sync_counter= 0; + } + /* + Flushing the relay log is done by the slave I/O thread + or by the user on STOP SLAVE. + */ + DBUG_RETURN(error); +} + #endif diff --git a/sql/rpl_rli.h b/sql/rpl_rli.h index 0c8f16a0d16..1d7bd70cd8b 100644 --- a/sql/rpl_rli.h +++ b/sql/rpl_rli.h @@ -42,7 +42,7 @@ class Rpl_filter; Relay_log_info is initialized from the slave.info file if such exists. Otherwise, data members are intialized with defaults. The - initialization is done with init_relay_log_info() call. + initialization is done with Relay_log_info::init() call. The format of slave.info file: @@ -536,7 +536,7 @@ private: MASTER_DELAY=X. Read by SQL thread and by client threads executing SHOW SLAVE STATUS. Note: must not be written while the slave SQL thread is running, since the SQL thread reads it without - a lock when executing flush_relay_log_info(). + a lock when executing Relay_log_info::flush(). */ int sql_delay; @@ -954,17 +954,6 @@ public: }; -/** - Reads the relay_log.info file. - - @todo This is a wrapper around Relay_log_info::init(). It's only - kept for historical reasons. It would be good if we removed this - function and replaced all calls to it by calls to - Relay_log_info::init(). /SVEN -*/ -int init_relay_log_info(Relay_log_info* rli, const char* info_fname); - - extern struct rpl_slave_state *rpl_global_gtid_slave_state; extern gtid_waiting rpl_global_gtid_waiting; diff --git a/sql/slave.cc b/sql/slave.cc index a63fc9c005d..813827e883f 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -738,7 +738,7 @@ int terminate_slave_threads(Master_info* mi,int thread_mask,bool skip_lock) DBUG_PRINT("info",("Flushing relay-log info file.")); if (current_thd) THD_STAGE_INFO(current_thd, stage_flushing_relay_log_info_file); - if (flush_relay_log_info(&mi->rli)) + if (mi->rli.flush()) DBUG_RETURN(ER_ERROR_DURING_FLUSH_LOGS); if (my_sync(mi->rli.info_fd, MYF(MY_WME))) @@ -5124,7 +5124,7 @@ pthread_handler_t handle_slave_sql(void *arg) { ulong domain_count; - flush_relay_log_info(rli); + rli->flush(); if (mi->using_parallel()) { /* @@ -6708,88 +6708,6 @@ MYSQL *rpl_connect_master(MYSQL *mysql) } #endif -/** - Store the file and position where the slave's SQL thread are in the - relay log. - - Notes: - - - This function should be called either from the slave SQL thread, - or when the slave thread is not running. (It reads the - group_{relay|master}_log_{pos|name} and delay fields in the rli - object. These may only be modified by the slave SQL thread or by - a client thread when the slave SQL thread is not running.) - - - If there is an active transaction, then we do not update the - position in the relay log. This is to ensure that we re-execute - statements if we die in the middle of an transaction that was - rolled back. - - - As a transaction never spans binary logs, we don't have to handle - the case where we do a relay-log-rotation in the middle of the - transaction. If transactions could span several binlogs, we would - have to ensure that we do not delete the relay log file where the - transaction started before switching to a new relay log file. - - - Error can happen if writing to file fails or if flushing the file - fails. - - @param rli The object representing the Relay_log_info. - - @todo Change the log file information to a binary format to avoid - calling longlong2str. - - @todo Move the member function into rpl_rli.cc and get rid of the - global function. /SVEN - - @return 0 on success, 1 on error. -*/ -bool flush_relay_log_info(Relay_log_info* rli) -{ - return rli->flush(); -} - -bool Relay_log_info::flush() -{ - bool error=0; - - DBUG_ENTER("Relay_log_info::flush()"); - - IO_CACHE *file = &info_file; - // 2*file name, 2*long long, 2*unsigned long, 6*'\n' - char buff[FN_REFLEN * 2 + 22 * 2 + 10 * 2 + 6], *pos; - my_b_seek(file, 0L); - pos= longlong10_to_str(LINES_IN_RELAY_LOG_INFO_WITH_DELAY, buff, 10); - *pos++='\n'; - pos=strmov(pos, group_relay_log_name); - *pos++='\n'; - pos=longlong10_to_str(group_relay_log_pos, pos, 10); - *pos++='\n'; - pos=strmov(pos, group_master_log_name); - *pos++='\n'; - pos=longlong10_to_str(group_master_log_pos, pos, 10); - *pos++='\n'; - pos= longlong10_to_str(sql_delay, pos, 10); - *pos++= '\n'; - if (my_b_write(file, (uchar*) buff, (size_t) (pos-buff))) - error=1; - if (flush_io_cache(file)) - error=1; - if (sync_relayloginfo_period && - !error && - ++sync_counter >= sync_relayloginfo_period) - { - if (my_sync(info_fd, MYF(MY_WME))) - error=1; - sync_counter= 0; - } - /* - Flushing the relay log is done by the slave I/O thread - or by the user on STOP SLAVE. - */ - DBUG_RETURN(error); -} - /* Called when we notice that the current "hot" log got rotated under our feet. @@ -7146,7 +7064,7 @@ static Log_event* next_event(rpl_group_info *rgi, ulonglong *event_size) } rli->event_relay_log_pos = BIN_LOG_HEADER_SIZE; strmake_buf(rli->event_relay_log_name,rli->linfo.log_file_name); - flush_relay_log_info(rli); + rli->flush(); } /* diff --git a/sql/slave.h b/sql/slave.h index d28048af8ea..11015ac2db0 100644 --- a/sql/slave.h +++ b/sql/slave.h @@ -183,7 +183,6 @@ extern const char *relay_log_basename; int init_slave(); int init_recovery(Master_info* mi, const char** errmsg); void init_slave_skip_errors(const char* arg); -bool flush_relay_log_info(Relay_log_info* rli); int register_slave_on_master(MYSQL* mysql); int terminate_slave_threads(Master_info* mi, int thread_mask, bool skip_lock = 0); diff --git a/sql/sql_binlog.cc b/sql/sql_binlog.cc index 0543cd2434e..314744714d0 100644 --- a/sql/sql_binlog.cc +++ b/sql/sql_binlog.cc @@ -100,7 +100,7 @@ static int check_event_type(int type, Relay_log_info *rli) /* It is not meaningful to execute other events than row-events and FD events. It would even be dangerous to execute Stop_log_event - and Rotate_log_event since they call flush_relay_log_info, which + and Rotate_log_event since they call Relay_log_info::flush(), which is not allowed to call by other threads than the slave SQL thread when the slave SQL thread is running. */ diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc index 8bea280b820..6ecaef6500f 100644 --- a/sql/sql_repl.cc +++ b/sql/sql_repl.cc @@ -494,7 +494,7 @@ static enum enum_binlog_checksum_alg get_binlog_checksum_value_at_connect(THD * TODO - Inform the slave threads that they should sync the position - in the binary log file with flush_relay_log_info. + in the binary log file with Relay_log_info::flush(). Now they sync is done for next read. */ @@ -3818,7 +3818,7 @@ bool change_master(THD* thd, Master_info* mi, bool *master_info_added) in-memory value at restart (thus causing errors, as the old relay log does not exist anymore). */ - flush_relay_log_info(&mi->rli); + mi->rli.flush(); mysql_cond_broadcast(&mi->data_cond); mysql_mutex_unlock(&mi->rli.data_lock); From 851c401c0d2db3d02f5312989da8034e647fecb8 Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Fri, 23 Sep 2016 11:31:57 +0200 Subject: [PATCH 10/52] MDEV-7145: Delayed replication, fix wsrep build failure. Signed-off-by: Kristian Nielsen --- sql/wsrep_thd.cc | 1 - 1 file changed, 1 deletion(-) diff --git a/sql/wsrep_thd.cc b/sql/wsrep_thd.cc index cf69a4d2d12..490a3db1a59 100644 --- a/sql/wsrep_thd.cc +++ b/sql/wsrep_thd.cc @@ -94,7 +94,6 @@ static rpl_group_info* wsrep_relay_group_init(const char* log_fname) { Relay_log_info* rli= new Relay_log_info(false); - rli->no_storage= true; if (!rli->relay_log.description_event_for_exec) { rli->relay_log.description_event_for_exec= From 814880711f0084f5cb1d8b1342b15ac819935742 Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Fri, 14 Oct 2016 11:18:33 +0200 Subject: [PATCH 11/52] BUG#56442: Slave executes delayed statements when STOP SLAVE is issued Problem: When using the delayed slave feature, and the SQL thread is delaying, and the user issues STOP SLAVE, the event we wait for was executed. It should not be executed. Fix: Check the return value from the delay function, slave.cc:slave_sleep(). If the return value is 1, it means the thread has been stopped, in this case we don't execute the statement. Also, refactored the test case for delayed slave a little: added the test script include/rpl_assert.inc, which asserts that a condition holds and prints a message if not. Made rpl_delayed_slave.test use this. The advantage is that the test file is much easier to read and maintain, because it is clear what is an assertion and what is not, and also the expected result can be found in the test file, you don't have to compare it to the result file. Manually merged into MariaDB from MySQL commit fd2b210383358fe7697f201e19ac9779879ba72a Signed-off-by: Kristian Nielsen --- .../rpl_tests/delayed_slave_wait_on_query.inc | 30 ++- mysql-test/include/rpl_assert.inc | 118 +++++++++ .../suite/rpl/r/rpl_delayed_slave.result | 135 +++++----- mysql-test/suite/rpl/t/rpl_delayed_slave.test | 242 +++++++++++------- sql/slave.cc | 20 +- 5 files changed, 372 insertions(+), 173 deletions(-) create mode 100644 mysql-test/include/rpl_assert.inc diff --git a/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc b/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc index 5d04d14edf3..ffdcb7f60bb 100644 --- a/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc +++ b/mysql-test/extra/rpl_tests/delayed_slave_wait_on_query.inc @@ -10,21 +10,32 @@ # - After one and a half delay, check the status. It should not be # delaying and the query should be executed. # +# # ==== Usage ==== # +# --let $query_number= 4 # --source extra/rpl_tests/delayed_slave_wait_on_query.inc +# +# Parameters: +# $query_number +# The value of the 'b' column in t1 for the row inserted by the query +# we are waiting for. connection master; + --echo [on slave] --let $slave_timeout= $time1 - --source include/sync_slave_io_with_master.inc --echo # sleep 1*T --sleep $time1 ---echo # Expect query not executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Query $query_number should not be executed +--let $assert_cond= MAX(b) < $query_number FROM t1 +--source include/rpl_assert.inc + +--let $assert_text= Status should be 'Waiting until MASTER_DELAY...' +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%" +--source include/rpl_assert.inc --echo # sleep 1*T --sleep $time1 @@ -32,8 +43,13 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1; --echo # sync with master (with timeout 1*T) --source include/sync_with_master.inc ---echo # Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Query $query_number should be executed +--let $assert_cond= MAX(b) = $query_number FROM t1 +--source include/rpl_assert.inc + +--let $assert_text= Status should be 'Has read all relay log...' +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%" +--source include/rpl_assert.inc + --source include/check_slave_is_running.inc diff --git a/mysql-test/include/rpl_assert.inc b/mysql-test/include/rpl_assert.inc new file mode 100644 index 00000000000..d9963e8e782 --- /dev/null +++ b/mysql-test/include/rpl_assert.inc @@ -0,0 +1,118 @@ +# ==== Purpose ==== +# +# Check if a condition holds, fail with debug info if not. +# +# The condition is parsed before executed. The following constructs +# are supported: +# +# [SQL STATEMENT, COLUMN, ROW] +# The square bracket is replaced by the result from SQL STATEMENT, +# in the given COLUMN and ROW. +# +# <1> +# This is a shorthand for the result of the first executed square +# bracket. <2> is a shorthand for the second executed square +# bracket, and so on. +# +# ==== Usage ==== +# +# --let $assert_text= Relay_Log_Pos must be smaller than pos. +# --let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] >= $min_pos AND <1> <= $max_pos +# [--let $assert_quiet= 1] +# [--let $rpl_debug= 1] +# --source include/rpl_assert.inc +# +# Parameters: +# +# $assert_text +# Text that describes what is being checked. By default, this text +# is written to the query log. +# +# $assert_cond +# Condition to check. See above for details about the format. The +# condition will be executed as `SELECT $assert_cond`. Note: this +# condition is parsed using SQL statements, quoted inside single +# quotes, so it must not contain single quotes itself (use double +# quotes for strings). +# +# $assert_quiet +# Do not print $assert_text to the query log. +# +# $rpl_debug +# Print extra debug info. + + +if ($rpl_debug) +{ + --echo # debug: assert_text='$assert_text' assert_cond='$assert_cond' +} + +# Sanity-check input +if (`SELECT "$assert_text" = ""`) +{ + --die ERROR IN TEST: the mysqltest variable rpl_test must be set +} + +# Evaluate square brackets in cond. +--let $_rpl_assert_substmt_number= 1 +--let $_rpl_interpolated_cond= $assert_cond +--let $_rpl_assert_lbracket= `SELECT LOCATE('[', '$_rpl_interpolated_cond')` +while ($_rpl_assert_lbracket) +{ + # Get position of right bracket + --let $_rpl_assert_rbracket= `SELECT LOCATE(']', '$_rpl_interpolated_cond')` + if (!$_rpl_assert_rbracket) + { + --echo BUG IN TEST: Mismatching square brackets in assert_cond: '$assert_cond' + --die BUG IN TEST: Mismatching square brackets in $assert_cond + } + # Get sub-statement and result of it + --let $_rpl_assert_substmt= `SELECT SUBSTRING('$_rpl_interpolated_cond', $_rpl_assert_lbracket + 1, $_rpl_assert_rbracket - $_rpl_assert_lbracket - 1)` + --let $_rpl_assert_substmt_result= query_get_value($_rpl_assert_substmt) + if ($rpl_debug) + { + --echo # debug: sub-statement='$_rpl_assert_substmt' result='$rpl_assert_result' + } + # Replace sub-statement by its result + --let $_rpl_interpolated_cond= `SELECT REPLACE('$_rpl_interpolated_cond', '[$_rpl_assert_substmt]', '$_rpl_assert_substmt_result')` + # Replace result references by result + --let $_rpl_interpolated_cond= `SELECT REPLACE('$_rpl_interpolated_cond', '<$_rpl_assert_substmt_number>', '$_rpl_assert_substmt_result')` + + --let $_rpl_assert_lbracket= `SELECT LOCATE('[', '$_rpl_interpolated_cond')` + + --inc $_rpl_assert_substmt_number +} + +if ($rpl_debug) +{ + --echo # debug: interpolated_cond='$_rpl_interpolated_cond' +} + +# Execute. +--let $_rpl_assert_result= `SELECT $_rpl_interpolated_cond` + +if ($rpl_debug) +{ + --echo # debug: result='$_rpl_assert_result' +} + +# Check. +if (!$_rpl_assert_result) +{ + --echo ######## Test assertion failed: $assert_text ######## + --echo Dumping debug info: + --source include/show_rpl_debug_info.inc + --echo Assertion text: '$assert_text' + --echo Assertion condition: '$assert_cond' + --echo Assertion condition, interpolated: '$_rpl_interpolated_cond' + --echo Assertion result: '$_rpl_assert_result' + --die Test assertion failed in rpl_assertion.inc +} + +if (!$assert_quiet) +{ + --echo # Asserted this: $assert_text +} + +--let $assert_text= +--let $assert_cond= diff --git a/mysql-test/suite/rpl/r/rpl_delayed_slave.result b/mysql-test/suite/rpl/r/rpl_delayed_slave.result index 75b263b61e0..1aad398bbc9 100644 --- a/mysql-test/suite/rpl/r/rpl_delayed_slave.result +++ b/mysql-test/suite/rpl/r/rpl_delayed_slave.result @@ -3,153 +3,146 @@ include/master-slave.inc call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); call mtr.add_suppression("Unsafe statement written to the binary log using statement format"); [on master] -CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); +CREATE TABLE t1 (a VARCHAR(100), b INT); +INSERT INTO t1 VALUES ("zero", 0); ==== Normal setup ==== [on slave] include/stop_slave.inc # CHANGE MASTER TO MASTER_DELAY = 2*T -# Checking that delay is what we set it to -# Expect status to be '' -SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1; -STATE - include/start_slave.inc +# Asserted this: SHOW SLAVE STATUS should return the same delay that we set with CHANGE MASTER [on master] -INSERT INTO t1(a) VALUES ('normal setup'); +INSERT INTO t1 VALUES ('normal setup', 1); [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect query not executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# Asserted this: Query 1 should not be executed +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' # sleep 1*T # sync with master (with timeout 1*T) include/wait_for_slave_param.inc [Relay_Master_Log_File] include/wait_for_slave_param.inc [Exec_Master_Log_Pos] -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -normal setup 1 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Query 1 should be executed +# Asserted this: Status should be 'Has read all relay log...' include/check_slave_is_running.inc ==== Slave lags "naturally" after master ==== [on master] # CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * T); ELSE RETURN 0; END IF; END -INSERT INTO t1(a) SELECT delay_on_slave(3); +INSERT INTO t1 SELECT delay_on_slave(3), 2; Warnings: Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. -INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately'); -INSERT INTO t1(a) SELECT delay_on_slave(2); +INSERT INTO t1 VALUES ('slave is already lagging: this statement should execute immediately', 3); +INSERT INTO t1 SELECT delay_on_slave(2), 4; Warnings: Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect no query executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -normal setup 1 -Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# Asserted this: No query executed +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' # wait for first query to execute # sleep 1*T -# Expect second query executed and status is executing third query (i.e., 'User sleep') -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -slave is already lagging: this statement should execute immediately 3 -Slave_SQL_Running_State='User sleep'; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread +# Asserted this: Second query executed +# Asserted this: Status should be executing third query (i.e., 'User sleep') # sleep 2*T -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -0 4 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Third query executed +# Asserted this: Status should be 'Has read all relay log...' ==== Seconds_Behind_Master ==== # Bring slave to sync. include/stop_slave.inc CHANGE MASTER TO MASTER_DELAY = 0; include/start_slave.inc -INSERT INTO t1(a) VALUES ('Syncing slave'); +INSERT INTO t1 VALUES ('Syncing slave', 5); include/stop_slave.inc # CHANGE MASTER TO MASTER_DELAY = 2*T include/start_slave.inc -INSERT INTO t1(a) VALUES (delay_on_slave(1)); +INSERT INTO t1 VALUES (delay_on_slave(1), 6); Warnings: Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system variable that may have a different value on the slave. Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. # sleep 1*T +# Asserted this: Seconds_Behind_Master should be between 0 and the 2*T # sleep 1*T -==== STOP SLAVE and START SLAVE ==== +# Asserted this: Seconds_Behind_Master should be at least 2*T +==== STOP SLAVE / START SLAVE + DML ==== include/stop_slave.inc # CHANGE MASTER TO MASTER_DELAY = 3*T include/start_slave.inc -# Checking that delay is what we set it to [on master] -INSERT INTO t1(a) VALUES ('stop slave and start slave'); +INSERT INTO t1 VALUES ('stop slave and start slave: DML', 7); [on slave] # sleep 1*T -SET @before_stop_slave= UNIX_TIMESTAMP(); include/stop_slave.inc -# STOP SLAVE finished in time. -# Expect query not executed and status is '' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -0 6 -Slave_SQL_Running_State=''; SQL_Remaining_Delay is NULL; SQL thread is behind IO thread +# Asserted this: STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish +# Asserted this: SQL thread position should not increase after STOP SLAVE +# Asserted this: Query should not be executed after STOP SLAVE +# Asserted this: Status should be '' after STOP SLAVE include/start_slave.inc -# START SLAVE finished in time. +# Asserted this: START SLAVE should finish quickly [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect query not executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -0 6 -Slave_SQL_Running_State='Waiting until MASTER_DELAY seconds after master executed event'; SQL_Remaining_Delay is greater than zero; SQL thread is behind IO thread +# Asserted this: Query 7 should not be executed +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' # sleep 1*T # sync with master (with timeout 1*T) include/wait_for_slave_param.inc [Relay_Master_Log_File] include/wait_for_slave_param.inc [Exec_Master_Log_Pos] -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -stop slave and start slave 7 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Query 7 should be executed +# Asserted this: Status should be 'Has read all relay log...' +include/check_slave_is_running.inc +==== STOP SLAVE / START SLAVE + DDL ==== +This verifies BUG#56442 +[on master] +CREATE TABLE t_check_dml_not_executed_prematurely (a INT); +include/save_master_pos.inc +[on slave] +# sleep 1*T +include/stop_slave.inc +# Asserted this: STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish +# Asserted this: SQL thread position should not increase after STOP SLAVE +# Asserted this: Query should not be executed after STOP SLAVE +# Asserted this: Status should be '' after STOP SLAVE +include/start_slave.inc +# Asserted this: START SLAVE should finish quickly +# sleep 1*T +# Asserted this: DDL Query should not be executed after START SLAVE +# Asserted this: Status should be 'Waiting until MASTER_DELAY...' +# sleep 1*T +# sync with master (with timeout 1*T) +include/wait_for_slave_param.inc [Relay_Master_Log_File] +include/wait_for_slave_param.inc [Exec_Master_Log_Pos] +# Asserted this: DDL Query should be executed +# Asserted this: Status should be 'Has read all relay log...' include/check_slave_is_running.inc ==== Change back to no delay ==== [on slave] include/stop_slave.inc CHANGE MASTER TO MASTER_DELAY = 0; -# Expect delay is 0. -SQL_Delay='0' +# Asserted this: Delay should be 0 when we set it to 0 include/start_slave.inc [on master] -INSERT INTO t1(a) VALUES ('change back to no delay'); +INSERT INTO t1 VALUES ('change back to no delay', 8); [on slave] include/sync_slave_io_with_master.inc # sleep 1*T -# Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; -a b -change back to no delay 8 -Slave_SQL_Running_State='Slave has read all relay log; waiting for the slave I/O thread to update it'; SQL_Remaining_Delay is NULL; SQL thread is in sync with IO thread +# Asserted this: Query should be executed +# Asserted this: Status should be 'Slave has read all relay log...' ==== Reset delay with RESET SLAVE ==== include/stop_slave.inc CHANGE MASTER TO MASTER_DELAY = 71; include/start_slave.inc -# Expect delay is 71 -SQL_Delay='71' +# Asserted this: Delay should be 71 when we set it to 71 include/stop_slave.inc RESET SLAVE; [on master] RESET MASTER; [on slave] include/start_slave.inc -# Expect delay is 0 -SQL_Delay='0' -==== Set a bad value for the delay ==== +# Asserted this: Delay should be 0 after RESET SLAVE +==== Set an invalid value for the delay ==== include/stop_slave.inc # Expect error for setting negative delay CHANGE MASTER TO MASTER_DELAY = -1; @@ -166,7 +159,7 @@ CHANGE MASTER TO MASTER_DELAY = 0; include/start_slave.inc ==== Clean up ==== [on master] -DROP TABLE t1; +DROP TABLE t1, t_check_dml_not_executed_prematurely; DROP FUNCTION delay_on_slave; [on slave] include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_delayed_slave.test b/mysql-test/suite/rpl/t/rpl_delayed_slave.test index 2fa5c81f5a5..3e6f5564bf2 100644 --- a/mysql-test/suite/rpl/t/rpl_delayed_slave.test +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave.test @@ -6,7 +6,7 @@ # - Verify that slave has executed the events after but not before the # delay timeout. # -# - Verify that delay is correct works when slave is already lagging +# - Verify that delay is correct when slave is already lagging # due to slow queries. # # - Verify that Seconds_Behind_Master is greater than or equal to the @@ -44,6 +44,7 @@ # BUG#28760: Simulating a replication lag # [duplicate] BUG#22072: configurable delayed replication # [duplicate] BUG#21639: Add Replication Delay parameter +# BUG#56442: Slave executes delayed statements when STOP SLAVE is issued # # ==== Issues with this Test Case ==== # @@ -79,7 +80,8 @@ if (`SELECT '$max_query_execution_time' > 0`) { --echo [on master] -CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); +CREATE TABLE t1 (a VARCHAR(100), b INT); +INSERT INTO t1 VALUES ("zero", 0); --echo ==== Normal setup ==== @@ -94,23 +96,17 @@ CREATE TABLE t1 (a VARCHAR(100), b INT AUTO_INCREMENT PRIMARY KEY); eval CHANGE MASTER TO MASTER_DELAY = $time2; --enable_query_log ---echo # Checking that delay is what we set it to ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) -if (`SELECT $delay != $time2`) { - --echo Delay is wrong! Expected $time2, got $delay - --source include/show_rpl_debug_info.inc - --die wrong delay -} - ---echo # Expect status to be '' -SELECT STATE FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY ID DESC LIMIT 1; - --source include/start_slave.inc +--let $assert_text= SHOW SLAVE STATUS should return the same delay that we set with CHANGE MASTER +--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = $time2 +--source include/rpl_assert.inc + --echo [on master] --connection master -INSERT INTO t1(a) VALUES ('normal setup'); +INSERT INTO t1 VALUES ('normal setup', 1); +--let $query_number= 1 --source extra/rpl_tests/delayed_slave_wait_on_query.inc @@ -124,20 +120,24 @@ INSERT INTO t1(a) VALUES ('normal setup'); --eval CREATE FUNCTION delay_on_slave(time_units INT) RETURNS INT BEGIN IF @@GLOBAL.server_id = 2 THEN RETURN SLEEP(time_units * $time1); ELSE RETURN 0; END IF; END --enable_query_log -INSERT INTO t1(a) SELECT delay_on_slave(3); +INSERT INTO t1 SELECT delay_on_slave(3), 2; --save_master_pos -INSERT INTO t1(a) VALUES ('slave is already lagging: this statement should execute immediately'); -INSERT INTO t1(a) SELECT delay_on_slave(2); +INSERT INTO t1 VALUES ('slave is already lagging: this statement should execute immediately', 3); +INSERT INTO t1 SELECT delay_on_slave(2), 4; --echo [on slave] --source include/sync_slave_io_with_master.inc --echo # sleep 1*T --sleep $time1 ---echo # Expect no query executed and status is 'Waiting until MASTER_DELAY...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= No query executed +--let $assert_cond= MAX(b) = 1 FROM t1 +--source include/rpl_assert.inc + +--let $assert_text= Status should be 'Waiting until MASTER_DELAY...' +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%" +--source include/rpl_assert.inc --echo # wait for first query to execute --sync_with_master @@ -145,27 +145,35 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1; --echo # sleep 1*T --sleep $time1 ---echo # Expect second query executed and status is executing third query (i.e., 'User sleep') -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Second query executed +--let $assert_cond= MAX(b) = 3 FROM t1 +--source include/rpl_assert.inc + +--let $assert_text= Status should be executing third query (i.e., 'User sleep') +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = "User sleep" +--source include/rpl_assert.inc --echo # sleep 2*T --sleep $time2 ---echo # Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Third query executed +--let $assert_cond= MAX(b) = 4 FROM t1 +--source include/rpl_assert.inc + +--let $assert_text= Status should be 'Has read all relay log...' +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%" +--source include/rpl_assert.inc --echo ==== Seconds_Behind_Master ==== --echo # Bring slave to sync. --source include/stop_slave.inc -eval CHANGE MASTER TO MASTER_DELAY = 0; +CHANGE MASTER TO MASTER_DELAY = 0; --source include/start_slave.inc --connection master -INSERT INTO t1(a) VALUES ('Syncing slave'); +INSERT INTO t1 VALUES ('Syncing slave', 5); --sync_slave_with_master --source include/stop_slave.inc @@ -176,38 +184,28 @@ eval CHANGE MASTER TO MASTER_DELAY = $time2; --source include/start_slave.inc --connection master -INSERT INTO t1(a) VALUES (delay_on_slave(1)); +INSERT INTO t1 VALUES (delay_on_slave(1), 6); --save_master_pos --connection slave --echo # sleep 1*T --sleep $time1 -if ($bug_53167_is_fixed) { - ---let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1) -if (`SELECT $seconds_behind_master <= 0 OR $seconds_behind_master >= $time2`) { - --echo Seconds_Behind_Master was $seconds_behind_master. Expected that 0 < Seconds_Behind_Master < SQL_Delay = $time2 - --source include/show_rpl_debug_info.inc - --die Seconds_Behind_Master was wrong -} - -} +--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] >= 0 AND <1> < $time2 +--let $assert_text= Seconds_Behind_Master should be between 0 and the 2*T +--source include/rpl_assert.inc --echo # sleep 1*T --sleep $time1 ---let $seconds_behind_master= query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1) -if (`SELECT $seconds_behind_master < $time2`) { - --echo Seconds_Behind_Master was $seconds_behind_master. Expected it to be >= SQL_Delay = $time2 - --source include/show_rpl_debug_info.inc - --die Seconds_Behind_Master was < SQL_Delay -} +--let $assert_cond= [SHOW SLAVE STATUS, Seconds_Behind_Master, 1] >= $time2 +--let $assert_text= Seconds_Behind_Master should be at least 2*T +--source include/rpl_assert.inc --sync_with_master ---echo ==== STOP SLAVE and START SLAVE ==== +--echo ==== STOP SLAVE / START SLAVE + DML ==== # Set up a longer delay. --source include/stop_slave.inc @@ -219,71 +217,141 @@ eval CHANGE MASTER TO MASTER_DELAY = $time3; --source include/start_slave.inc ---echo # Checking that delay is what we set it to ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) -if (`SELECT $delay != $time3`) { - --echo Delay is wrong! Expected $time2, got $delay - --source include/show_rpl_debug_info.inc - --die wrong delay -} - --echo [on master] --connection master -INSERT INTO t1(a) VALUES ('stop slave and start slave'); +INSERT INTO t1 VALUES ('stop slave and start slave: DML', 7); --echo [on slave] --connection slave --echo # sleep 1*T --sleep $time1 -SET @before_stop_slave= UNIX_TIMESTAMP(); +--let $timestamp_before_stop= `SELECT UNIX_TIMESTAMP()` +--let $relay_log_pos_before_stop= query_get_value(SHOW SLAVE STATUS, Relay_Log_Pos, 1) --source include/stop_slave.inc -if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`) -{ - --source include/show_rpl_debug_info.inc - --die STOP SLAVE did not finish in time -} ---echo # STOP SLAVE finished in time. ---echo # Expect query not executed and status is '' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish +--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1 +--source include/rpl_assert.inc + +--let $assert_text= SQL thread position should not increase after STOP SLAVE +--let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] = $relay_log_pos_before_stop +--source include/rpl_assert.inc + +--let $assert_text= Query should not be executed after STOP SLAVE +--let $assert_cond= MAX(b) = 6 FROM t1 +--source include/rpl_assert.inc + +--let $assert_text= Status should be '' after STOP SLAVE +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = "" +--source include/rpl_assert.inc --source include/start_slave.inc -if (`SELECT UNIX_TIMESTAMP() - @before_stop_slave >= $time1`) -{ - --source include/show_rpl_debug_info.inc - --die START SLAVE did not finish in time -} ---echo # START SLAVE finished in time. +--let $assert_text= START SLAVE should finish quickly +--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1 +--source include/rpl_assert.inc + +--let $query_number= 7 --source extra/rpl_tests/delayed_slave_wait_on_query.inc +--echo ==== STOP SLAVE / START SLAVE + DDL ==== + +--echo This verifies BUG#56442 + +--echo [on master] +--connection master +CREATE TABLE t_check_dml_not_executed_prematurely (a INT); +--source include/save_master_pos.inc + +--echo [on slave] +--connection slave +--echo # sleep 1*T +--sleep $time1 + +--let $timestamp_before_stop= `SELECT UNIX_TIMESTAMP()` +--let $relay_log_pos_before_stop= query_get_value(SHOW SLAVE STATUS, Relay_Log_Pos, 1) +--source include/stop_slave.inc + +--let $assert_text= STOP SLAVE should finish quickly, not wait for the ongoing sleep to finish +--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1 +--source include/rpl_assert.inc + +--let $assert_text= SQL thread position should not increase after STOP SLAVE +--let $assert_cond= [SHOW SLAVE STATUS, Relay_Log_Pos, 1] = $relay_log_pos_before_stop +--source include/rpl_assert.inc + +--let $assert_text= Query should not be executed after STOP SLAVE +--let $assert_cond= COUNT(*) = 0 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely" +--source include/rpl_assert.inc + +--let $assert_text= Status should be '' after STOP SLAVE +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = "" +--source include/rpl_assert.inc + +--source include/start_slave.inc + +--let $assert_text= START SLAVE should finish quickly +--let $assert_cond= UNIX_TIMESTAMP() - $timestamp_before_stop < $time1 +--source include/rpl_assert.inc + +--echo # sleep 1*T +--sleep $time1 + +--let $assert_text= DDL Query should not be executed after START SLAVE +--let $assert_cond= COUNT(*) = 0 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely" +--source include/rpl_assert.inc + +--let $assert_text= Status should be 'Waiting until MASTER_DELAY...' +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Waiting until MASTER_DELAY%" +--source include/rpl_assert.inc + +--echo # sleep 1*T +--sleep $time1 + +--echo # sync with master (with timeout 1*T) +--source include/sync_with_master.inc + +--let $assert_text= DDL Query should be executed +--let $assert_cond= COUNT(*) = 1 FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = "t_check_dml_not_executed_prematurely" +--source include/rpl_assert.inc + +--let $assert_text= Status should be 'Has read all relay log...' +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" LIKE "Slave has read all relay log%" +--source include/rpl_assert.inc + +--source include/check_slave_is_running.inc + + --echo ==== Change back to no delay ==== --echo [on slave] --connection slave --source include/stop_slave.inc -eval CHANGE MASTER TO MASTER_DELAY = 0; +CHANGE MASTER TO MASTER_DELAY = 0; ---echo # Expect delay is 0. ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) ---echo SQL_Delay='$delay' +--let $assert_text= Delay should be 0 when we set it to 0 +--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 0 +--source include/rpl_assert.inc --source include/start_slave.inc --echo [on master] --connection master -INSERT INTO t1(a) VALUES ('change back to no delay'); +INSERT INTO t1 VALUES ('change back to no delay', 8); --echo [on slave] --source include/sync_slave_io_with_master.inc --echo # sleep 1*T --sleep $time1 ---echo # Expect query executed and status is 'Has read all relay log...' -SELECT * FROM t1 ORDER BY b DESC LIMIT 1; ---source include/show_delayed_slave_state.inc +--let $assert_text= Query should be executed +--let $assert_cond= MAX(b) = 8 FROM t1 +--source include/rpl_assert.inc + +--let $assert_text= Status should be 'Slave has read all relay log...' +--let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" Like "Slave has read all relay log%" +--source include/rpl_assert.inc --echo ==== Reset delay with RESET SLAVE ==== @@ -292,9 +360,9 @@ SELECT * FROM t1 ORDER BY b DESC LIMIT 1; CHANGE MASTER TO MASTER_DELAY = 71; --source include/start_slave.inc ---echo # Expect delay is 71 ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) ---echo SQL_Delay='$delay' +--let $assert_text= Delay should be 71 when we set it to 71 +--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 71 +--source include/rpl_assert.inc --source include/stop_slave.inc RESET SLAVE; @@ -305,12 +373,12 @@ RESET MASTER; --connection slave --source include/start_slave.inc ---echo # Expect delay is 0 ---let $delay= query_get_value(SHOW SLAVE STATUS, SQL_Delay, 1) ---echo SQL_Delay='$delay' +--let $assert_text= Delay should be 0 after RESET SLAVE +--let $assert_cond= [SHOW SLAVE STATUS, SQL_Delay, 1] = 0 +--source include/rpl_assert.inc ---echo ==== Set a bad value for the delay ==== +--echo ==== Set an invalid value for the delay ==== --source include/stop_slave.inc @@ -339,7 +407,7 @@ CHANGE MASTER TO MASTER_DELAY = 0; --echo [on master] --connection master -DROP TABLE t1; +DROP TABLE t1, t_check_dml_not_executed_prematurely; DROP FUNCTION delay_on_slave; --echo [on slave] diff --git a/sql/slave.cc b/sql/slave.cc index 813827e883f..a927b7598c6 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -3410,17 +3410,21 @@ has_temporary_error(THD *thd) /** If this is a lagging slave (specified with CHANGE MASTER TO MASTER_DELAY = X), delays accordingly. Also unlocks rli->data_lock. - Design note: this is the place to unlock rli->data_lock here since - it should be held when reading delay info from rli, but it should - not be held while sleeping. + Design note: this is the place to unlock rli->data_lock. The lock + must be held when reading delay info from rli, but it should not be + held while sleeping. @param ev Event that is about to be executed. @param thd The sql thread's THD object. @param rli The sql thread's Relay_log_info structure. + + @retval 0 If the delay timed out and the event shall be executed. + + @retval nonzero If the delay was interrupted and the event shall be skipped. */ -static void sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) +static int sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) { Relay_log_info* rli= rgi->rli; long sql_delay= rli->get_sql_delay(); @@ -3459,14 +3463,13 @@ static void sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) nap_time)); rli->start_sql_delay(sql_delay_end); mysql_mutex_unlock(&rli->data_lock); - slave_sleep(thd, nap_time, sql_slave_killed, rgi); - DBUG_VOID_RETURN; + DBUG_RETURN(slave_sleep(thd, nap_time, sql_slave_killed, rgi)); } } mysql_mutex_unlock(&rli->data_lock); - DBUG_VOID_RETURN; + DBUG_RETURN(0); } @@ -3696,7 +3699,8 @@ apply_event_and_update_pos(Log_event* ev, THD* thd, rpl_group_info *rgi) if (reason == Log_event::EVENT_SKIP_NOT) { // Sleeps if needed, and unlocks rli->data_lock. - sql_delay_event(ev, thd, rgi); + if (sql_delay_event(ev, thd, rgi)) + return 0; } else mysql_mutex_unlock(&rli->data_lock); From 09136ec30484deb97db548ca2b079b9e26cef8cf Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Fri, 14 Oct 2016 11:33:45 +0200 Subject: [PATCH 12/52] MDEV-7145, Delayed slave. Only run testcase in --big. It takes a long time due to excessive sleeps. Signed-off-by: Kristian Nielsen --- mysql-test/suite/rpl/t/rpl_delayed_slave.test | 2 ++ 1 file changed, 2 insertions(+) diff --git a/mysql-test/suite/rpl/t/rpl_delayed_slave.test b/mysql-test/suite/rpl/t/rpl_delayed_slave.test index 3e6f5564bf2..e34c46a460c 100644 --- a/mysql-test/suite/rpl/t/rpl_delayed_slave.test +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave.test @@ -53,6 +53,8 @@ # # The test takes a long time; it sleeps for around 20*10 seconds. +--source include/big_test.inc +--source include/not_valgrind.inc --source include/master-slave.inc # Needed so that sleeps get executed in the slave SQL thread. --source include/have_binlog_format_statement.inc From 3011060b2ab8b56a5c1c69695de6041b80a663b7 Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Fri, 14 Oct 2016 12:22:00 +0200 Subject: [PATCH 13/52] MDEV-7145: Delayed slave. Extend to work also for parallel replication. Signed-off-by: Kristian Nielsen --- sql/rpl_parallel.cc | 13 +++++++++++-- sql/slave.cc | 3 ++- sql/slave.h | 1 + 3 files changed, 14 insertions(+), 3 deletions(-) diff --git a/sql/rpl_parallel.cc b/sql/rpl_parallel.cc index c507a132374..cbba2e6662e 100644 --- a/sql/rpl_parallel.cc +++ b/sql/rpl_parallel.cc @@ -2418,8 +2418,17 @@ rpl_parallel::do_event(rpl_group_info *serial_rgi, Log_event *ev, !(unlikely(rli->gtid_skip_flag != GTID_SKIP_NOT) && is_group_event)) return -1; - /* ToDo: what to do with this lock?!? */ - mysql_mutex_unlock(&rli->data_lock); + /* Note: rli->data_lock is released by sql_delay_event(). */ + if (sql_delay_event(ev, rli->sql_driver_thd, serial_rgi)) + { + /* + If sql_delay_event() returns non-zero, it means that the wait timed out + due to slave stop. We should not queue the event in this case, it must + not be applied yet. + */ + delete ev; + return 1; + } if (unlikely(typ == FORMAT_DESCRIPTION_EVENT)) { diff --git a/sql/slave.cc b/sql/slave.cc index a927b7598c6..8a861a3ad7d 100644 --- a/sql/slave.cc +++ b/sql/slave.cc @@ -3424,7 +3424,8 @@ has_temporary_error(THD *thd) @retval nonzero If the delay was interrupted and the event shall be skipped. */ -static int sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) +int +sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi) { Relay_log_info* rli= rgi->rli; long sql_delay= rli->get_sql_delay(); diff --git a/sql/slave.h b/sql/slave.h index 11015ac2db0..4b9e04084d2 100644 --- a/sql/slave.h +++ b/sql/slave.h @@ -251,6 +251,7 @@ void set_slave_thread_options(THD* thd); void set_slave_thread_default_charset(THD *thd, rpl_group_info *rgi); int rotate_relay_log(Master_info* mi); int has_temporary_error(THD *thd); +int sql_delay_event(Log_event *ev, THD *thd, rpl_group_info *rgi); int apply_event_and_update_pos(Log_event* ev, THD* thd, struct rpl_group_info *rgi); int apply_event_and_update_pos_for_parallel(Log_event* ev, THD* thd, From fb13616518975b84eea9b9e0d5a91122bb1abe7a Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Fri, 14 Oct 2016 21:29:35 +0200 Subject: [PATCH 14/52] MDEV-7145: Delayed replication. Add test cases for delayed slave with parallel replication. Signed-off-by: Kristian Nielsen --- .../rpl/r/rpl_delayed_slave,parallel.rdiff | 17 +++++ .../suite/rpl/r/rpl_delayed_slave.result | 6 ++ .../suite/rpl/r/rpl_delayed_slave2.result | 52 +++++++++++++++ .../rpl/t/rpl_delayed_slave.combinations | 5 ++ mysql-test/suite/rpl/t/rpl_delayed_slave.test | 12 +++- .../suite/rpl/t/rpl_delayed_slave2.test | 65 +++++++++++++++++++ 6 files changed, 154 insertions(+), 3 deletions(-) create mode 100644 mysql-test/suite/rpl/r/rpl_delayed_slave,parallel.rdiff create mode 100644 mysql-test/suite/rpl/r/rpl_delayed_slave2.result create mode 100644 mysql-test/suite/rpl/t/rpl_delayed_slave.combinations create mode 100644 mysql-test/suite/rpl/t/rpl_delayed_slave2.test diff --git a/mysql-test/suite/rpl/r/rpl_delayed_slave,parallel.rdiff b/mysql-test/suite/rpl/r/rpl_delayed_slave,parallel.rdiff new file mode 100644 index 00000000000..aaadbb28ca3 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_delayed_slave,parallel.rdiff @@ -0,0 +1,17 @@ +--- mysql-test/suite/rpl/r/rpl_delayed_slave.result 2016-10-14 21:14:02.338075590 +0200 ++++ mysql-test/suite/rpl/r/rpl_delayed_slave,parallel.reject 2016-10-14 21:17:51.296986686 +0200 +@@ -45,7 +45,6 @@ + # wait for first query to execute + # sleep 1*T + # Asserted this: Second query executed +-# Asserted this: Status should be executing third query (i.e., 'User sleep') + # sleep 2*T + # Asserted this: Third query executed + # Asserted this: Status should be 'Has read all relay log...' +@@ -167,5 +166,5 @@ + conservative + SELECT @@GLOBAL.slave_parallel_threads; + @@GLOBAL.slave_parallel_threads +-0 ++10 + include/rpl_end.inc diff --git a/mysql-test/suite/rpl/r/rpl_delayed_slave.result b/mysql-test/suite/rpl/r/rpl_delayed_slave.result index 1aad398bbc9..4dd4d6601e5 100644 --- a/mysql-test/suite/rpl/r/rpl_delayed_slave.result +++ b/mysql-test/suite/rpl/r/rpl_delayed_slave.result @@ -162,4 +162,10 @@ include/start_slave.inc DROP TABLE t1, t_check_dml_not_executed_prematurely; DROP FUNCTION delay_on_slave; [on slave] +SELECT @@GLOBAL.slave_parallel_mode; +@@GLOBAL.slave_parallel_mode +conservative +SELECT @@GLOBAL.slave_parallel_threads; +@@GLOBAL.slave_parallel_threads +0 include/rpl_end.inc diff --git a/mysql-test/suite/rpl/r/rpl_delayed_slave2.result b/mysql-test/suite/rpl/r/rpl_delayed_slave2.result new file mode 100644 index 00000000000..efc9769520c --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_delayed_slave2.result @@ -0,0 +1,52 @@ +include/master-slave.inc +[connection master] +ALTER TABLE mysql.gtid_slave_pos ENGINE=InnoDB; +CREATE TABLE t1 (a INT PRIMARY KEY, b VARCHAR(100)); +INSERT INTO t1 VALUES (1, "a"); +include/stop_slave.inc +CHANGE MASTER TO master_use_gtid=slave_pos; +SET @old_mode= @@GLOBAL.slave_parallel_mode; +SET GLOBAL slave_parallel_mode=optimistic; +SET @old_threads= @@GLOBAL.slave_parallel_threads; +SET GLOBAL slave_parallel_threads=10; +INSERT INTO t1 VALUES (2, "b"); +INSERT INTO t1 VALUES (3, "b"); +INSERT INTO t1 VALUES (4, "b"); +SET timestamp= @@timestamp + 24*60*60; +INSERT INTO t1 VALUES (5, "c"); +INSERT INTO t1 VALUES (6, "c"); +SET timestamp= 0; +include/save_master_gtid.inc +CHANGE MASTER TO master_delay=1; +include/start_slave.inc +SELECT MASTER_GTID_WAIT('GTID1'); +MASTER_GTID_WAIT('GTID1') +0 +SELECT MASTER_GTID_WAIT('GTID2', 2); +MASTER_GTID_WAIT('GTID2', 2) +-1 +include/stop_slave.inc +SELECT * FROM t1 ORDER BY a; +a b +1 a +2 b +3 b +4 b +CHANGE MASTER TO master_delay=0; +include/start_slave.inc +include/sync_with_master_gtid.inc +SELECT * FROM t1 ORDER BY a; +a b +1 a +2 b +3 b +4 b +5 c +6 c +include/stop_slave.inc +CHANGE MASTER TO master_use_gtid=no, master_delay=0; +SET GLOBAL slave_parallel_mode=@old_mode; +SET GLOBAL slave_parallel_threads=@old_threads; +include/start_slave.inc +DROP TABLE t1; +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_delayed_slave.combinations b/mysql-test/suite/rpl/t/rpl_delayed_slave.combinations new file mode 100644 index 00000000000..8adc75e834f --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave.combinations @@ -0,0 +1,5 @@ +[nonparallel] + +[parallel] +--slave-parallel-mode=conservative +--slave-parallel-threads=10 diff --git a/mysql-test/suite/rpl/t/rpl_delayed_slave.test b/mysql-test/suite/rpl/t/rpl_delayed_slave.test index e34c46a460c..2400a821e2b 100644 --- a/mysql-test/suite/rpl/t/rpl_delayed_slave.test +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave.test @@ -151,9 +151,13 @@ INSERT INTO t1 SELECT delay_on_slave(2), 4; --let $assert_cond= MAX(b) = 3 FROM t1 --source include/rpl_assert.inc ---let $assert_text= Status should be executing third query (i.e., 'User sleep') ---let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = "User sleep" ---source include/rpl_assert.inc +let $parallel= `SELECT @@GLOBAL.slave_parallel_threads`; +if (!$parallel) +{ + let $assert_text= Status should be executing third query (i.e., 'User sleep'); + let $assert_cond= "[SHOW SLAVE STATUS, Slave_SQL_Running_State, 1]" = "User sleep"; + source include/rpl_assert.inc; +} --echo # sleep 2*T --sleep $time2 @@ -414,5 +418,7 @@ DROP FUNCTION delay_on_slave; --echo [on slave] --sync_slave_with_master +SELECT @@GLOBAL.slave_parallel_mode; +SELECT @@GLOBAL.slave_parallel_threads; --source include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/rpl_delayed_slave2.test b/mysql-test/suite/rpl/t/rpl_delayed_slave2.test new file mode 100644 index 00000000000..68e8f8e1c46 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_delayed_slave2.test @@ -0,0 +1,65 @@ +--source include/have_innodb.inc +--source include/master-slave.inc + +# This test file tests delayed slave for parallel replication (and GTID). +# Uses a different approach from rpl_delayed_slave.test, setting @@timestamp +# to simulate events logged on master at different times. + +--connection master +ALTER TABLE mysql.gtid_slave_pos ENGINE=InnoDB; +CREATE TABLE t1 (a INT PRIMARY KEY, b VARCHAR(100)); +INSERT INTO t1 VALUES (1, "a"); +--save_master_pos + +--connection slave +--sync_with_master +--source include/stop_slave.inc +CHANGE MASTER TO master_use_gtid=slave_pos; +SET @old_mode= @@GLOBAL.slave_parallel_mode; +SET GLOBAL slave_parallel_mode=optimistic; +SET @old_threads= @@GLOBAL.slave_parallel_threads; +SET GLOBAL slave_parallel_threads=10; + +--connection master +INSERT INTO t1 VALUES (2, "b"); +INSERT INTO t1 VALUES (3, "b"); +INSERT INTO t1 VALUES (4, "b"); +--let $gtid1= `SELECT @@gtid_binlog_pos` +# Simulate an event a days in the future, for delayed slave to wait on. +SET timestamp= @@timestamp + 24*60*60; +INSERT INTO t1 VALUES (5, "c"); +INSERT INTO t1 VALUES (6, "c"); +SET timestamp= 0; +--let $gtid2= `SELECT @@gtid_binlog_pos` +--source include/save_master_gtid.inc + +--connection slave +CHANGE MASTER TO master_delay=1; +--source include/start_slave.inc +--replace_result $gtid1 GTID1 +# First sync halfways, to avoid timing-dependent test failures. +eval SELECT MASTER_GTID_WAIT('$gtid1'); +# Try to sync up, should timeout because slave is waiting for one day. +--replace_result $gtid2 GTID2 +eval SELECT MASTER_GTID_WAIT('$gtid2', 2); + +# Check that we can stop slave while delaying. +--source include/stop_slave.inc +SELECT * FROM t1 ORDER BY a; +CHANGE MASTER TO master_delay=0; +--source include/start_slave.inc +--source include/sync_with_master_gtid.inc +SELECT * FROM t1 ORDER BY a; + + +--connection slave +--source include/stop_slave.inc +CHANGE MASTER TO master_use_gtid=no, master_delay=0; +SET GLOBAL slave_parallel_mode=@old_mode; +SET GLOBAL slave_parallel_threads=@old_threads; +--source include/start_slave.inc + +--connection master +DROP TABLE t1; + +--source include/rpl_end.inc From 057c560ee45c61d172ed0ed762b0b33b37349e5c Mon Sep 17 00:00:00 2001 From: Vladislav Vaintroub Date: Sat, 15 Oct 2016 02:27:28 +0200 Subject: [PATCH 15/52] MDEV-10943 . Workaround linker error on Linux. Linux does not actually use __bss_start, put __bss_start into #ifndef __linux__ section --- mysys/stacktrace.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/mysys/stacktrace.c b/mysys/stacktrace.c index 395659238b3..e22fb4162ec 100644 --- a/mysys/stacktrace.c +++ b/mysys/stacktrace.c @@ -38,13 +38,13 @@ static char *heap_start; -#ifdef HAVE_BSS_START +#if(defined HAVE_BSS_START) && !(defined __linux__) extern char *__bss_start; #endif void my_init_stacktrace() { -#ifdef HAVE_BSS_START +#if(defined HAVE_BSS_START) && !(defined __linux__) heap_start = (char*) &__bss_start; #endif } From 4d3e3669ec1dc0352b7da90f8bdb69963f4b90f4 Mon Sep 17 00:00:00 2001 From: Elena Stepanova Date: Mon, 17 Oct 2016 00:59:02 +0300 Subject: [PATCH 16/52] MDEV-11061 Valgrind builder produces warnings with OpenSSL --- mysql-test/valgrind.supp | 120 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 120 insertions(+) diff --git a/mysql-test/valgrind.supp b/mysql-test/valgrind.supp index b2b264e17fa..cfd7f23ed2b 100644 --- a/mysql-test/valgrind.supp +++ b/mysql-test/valgrind.supp @@ -1451,3 +1451,123 @@ g codership/mysql-wsrep/issues#176 fun:start_thread fun:clone } + +# +# MDEV-11061: OpenSSL 0.9.8 problems +# + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Cond + obj:*/libz.so* + ... + obj:*/libcrypto.so.0.9.8 + ... + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Value8 + obj:*/libz.so* + ... + obj:*/libcrypto.so.0.9.8 + ... + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Cond + obj:*/libcrypto.so.0.9.8 + ... + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Value8 + obj:*/libcrypto.so.0.9.8 + ... + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Cond + obj:*/libssl.so.0.9.8 + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Value8 + obj:*/libssl.so.0.9.8 + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Cond + fun:memcpy + obj:*/libcrypto.so.0.9.8 + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Value8 + fun:memcpy + obj:*/libcrypto.so.0.9.8 + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Cond + fun:is_overlap + fun:memcpy + obj:*/libcrypto.so.0.9.8 + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Cond + fun:memset + obj:*/libcrypto.so.0.9.8 + ... + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Value8 + fun:memset + obj:*/libcrypto.so.0.9.8 + ... + obj:*/libssl.so.0.9.8 + ... +} + +{ + MDEV-11061: OpenSSL 0.9.8 + Memcheck:Param + write(buf) + obj:*/libpthread-2.9.so* + obj:*/libcrypto.so.0.9.8 + ... + obj:*/libssl.so.0.9.8 + ... +} + From cc49f00994aa9fc4698d1ca88414e533258b5cf3 Mon Sep 17 00:00:00 2001 From: Kristian Nielsen Date: Mon, 17 Oct 2016 12:52:14 +0200 Subject: [PATCH 17/52] Move InnoDB/XtraDB to async deadlock kill for parallel replication. In 10.2, use the thd_rpl_deadlock_check() API. This way, all the locking hacks around thd_report_wait_for() can be removed. Now parallel replication deadlock kill happens asynchroneously, from the slave background thread. In InnoDB, remove also the buffering of wait reports, to simplify the code, as this is no longer needed when the locking issues are gone. In XtraDB, the buffering is kept for now. This is just because presumably XtraDB will eventually be updated to MySQL 5.7-based InnoDB as well, so there is little need to modify the existing code only for clean-up purposes. The old synchronous function thd_report_wait_for() is no longer used and removed in this patch. Signed-off-by: Kristian Nielsen --- sql/sql_class.cc | 99 ++++----------------- storage/innobase/handler/ha_innodb.cc | 3 +- storage/innobase/include/trx0trx.h | 3 +- storage/innobase/lock/lock0lock.cc | 121 +++----------------------- storage/xtradb/handler/ha_innodb.cc | 6 +- storage/xtradb/include/trx0trx.h | 3 +- storage/xtradb/lock/lock0lock.cc | 17 ++-- 7 files changed, 41 insertions(+), 211 deletions(-) diff --git a/sql/sql_class.cc b/sql/sql_class.cc index 6433786a079..1af3b9a9cca 100644 --- a/sql/sql_class.cc +++ b/sql/sql_class.cc @@ -4598,19 +4598,20 @@ extern "C" int thd_rpl_is_parallel(const MYSQL_THD thd) } /* - This function can optionally be called to check if thd_report_wait_for() + This function can optionally be called to check if thd_rpl_deadlock_check() needs to be called for waits done by a given transaction. - If this function returns false for a given thd, there is no need to do any - calls to thd_report_wait_for() on that thd. + If this function returns false for a given thd, there is no need to do + any calls to thd_rpl_deadlock_check() on that thd. - This call is optional; it is safe to call thd_report_wait_for() in any case. - This call can be used to save some redundant calls to thd_report_wait_for() - if desired. (This is unlikely to matter much unless there are _lots_ of - waits to report, as the overhead of thd_report_wait_for() is small). + This call is optional; it is safe to call thd_rpl_deadlock_check() in + any case. This call can be used to save some redundant calls to + thd_rpl_deadlock_check() if desired. (This is unlikely to matter much + unless there are _lots_ of waits to report, as the overhead of + thd_rpl_deadlock_check() is small). */ extern "C" int -thd_need_wait_for(const MYSQL_THD thd) +thd_need_wait_reports(const MYSQL_THD thd) { rpl_group_info *rgi; @@ -4625,75 +4626,9 @@ thd_need_wait_for(const MYSQL_THD thd) } /* - Used by InnoDB/XtraDB to report that one transaction THD is about to go to - wait for a transactional lock held by another transactions OTHER_THD. - - This is used for parallel replication, where transactions are required to - commit in the same order on the slave as they did on the master. If the - transactions on the slave encounters lock conflicts on the slave that did - not exist on the master, this can cause deadlocks. - - Normally, such conflicts will not occur, because the same conflict would - have prevented the two transactions from committing in parallel on the - master, thus preventing them from running in parallel on the slave in the - first place. However, it is possible in case when the optimizer chooses a - different plan on the slave than on the master (eg. table scan instead of - index scan). - - InnoDB/XtraDB reports lock waits using this call. If a lock wait causes a - deadlock with the pre-determined commit order, we kill the later transaction, - and later re-try it, to resolve the deadlock. - - This call need only receive reports about waits for locks that will remain - until the holding transaction commits. InnoDB/XtraDB auto-increment locks - are released earlier, and so need not be reported. (Such false positives are - not harmful, but could lead to unnecessary kill and retry, so best avoided). -*/ -extern "C" void -thd_report_wait_for(MYSQL_THD thd, MYSQL_THD other_thd) -{ - rpl_group_info *rgi; - rpl_group_info *other_rgi; - - if (!thd) - return; - DEBUG_SYNC(thd, "thd_report_wait_for"); - thd->transaction.stmt.mark_trans_did_wait(); - if (!other_thd) - return; - binlog_report_wait_for(thd, other_thd); - rgi= thd->rgi_slave; - other_rgi= other_thd->rgi_slave; - if (!rgi || !other_rgi) - return; - if (!rgi->is_parallel_exec) - return; - if (rgi->rli != other_rgi->rli) - return; - if (!rgi->gtid_sub_id || !other_rgi->gtid_sub_id) - return; - if (rgi->current_gtid.domain_id != other_rgi->current_gtid.domain_id) - return; - if (rgi->gtid_sub_id > other_rgi->gtid_sub_id) - return; - /* - This transaction is about to wait for another transaction that is required - by replication binlog order to commit after. This would cause a deadlock. - - So send a kill to the other transaction, with a temporary error; this will - cause replication to rollback (and later re-try) the other transaction, - releasing the lock for this transaction so replication can proceed. - */ - other_rgi->killed_for_retry= rpl_group_info::RETRY_KILL_KILLED; - mysql_mutex_lock(&other_thd->LOCK_thd_data); - other_thd->awake(KILL_CONNECTION); - mysql_mutex_unlock(&other_thd->LOCK_thd_data); -} - -/* - Used by storage engines (currently TokuDB) to report that one transaction - THD is about to go to wait for a transactional lock held by another - transactions OTHER_THD. + Used by storage engines (currently TokuDB and InnoDB/XtraDB) to report that + one transaction THD is about to go to wait for a transactional lock held by + another transactions OTHER_THD. This is used for parallel replication, where transactions are required to commit in the same order on the slave as they did on the master. If the @@ -4708,9 +4643,9 @@ thd_report_wait_for(MYSQL_THD thd, MYSQL_THD other_thd) chooses a different plan on the slave than on the master (eg. table scan instead of index scan). - InnoDB/XtraDB reports lock waits using this call. If a lock wait causes a - deadlock with the pre-determined commit order, we kill the later transaction, - and later re-try it, to resolve the deadlock. + Storage engines report lock waits using this call. If a lock wait causes a + deadlock with the pre-determined commit order, we kill the later + transaction, and later re-try it, to resolve the deadlock. This call need only receive reports about waits for locks that will remain until the holding transaction commits. InnoDB/XtraDB auto-increment locks, @@ -4801,8 +4736,8 @@ thd_rpl_deadlock_check(MYSQL_THD thd, MYSQL_THD other_thd) Calling this function is just an optimisation to avoid unnecessary deadlocks. If it was not used, a gap lock would be set that could eventually - cause a deadlock; the deadlock would be caught by thd_report_wait_for() and - the transaction T2 killed and rolled back (and later re-tried). + cause a deadlock; the deadlock would be caught by thd_rpl_deadlock_check() + and the transaction T2 killed and rolled back (and later re-tried). */ extern "C" int thd_need_ordering_with(const MYSQL_THD thd, const MYSQL_THD other_thd) diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc index 604beec6f78..7734eb162fb 100644 --- a/storage/innobase/handler/ha_innodb.cc +++ b/storage/innobase/handler/ha_innodb.cc @@ -5685,8 +5685,7 @@ innobase_kill_query( wsrep_thd_is_BF(current_thd, FALSE)); } - if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE) && - trx->abort_type == TRX_SERVER_ABORT) { + if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE)) { ut_ad(!lock_mutex_own()); lock_mutex_enter(); lock_mutex_taken = true; diff --git a/storage/innobase/include/trx0trx.h b/storage/innobase/include/trx0trx.h index 839c3d057e7..42d59cb396f 100644 --- a/storage/innobase/include/trx0trx.h +++ b/storage/innobase/include/trx0trx.h @@ -842,8 +842,7 @@ lock_sys->mutex and sometimes by trx->mutex. */ typedef enum { TRX_SERVER_ABORT = 0, - TRX_WSREP_ABORT = 1, - TRX_REPLICATION_ABORT = 2 + TRX_WSREP_ABORT = 1 } trx_abort_t; diff --git a/storage/innobase/lock/lock0lock.cc b/storage/innobase/lock/lock0lock.cc index 8f65966f1cb..6adb1c99041 100644 --- a/storage/innobase/lock/lock0lock.cc +++ b/storage/innobase/lock/lock0lock.cc @@ -70,15 +70,8 @@ static const ulint TABLE_LOCK_CACHE = 8; /** Size in bytes, of the table lock instance */ static const ulint TABLE_LOCK_SIZE = sizeof(ib_lock_t); -/* Buffer to collect THDs to report waits for. */ -struct thd_wait_reports { - struct thd_wait_reports *next; /*!< List link */ - ulint used; /*!< How many elements in waitees[] */ - trx_t *waitees[64]; /*!< Trxs for thd_report_wait_for() */ -}; - -extern "C" void thd_report_wait_for(MYSQL_THD thd, MYSQL_THD other_thd); -extern "C" int thd_need_wait_for(const MYSQL_THD thd); +extern "C" void thd_rpl_deadlock_check(MYSQL_THD thd, MYSQL_THD other_thd); +extern "C" int thd_need_wait_reports(const MYSQL_THD thd); extern "C" int thd_need_ordering_with(const MYSQL_THD thd, const MYSQL_THD other_thd); /** Deadlock checker. */ @@ -109,7 +102,7 @@ private: const trx_t* trx, const lock_t* wait_lock, ib_uint64_t mark_start, - struct thd_wait_reports* waitee_buf_ptr) + bool report_waiters) : m_cost(), m_start(trx), @@ -117,7 +110,7 @@ private: m_wait_lock(wait_lock), m_mark_start(mark_start), m_n_elems(), - m_waitee_ptr(waitee_buf_ptr) + m_report_waiters(report_waiters) { } @@ -276,8 +269,8 @@ private: /** This is to avoid malloc/free calls. */ static state_t s_states[MAX_STACK_SIZE]; - /** Buffer to collect THDs to report waits for. */ - struct thd_wait_reports* m_waitee_ptr; + /** Set if thd_rpl_deadlock_check() should be called for waits. */ + bool m_report_waiters; }; /** Counter to mark visited nodes during deadlock search. */ @@ -286,11 +279,6 @@ ib_uint64_t DeadlockChecker::s_lock_mark_counter = 0; /** The stack used for deadlock searches. */ DeadlockChecker::state_t DeadlockChecker::s_states[MAX_STACK_SIZE]; -extern "C" void thd_report_wait_for(MYSQL_THD thd, MYSQL_THD other_thd); -extern "C" int thd_need_wait_for(const MYSQL_THD thd); -extern "C" -int thd_need_ordering_with(const MYSQL_THD thd, const MYSQL_THD other_thd); - #ifdef UNIV_DEBUG /*********************************************************************//** Validates the lock system. @@ -2074,14 +2062,6 @@ RecLock::add_to_waitq(const lock_t* wait_for, const lock_prdt_t* prdt) dberr_t err = deadlock_check(lock); ut_ad(trx_mutex_own(m_trx)); - - /* m_trx->mysql_thd is NULL if it's an internal trx. So current_thd is used */ - if (err == DB_LOCK_WAIT) { - ut_ad(wait_for && wait_for->trx); - wait_for->trx->abort_type = TRX_REPLICATION_ABORT; - thd_report_wait_for(current_thd, wait_for->trx->mysql_thd); - wait_for->trx->abort_type = TRX_SERVER_ABORT; - } return(err); } @@ -7968,27 +7948,11 @@ DeadlockChecker::search() layer. These locks are released before commit, so they can not cause deadlocks with binlog-fixed commit order. */ - if (m_waitee_ptr && + if (m_report_waiters && (lock_get_type_low(lock) != LOCK_TABLE || lock_get_mode(lock) != LOCK_AUTO_INC)) { - if (m_waitee_ptr->used == - sizeof(m_waitee_ptr->waitees) / - sizeof(m_waitee_ptr->waitees[0])) { - m_waitee_ptr->next = - (struct thd_wait_reports *) - ut_malloc_nokey(sizeof(*m_waitee_ptr)); - m_waitee_ptr = m_waitee_ptr->next; - - if (!m_waitee_ptr) { - m_too_deep = true; - return (m_start); - } - - m_waitee_ptr->next = NULL; - m_waitee_ptr->used = 0; - } - - m_waitee_ptr->waitees[m_waitee_ptr->used++] = lock->trx; + thd_rpl_deadlock_check(m_start->mysql_thd, + lock->trx->mysql_thd); } if (lock->trx->lock.que_state == TRX_QUE_LOCK_WAIT) { @@ -8068,47 +8032,6 @@ DeadlockChecker::trx_rollback() trx_mutex_exit(trx); } -static -void -lock_report_waiters_to_mysql( -/*=======================*/ - struct thd_wait_reports* waitee_buf_ptr, /*!< in: set of trxs */ - THD* mysql_thd, /*!< in: THD */ - const trx_t* victim_trx) /*!< in: Trx selected - as deadlock victim, if - any */ -{ - struct thd_wait_reports* p; - struct thd_wait_reports* q; - ulint i; - - p = waitee_buf_ptr; - while (p) { - i = 0; - while (i < p->used) { - trx_t *w_trx = p->waitees[i]; - /* There is no need to report waits to a trx already - selected as a victim. */ - if (w_trx != victim_trx) { - /* If thd_report_wait_for() decides to kill the - transaction, then we will get a call back into - innobase_kill_query. We mark this by setting - current_lock_mutex_owner, so we can avoid trying - to recursively take lock_sys->mutex. */ - w_trx->abort_type = TRX_REPLICATION_ABORT; - thd_report_wait_for(mysql_thd, w_trx->mysql_thd); - w_trx->abort_type = TRX_SERVER_ABORT; - } - ++i; - } - q = p->next; - if (p != waitee_buf_ptr) { - ut_free(p); - } - p = q; - } -} - /** Checks if a joining lock request results in a deadlock. If a deadlock is found this function will resolve the deadlock by choosing a victim transaction and rolling it back. It will attempt to resolve all deadlocks. The returned @@ -8127,36 +8050,20 @@ DeadlockChecker::check_and_resolve(const lock_t* lock, const trx_t* trx) ut_ad(!srv_read_only_mode); const trx_t* victim_trx; - struct thd_wait_reports waitee_buf; - struct thd_wait_reports*waitee_buf_ptr; - THD* start_mysql_thd; + THD* start_mysql_thd; + bool report_waits = false; start_mysql_thd = trx->mysql_thd; - if (start_mysql_thd && thd_need_wait_for(start_mysql_thd)) { - waitee_buf_ptr = &waitee_buf; - } else { - waitee_buf_ptr = NULL; - } + if (start_mysql_thd && thd_need_wait_reports(start_mysql_thd)) + report_waits = true; /* Try and resolve as many deadlocks as possible. */ do { - if (waitee_buf_ptr) { - waitee_buf_ptr->next = NULL; - waitee_buf_ptr->used = 0; - } - - DeadlockChecker checker(trx, lock, s_lock_mark_counter, waitee_buf_ptr); + DeadlockChecker checker(trx, lock, s_lock_mark_counter, report_waits); victim_trx = checker.search(); - /* Report waits to upper layer, as needed. */ - if (waitee_buf_ptr) { - lock_report_waiters_to_mysql(waitee_buf_ptr, - start_mysql_thd, - victim_trx); - } - /* Search too deep, we rollback the joining transaction only if it is possible to rollback. Otherwise we rollback the transaction that is holding the lock that the joining diff --git a/storage/xtradb/handler/ha_innodb.cc b/storage/xtradb/handler/ha_innodb.cc index aa54a5aff5d..900d520d242 100644 --- a/storage/xtradb/handler/ha_innodb.cc +++ b/storage/xtradb/handler/ha_innodb.cc @@ -5441,8 +5441,7 @@ innobase_kill_connection( wsrep_thd_is_BF(current_thd, FALSE), lock_get_info(trx->lock.wait_lock).c_str()); - if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE) && - trx->abort_type == TRX_SERVER_ABORT) { + if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE)) { ut_ad(!lock_mutex_own()); lock_mutex_enter(); } @@ -5462,8 +5461,7 @@ innobase_kill_connection( trx_mutex_exit(trx); } - if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE) && - trx->abort_type == TRX_SERVER_ABORT) { + if (!wsrep_thd_is_BF(trx->mysql_thd, FALSE)) { lock_mutex_exit(); } } diff --git a/storage/xtradb/include/trx0trx.h b/storage/xtradb/include/trx0trx.h index ec810405b5a..44ff8f3ec98 100644 --- a/storage/xtradb/include/trx0trx.h +++ b/storage/xtradb/include/trx0trx.h @@ -707,8 +707,7 @@ lock_sys->mutex and sometimes by trx->mutex. */ typedef enum { TRX_SERVER_ABORT = 0, - TRX_WSREP_ABORT = 1, - TRX_REPLICATION_ABORT = 2 + TRX_WSREP_ABORT = 1 } trx_abort_t; struct trx_t{ diff --git a/storage/xtradb/lock/lock0lock.cc b/storage/xtradb/lock/lock0lock.cc index ecf43f71b21..341c452cd15 100644 --- a/storage/xtradb/lock/lock0lock.cc +++ b/storage/xtradb/lock/lock0lock.cc @@ -380,8 +380,8 @@ struct lock_stack_t { ulint heap_no; /*!< heap number if rec lock */ }; -extern "C" void thd_report_wait_for(MYSQL_THD thd, MYSQL_THD other_thd); -extern "C" int thd_need_wait_for(const MYSQL_THD thd); +extern "C" void thd_rpl_deadlock_check(MYSQL_THD thd, MYSQL_THD other_thd); +extern "C" int thd_need_wait_reports(const MYSQL_THD thd); extern "C" int thd_need_ordering_with(const MYSQL_THD thd, const MYSQL_THD other_thd); @@ -406,7 +406,7 @@ UNIV_INTERN mysql_pfs_key_t lock_sys_wait_mutex_key; struct thd_wait_reports { struct thd_wait_reports *next; /*!< List link */ ulint used; /*!< How many elements in waitees[] */ - trx_t *waitees[64]; /*!< Trxs for thd_report_wait_for() */ + trx_t *waitees[64]; /*!< Trxs for thd_rpl_deadlock_check() */ }; @@ -4489,14 +4489,7 @@ lock_report_waiters_to_mysql( /* There is no need to report waits to a trx already selected as a victim. */ if (w_trx->id != victim_trx_id) { - /* If thd_report_wait_for() decides to kill the - transaction, then we will get a call back into - innobase_kill_query. We mark this by setting - current_lock_mutex_owner, so we can avoid trying - to recursively take lock_sys->mutex. */ - w_trx->abort_type = TRX_REPLICATION_ABORT; - thd_report_wait_for(mysql_thd, w_trx->mysql_thd); - w_trx->abort_type = TRX_SERVER_ABORT; + thd_rpl_deadlock_check(mysql_thd, w_trx->mysql_thd); } ++i; } @@ -4535,7 +4528,7 @@ lock_deadlock_check_and_resolve( assert_trx_in_list(trx); start_mysql_thd = trx->mysql_thd; - if (start_mysql_thd && thd_need_wait_for(start_mysql_thd)) { + if (start_mysql_thd && thd_need_wait_reports(start_mysql_thd)) { waitee_buf_ptr = &waitee_buf; } else { waitee_buf_ptr = NULL; From d055e28f61ef44f2fdbd139edcaf191c96d14e68 Mon Sep 17 00:00:00 2001 From: Sergey Vojtovich Date: Tue, 13 Sep 2016 23:35:20 +0400 Subject: [PATCH 18/52] MDEV-10813 - Clean-up InnoDB atomics, memory barriers and mutexes Simplified InnoDB mutex implementations, corrected memory barriers usage, use server atomic builtins. --- storage/innobase/include/ib0mutex.h | 553 +++++--------------------- storage/innobase/include/sync0types.h | 1 + storage/innobase/include/ut0mutex.h | 2 - storage/innobase/include/ut0mutex.ic | 108 ----- 4 files changed, 102 insertions(+), 562 deletions(-) delete mode 100644 storage/innobase/include/ut0mutex.ic diff --git a/storage/innobase/include/ib0mutex.h b/storage/innobase/include/ib0mutex.h index 3ea0687da43..9f4ad8424f3 100644 --- a/storage/innobase/include/ib0mutex.h +++ b/storage/innobase/include/ib0mutex.h @@ -31,6 +31,7 @@ Created 2013-03-26 Sunny Bains. #include "ut0ut.h" #include "ut0rnd.h" #include "os0event.h" +#include "sync0arr.h" /** OS mutex for tracking lock/unlock for debugging */ template