From e85b389b762e038bc2e347421fa39636159b53b9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jan=20Lindstr=C3=B6m?= Date: Tue, 27 Apr 2021 14:50:21 +0300 Subject: MDEV-25319 : Long BF log wait turns on InnoDB Monitor output without telling, never turns it off Removed explicit InnoDB monitor startup and used just functions to print current lock information. --- .../galera/r/galera_inject_bf_long_wait.result | 22 +++++++++++++++ .../suite/galera/t/galera_inject_bf_long_wait.test | 25 ++++++++++++++++ storage/innobase/lock/lock0wait.cc | 33 +++++++++++++--------- 3 files changed, 66 insertions(+), 14 deletions(-) create mode 100644 mysql-test/suite/galera/r/galera_inject_bf_long_wait.result create mode 100644 mysql-test/suite/galera/t/galera_inject_bf_long_wait.test diff --git a/mysql-test/suite/galera/r/galera_inject_bf_long_wait.result b/mysql-test/suite/galera/r/galera_inject_bf_long_wait.result new file mode 100644 index 00000000000..e9eab5401c4 --- /dev/null +++ b/mysql-test/suite/galera/r/galera_inject_bf_long_wait.result @@ -0,0 +1,22 @@ +CREATE TABLE t1(id int not null primary key, b int) engine=InnoDB; +INSERT INTO t1 VALUES (0,0),(1,1),(2,2),(3,3); +BEGIN; +UPDATE t1 set b = 100 where id between 1 and 2;; +connect node_1b, 127.0.0.1, root, , test, $NODE_MYPORT_1; +connection node_1b; +SET @save_dbug = @@SESSION.debug_dbug; +SET @@SESSION.innodb_lock_wait_timeout=2; +SET @@SESSION.debug_dbug = '+d,wsrep_instrument_BF_lock_wait'; +UPDATE t1 set b = 200 WHERE id = 1; +ERROR HY000: Lock wait timeout exceeded; try restarting transaction +SET @@SESSION.debug_dbug = @save_dbug; +connection node_1; +COMMIT; +SELECT * FROM t1; +id b +0 0 +1 100 +2 100 +3 3 +disconnect node_1b; +DROP TABLE t1; diff --git a/mysql-test/suite/galera/t/galera_inject_bf_long_wait.test b/mysql-test/suite/galera/t/galera_inject_bf_long_wait.test new file mode 100644 index 00000000000..f4aac7fd795 --- /dev/null +++ b/mysql-test/suite/galera/t/galera_inject_bf_long_wait.test @@ -0,0 +1,25 @@ +--source include/galera_cluster.inc +--source include/have_debug.inc +--source include/have_debug_sync.inc + +CREATE TABLE t1(id int not null primary key, b int) engine=InnoDB; +INSERT INTO t1 VALUES (0,0),(1,1),(2,2),(3,3); + +BEGIN; +--send UPDATE t1 set b = 100 where id between 1 and 2; + +--connect node_1b, 127.0.0.1, root, , test, $NODE_MYPORT_1 +--connection node_1b +SET @save_dbug = @@SESSION.debug_dbug; +SET @@SESSION.innodb_lock_wait_timeout=2; +SET @@SESSION.debug_dbug = '+d,wsrep_instrument_BF_lock_wait'; +--error ER_LOCK_WAIT_TIMEOUT +UPDATE t1 set b = 200 WHERE id = 1; +SET @@SESSION.debug_dbug = @save_dbug; + +--connection node_1 +--reap +COMMIT; +SELECT * FROM t1; +--disconnect node_1b +DROP TABLE t1; diff --git a/storage/innobase/lock/lock0wait.cc b/storage/innobase/lock/lock0wait.cc index 5d0d41ef494..df1488b9df3 100644 --- a/storage/innobase/lock/lock0wait.cc +++ b/storage/innobase/lock/lock0wait.cc @@ -192,28 +192,33 @@ wsrep_is_BF_lock_timeout( const trx_t* trx, bool locked = true) { - if (trx->is_wsrep() && wsrep_thd_is_BF(trx->mysql_thd, FALSE) - && trx->error_state != DB_DEADLOCK) { - ib::info() << "WSREP: BF lock wait long for trx:" << ib::hex(trx->id) + bool long_wait= (trx->error_state != DB_DEADLOCK && + trx->is_wsrep() && + wsrep_thd_is_BF(trx->mysql_thd, false)); + bool was_wait= true; + + DBUG_EXECUTE_IF("wsrep_instrument_BF_lock_wait", + was_wait=false; long_wait=true;); + + if (long_wait) { + ib::info() << "WSREP: BF lock wait long for trx:" << trx->id << " query: " << wsrep_thd_query(trx->mysql_thd); - if (!locked) { + + if (!locked) lock_mutex_enter(); - } ut_ad(lock_mutex_own()); wsrep_trx_print_locking(stderr, trx, 3000); + /* Note this will release lock_sys mutex */ + lock_print_info_all_transactions(stderr); - if (!locked) { - lock_mutex_exit(); - } + if (locked) + lock_mutex_enter(); - srv_print_innodb_monitor = TRUE; - srv_print_innodb_lock_monitor = TRUE; - os_event_set(srv_monitor_event); - return true; - } - return false; + return was_wait; + } else + return false; } #endif /* WITH_WSREP */ -- cgit v1.2.1