From 8885225de66906dc424be8f6ffc4d1b68e54ebca Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vicen=C8=9Biu=20Ciorbaru?= Date: Tue, 28 Sep 2021 22:17:59 +0300 Subject: [PATCH] Implement multiple-signal debug_sync The patch is inspired from MySQL. Instead of using a single String to hold the current active debug_sync signal, use a Hash_set to store LEX_STRINGS. This patch ensures that a signal can not be lost, by being overwritten by another thread via set DEBUG_SYNC = '... SIGNAL ...'; All signals are kepts "alive" until they are consumed by a wait event. This requires updating test cases that assume the GLOBAL signal is never consumed. Follow-up work needed: Port the additional syntax that allows one to set multiple signals and also conditionally deactivate signals when waiting. --- mysql-test/main/debug_sync.result | 39 +++-- mysql-test/main/debug_sync.test | 12 +- mysql-test/suite/innodb/r/mdev-14846.result | 3 +- mysql-test/suite/innodb/t/mdev-14846.test | 3 +- .../suite/sys_vars/r/debug_sync_basic.result | 6 +- .../suite/sys_vars/r/sysvars_debug.result | 2 +- sql/debug_sync.cc | 145 +++++++++++++++--- 7 files changed, 162 insertions(+), 48 deletions(-) diff --git a/mysql-test/main/debug_sync.result b/mysql-test/main/debug_sync.result index bb9ae1a417d0b..45cdc40e24195 100644 --- a/mysql-test/main/debug_sync.result +++ b/mysql-test/main/debug_sync.result @@ -2,7 +2,7 @@ SET DEBUG_SYNC= 'RESET'; DROP TABLE IF EXISTS t1; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: '' +debug_sync ON - current signals: '' SET DEBUG_SYNC='p0 SIGNAL s1 WAIT_FOR s2 TIMEOUT 6 EXECUTE 2 HIT_LIMIT 3'; SET DEBUG_SYNC='p0 SIGNAL s1 WAIT_FOR s2 TIMEOUT 6 EXECUTE 2'; SET DEBUG_SYNC='p0 SIGNAL s1 WAIT_FOR s2 TIMEOUT 6 HIT_LIMIT 3'; @@ -150,34 +150,34 @@ SET @myvar= 'now SIGNAL from_myvar'; SET DEBUG_SYNC= @myvar; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 'from_myvar' +debug_sync ON - current signals: 'from_myvar' SET DEBUG_SYNC= LEFT('now SIGNAL from_function_cut_here', 24); SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 'from_function' +debug_sync ON - current signals: 'from_myvar,from_function' SET DEBUG_SYNC= 'now SIGNAL something'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 'something' +debug_sync ON - current signals: 'something,from_function,from_myvar' SET DEBUG_SYNC= 'now WAIT_FOR nothing TIMEOUT 0'; Warnings: Warning #### debug sync point wait timed out SET DEBUG_SYNC= 'now SIGNAL nothing'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 'nothing' +debug_sync ON - current signals: 'something,from_function,nothing,from_myvar' SET DEBUG_SYNC= 'now WAIT_FOR nothing TIMEOUT 0'; SET DEBUG_SYNC= 'now SIGNAL something EXECUTE 0'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 'nothing' +debug_sync ON - current signals: 'something,from_function,from_myvar' SET DEBUG_SYNC= 'now WAIT_FOR anotherthing TIMEOUT 0 EXECUTE 0'; SET DEBUG_SYNC= 'now HIT_LIMIT 1'; ERROR HY000: debug sync point hit limit reached SET DEBUG_SYNC= 'RESET'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: '' +debug_sync ON - current signals: '' SET DEBUG_SYNC= 'p1abcd SIGNAL s1 EXECUTE 2'; SET DEBUG_SYNC= 'p2abc SIGNAL s2 EXECUTE 2'; SET DEBUG_SYNC= 'p9abcdef SIGNAL s9 EXECUTE 2'; @@ -190,23 +190,30 @@ SET DEBUG_SYNC= 'p3abcdef SIGNAL s3 EXECUTE 2'; SET DEBUG_SYNC= 'p4a TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's4' +debug_sync ON - current signals: 's4' SET DEBUG_SYNC= 'p1abcd TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's1' +debug_sync ON - current signals: 's4,s1' SET DEBUG_SYNC= 'p7 TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's7' +debug_sync ON - current signals: 's1,s7,s4' SET DEBUG_SYNC= 'p9abcdef TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's9' +debug_sync ON - current signals: 's1,s7,s4,s9' SET DEBUG_SYNC= 'p3abcdef TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's3' +debug_sync ON - current signals: 's1,s3,s4,s9,s7' +SET DEBUG_SYNC= 'now WAIT_FOR s9'; +SET DEBUG_SYNC= 'now WAIT_FOR s1'; +SET DEBUG_SYNC= 'now WAIT_FOR s4'; +SET DEBUG_SYNC= 'now WAIT_FOR s7'; +SHOW VARIABLES LIKE 'DEBUG_SYNC'; +Variable_name Value +debug_sync ON - current signals: 's3' SET DEBUG_SYNC= 'p1abcd CLEAR'; SET DEBUG_SYNC= 'p2abc CLEAR'; SET DEBUG_SYNC= 'p5abcde CLEAR'; @@ -219,19 +226,19 @@ SET DEBUG_SYNC= 'p7 CLEAR'; SET DEBUG_SYNC= 'p1abcd TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's3' +debug_sync ON - current signals: 's3' SET DEBUG_SYNC= 'p7 TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's3' +debug_sync ON - current signals: 's3' SET DEBUG_SYNC= 'p9abcdef TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: 's3' +debug_sync ON - current signals: 's3' SET DEBUG_SYNC= 'RESET'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; Variable_name Value -debug_sync ON - current signal: '' +debug_sync ON - current signals: '' CREATE USER mysqltest_1@localhost; GRANT SUPER ON *.* TO mysqltest_1@localhost; connect con1,localhost,mysqltest_1,,; diff --git a/mysql-test/main/debug_sync.test b/mysql-test/main/debug_sync.test index 89414939f5999..0e57071e08a40 100644 --- a/mysql-test/main/debug_sync.test +++ b/mysql-test/main/debug_sync.test @@ -298,6 +298,16 @@ SET DEBUG_SYNC= 'p9abcdef TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; SET DEBUG_SYNC= 'p3abcdef TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; + +# +# Wait for all signals currently active except s3. +# +SET DEBUG_SYNC= 'now WAIT_FOR s9'; +SET DEBUG_SYNC= 'now WAIT_FOR s1'; +SET DEBUG_SYNC= 'now WAIT_FOR s4'; +SET DEBUG_SYNC= 'now WAIT_FOR s7'; +SHOW VARIABLES LIKE 'DEBUG_SYNC'; + # # Clear the actions. # @@ -320,7 +330,7 @@ SHOW VARIABLES LIKE 'DEBUG_SYNC'; SET DEBUG_SYNC= 'p9abcdef TEST'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; # -# Now cleanup. Actions are clear already, but signal needs to be cleared. +# Now cleanup. Actions are clear already, but s3 signal needs to be cleared. # SET DEBUG_SYNC= 'RESET'; SHOW VARIABLES LIKE 'DEBUG_SYNC'; diff --git a/mysql-test/suite/innodb/r/mdev-14846.result b/mysql-test/suite/innodb/r/mdev-14846.result index 219bd718febe9..a1ccfb6bb4d0e 100644 --- a/mysql-test/suite/innodb/r/mdev-14846.result +++ b/mysql-test/suite/innodb/r/mdev-14846.result @@ -31,11 +31,12 @@ pk f1 f2 f3 3 t q 1 5 z t NULL SET DEBUG_SYNC='now SIGNAL default_dml'; +SET DEBUG_SYNC='now SIGNAL con2_dml'; connection default; SET DEBUG_SYNC='now WAIT_FOR default_dml'; UPDATE t3 AS alias1 LEFT JOIN t3 AS alias2 ON ( alias1.f1 <> alias1.f2 ) SET alias1.f3 = 59 WHERE ( EXISTS ( SELECT t1.f3 FROM t1 WHERE t1.f1 = alias1.f1 ) ) OR alias2.f1 = 'h'; connect con2,localhost,root,,test; -set debug_sync='now WAIT_FOR default_dml'; +set debug_sync='now WAIT_FOR con2_dml'; SET DEBUG_SYNC='now SIGNAL con1_dml2'; disconnect con2; connection con1; diff --git a/mysql-test/suite/innodb/t/mdev-14846.test b/mysql-test/suite/innodb/t/mdev-14846.test index adcefecd52f25..b1f323025910a 100644 --- a/mysql-test/suite/innodb/t/mdev-14846.test +++ b/mysql-test/suite/innodb/t/mdev-14846.test @@ -35,6 +35,7 @@ SET DEBUG_SYNC='now WAIT_FOR con1_dml'; begin; SELECT * FROM t1 for update; # Holds x lock of all records in the table t1 SET DEBUG_SYNC='now SIGNAL default_dml'; +SET DEBUG_SYNC='now SIGNAL con2_dml'; --connection default SET DEBUG_SYNC='now WAIT_FOR default_dml'; @@ -42,7 +43,7 @@ SET DEBUG_SYNC='now WAIT_FOR default_dml'; # It holds the lock of all record in t3 and tries to acquire record lock for the table t1. --connect (con2,localhost,root,,test) -set debug_sync='now WAIT_FOR default_dml'; +set debug_sync='now WAIT_FOR con2_dml'; let $wait_condition= select count(*) > 0 from information_schema.innodb_lock_waits; --source include/wait_condition.inc diff --git a/mysql-test/suite/sys_vars/r/debug_sync_basic.result b/mysql-test/suite/sys_vars/r/debug_sync_basic.result index 6ebb46dd6620a..11506cac2c228 100644 --- a/mysql-test/suite/sys_vars/r/debug_sync_basic.result +++ b/mysql-test/suite/sys_vars/r/debug_sync_basic.result @@ -2,17 +2,17 @@ select @@global.debug_sync; ERROR HY000: Variable 'debug_sync' is a SESSION variable select @@session.debug_sync; @@session.debug_sync -ON - current signal: '' +ON - current signals: '' show global variables like "debug_sync"; Variable_name Value show session variables like "debug_sync"; Variable_name Value -debug_sync ON - current signal: '' +debug_sync ON - current signals: '' select * from information_schema.global_variables where variable_name="debug_sync"; VARIABLE_NAME VARIABLE_VALUE select * from information_schema.session_variables where variable_name="debug_sync"; VARIABLE_NAME VARIABLE_VALUE -DEBUG_SYNC ON - current signal: '' +DEBUG_SYNC ON - current signals: '' set @@session.debug_sync=1; ERROR 42000: Incorrect argument type to variable 'debug_sync' set @@session.debug_sync=1.1; diff --git a/mysql-test/suite/sys_vars/r/sysvars_debug.result b/mysql-test/suite/sys_vars/r/sysvars_debug.result index 0d77b0211a1ea..fc04ac832101b 100644 --- a/mysql-test/suite/sys_vars/r/sysvars_debug.result +++ b/mysql-test/suite/sys_vars/r/sysvars_debug.result @@ -77,7 +77,7 @@ READ_ONLY YES COMMAND_LINE_ARGUMENT OPTIONAL GLOBAL_VALUE_PATH NULL VARIABLE_NAME DEBUG_SYNC -SESSION_VALUE ON - current signal: '' +SESSION_VALUE ON - current signals: '' GLOBAL_VALUE NULL GLOBAL_VALUE_ORIGIN COMPILE-TIME DEFAULT_VALUE diff --git a/sql/debug_sync.cc b/sql/debug_sync.cc index 55523a728f821..6c847dc992756 100644 --- a/sql/debug_sync.cc +++ b/sql/debug_sync.cc @@ -67,21 +67,99 @@ struct st_debug_sync_control }; + + /** Definitions for the debug sync facility. - 1. Global string variable to hold a "signal" ("signal post", "flag mast"). + 1. Global string variable to hold a set of of "signals". 2. Global condition variable for signaling and waiting. 3. Global mutex to synchronize access to the above. */ struct st_debug_sync_globals { - String ds_signal; /* signal variable */ + Hash_set ds_signal_set; /* A set of active signals */ mysql_cond_t ds_cond; /* condition variable */ mysql_mutex_t ds_mutex; /* mutex variable */ ulonglong dsp_hits; /* statistics */ ulonglong dsp_executed; /* statistics */ ulonglong dsp_max_active; /* statistics */ + + st_debug_sync_globals() : ds_signal_set(PSI_NOT_INSTRUMENTED, signal_key) {}; + ~st_debug_sync_globals() + { + clear_set(); + } + + void clear_set() + { + Hash_set::Iterator it{ds_signal_set}; + LEX_CSTRING *s; + while ((s= it++)) + my_free(s); + ds_signal_set.clear(); + } + + /* Hash key function for ds_signal_set. */ + static uchar *signal_key(const LEX_CSTRING *str, size_t *klen, my_bool) + { + *klen= str->length; + return (uchar*) str->str; + } + + /** + Return true if the signal is found in global signal list. + + @param signal_name Signal name identifying the signal. + + @note + If signal is found in the global signal set, it means that the + signal thread has signalled to the waiting thread. This method + must be called with the debug_sync_global.ds_mutex held. + + @retval true if signal is found in the global signal list. + @retval false otherwise. + */ + + inline bool is_signalled(const String &signal_name) + { + return ds_signal_set.find(signal_name.ptr(), signal_name.length()); + } + + void clear_signal(const String &signal_name) + { + DBUG_ENTER("clear_signal"); + LEX_CSTRING *record= ds_signal_set.find(signal_name.ptr(), + signal_name.length()); + if (record) + { + ds_signal_set.remove(record); + my_free(record); + } + DBUG_VOID_RETURN; + } + + bool set_signal(const String &signal_name) + { + /* Need to check if the signal is already in the hash set, because + Hash_set doesn't differentiate between OOM and key already in. */ + if (is_signalled(signal_name)) + return FALSE; + /* LEX_CSTRING and the string allocated with only one malloc. */ + LEX_CSTRING *s= (LEX_CSTRING *) my_malloc(PSI_NOT_INSTRUMENTED, + sizeof(LEX_CSTRING) + + signal_name.length() + 1, MYF(0)); + char *str= (char *)(s + 1); + memcpy(str, signal_name.ptr(), signal_name.length()); + str[signal_name.length()]= '\0'; + + s->length= signal_name.length(); + s->str= str; + if (ds_signal_set.insert(s)) + return TRUE; + return FALSE; + } }; + static st_debug_sync_globals debug_sync_global; /* All globals in one object */ /** @@ -161,7 +239,7 @@ int debug_sync_init(void) int rc; /* Initialize the global variables. */ - debug_sync_global.ds_signal.length(0); + debug_sync_global.clear_set(); if ((rc= mysql_cond_init(key_debug_sync_globals_ds_cond, &debug_sync_global.ds_cond, NULL)) || (rc= mysql_mutex_init(key_debug_sync_globals_ds_mutex, @@ -195,7 +273,7 @@ void debug_sync_end(void) debug_sync_C_callback_ptr= NULL; /* Destroy the global variables. */ - debug_sync_global.ds_signal.free(); + debug_sync_global.clear_set(); mysql_cond_destroy(&debug_sync_global.ds_cond); mysql_mutex_destroy(&debug_sync_global.ds_mutex); @@ -554,7 +632,7 @@ static void debug_sync_reset(THD *thd) /* Clear the global signal. */ mysql_mutex_lock(&debug_sync_global.ds_mutex); - debug_sync_global.ds_signal.length(0); + debug_sync_global.clear_set(); mysql_mutex_unlock(&debug_sync_global.ds_mutex); DBUG_VOID_RETURN; @@ -1325,13 +1403,19 @@ uchar *debug_sync_value_ptr(THD *thd) if (opt_debug_sync_timeout) { - static char on[]= "ON - current signal: '"; + static char on[]= "ON - current signals: '"; // Ensure exclusive access to debug_sync_global.ds_signal mysql_mutex_lock(&debug_sync_global.ds_mutex); - size_t lgt= (sizeof(on) /* includes '\0' */ + - debug_sync_global.ds_signal.length() + 1 /* for '\'' */); + size_t lgt= sizeof(on) + 1; /* +1 as we'll have to append ' at the end. */ + + for (size_t i= 0; i < debug_sync_global.ds_signal_set.size(); i++) + { + /* Assume each signal is separated by a comma, hence +1. */ + lgt+= debug_sync_global.ds_signal_set.at(i)->length + 1; + } + char *vend; char *vptr; @@ -1339,10 +1423,15 @@ uchar *debug_sync_value_ptr(THD *thd) { vend= value + lgt - 1; /* reserve space for '\0'. */ vptr= debug_sync_bmove_len(value, vend, STRING_WITH_LEN(on)); - vptr= debug_sync_bmove_len(vptr, vend, debug_sync_global.ds_signal.ptr(), - debug_sync_global.ds_signal.length()); - if (vptr < vend) - *(vptr++)= '\''; + for (size_t i= 0; i < debug_sync_global.ds_signal_set.size(); i++) + { + const LEX_CSTRING *s= debug_sync_global.ds_signal_set.at(i); + vptr= debug_sync_bmove_len(vptr, vend, s->str, s->length); + if (i != debug_sync_global.ds_signal_set.size() - 1) + *(vptr++)= ','; + } + DBUG_ASSERT(vptr < vend); + *(vptr++)= '\''; *vptr= '\0'; /* We have one byte reserved for the worst case. */ } mysql_mutex_unlock(&debug_sync_global.ds_mutex); @@ -1358,6 +1447,9 @@ uchar *debug_sync_value_ptr(THD *thd) } + + + /** Execute requested action at a synchronization point. @@ -1413,12 +1505,12 @@ static void debug_sync_execute(THD *thd, st_debug_sync_action *action) read access too, to create a memory barrier in order to avoid that threads just reads an old cached version of the signal. */ + mysql_mutex_lock(&debug_sync_global.ds_mutex); if (action->signal.length()) { - /* Copy the signal to the global variable. */ - if (debug_sync_global.ds_signal.copy(action->signal)) + if (debug_sync_global.set_signal(action->signal)) { /* Error is reported by my_malloc(). @@ -1461,12 +1553,12 @@ static void debug_sync_execute(THD *thd, st_debug_sync_action *action) restore_current_mutex = false; set_timespec(abstime, action->timeout); - DBUG_EXECUTE("debug_sync_exec", + // TODO turn this into a for loop printing. + DBUG_EXECUTE("debug_sync_exec", { /* Functions as DBUG_PRINT args can change keyword and line nr. */ DBUG_PRINT("debug_sync_exec", - ("wait for '%s' at: '%s' curr: '%s'", - sig_wait, dsp_name, - debug_sync_global.ds_signal.c_ptr()));); + ("wait for '%s' at: '%s'", + sig_wait, dsp_name));}); /* Wait until global signal string matches the wait_for string. @@ -1474,18 +1566,19 @@ static void debug_sync_execute(THD *thd, st_debug_sync_action *action) The facility can become disabled when some thread cannot get the required dynamic memory allocated. */ - while (stringcmp(&debug_sync_global.ds_signal, &action->wait_for) && - !(thd->killed & KILL_HARD_BIT) && opt_debug_sync_timeout) + while (!debug_sync_global.is_signalled(action->wait_for) && + !(thd->killed & KILL_HARD_BIT)&& + opt_debug_sync_timeout) { error= mysql_cond_timedwait(&debug_sync_global.ds_cond, &debug_sync_global.ds_mutex, &abstime); - DBUG_EXECUTE("debug_sync", + // TODO turn this into a for loop printing. + DBUG_EXECUTE("debug_sync", { /* Functions as DBUG_PRINT args can change keyword and line nr. */ DBUG_PRINT("debug_sync", - ("awoke from %s global: %s error: %d", - sig_wait, debug_sync_global.ds_signal.c_ptr(), - error));); + ("awoke from %s error: %d", + sig_wait, error));}); if (unlikely(error == ETIMEDOUT || error == ETIME)) { // We should not make the statement fail, even if in strict mode. @@ -1498,6 +1591,8 @@ static void debug_sync_execute(THD *thd, st_debug_sync_action *action) } error= 0; } + // TODO conditional on clear-event + debug_sync_global.clear_signal(action->wait_for); DBUG_EXECUTE("debug_sync_exec", if (thd->killed) DBUG_PRINT("debug_sync_exec", @@ -1571,10 +1666,10 @@ static void debug_sync(THD *thd, const char *sync_point_name, size_t name_len) st_debug_sync_control *ds_control= thd->debug_sync_control; st_debug_sync_action *action; DBUG_ENTER("debug_sync"); + DBUG_PRINT("debug_sync_point", ("hit: '%s'", sync_point_name)); DBUG_ASSERT(sync_point_name); DBUG_ASSERT(name_len); DBUG_ASSERT(ds_control); - DBUG_PRINT("debug_sync_point", ("hit: '%s'", sync_point_name)); /* Statistics. */ ds_control->dsp_hits++;