From 090a84366ad27564ae5e8be01fa1c672508d13ab Mon Sep 17 00:00:00 2001 From: Vlad Lesin Date: Thu, 6 Jul 2023 11:49:28 +0300 Subject: [PATCH] MDEV-29311 Server Status Innodb_row_lock_time% is reported in seconds MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Before MDEV-24671, the wait time was derived from my_interval_timer() / 1000 (nanoseconds converted to microseconds, and not microseconds to milliseconds like I must have assumed). The lock_sys.wait_time and lock_sys.wait_time_max are already in milliseconds; we should not divide them by 1000. In MDEV-24738 the millisecond counts lock_sys.wait_time and lock_sys.wait_time_max were changed to a 32-bit type. That would overflow in 49.7 days. Keep using a 64-bit type for those millisecond counters. Reviewed by: Marko Mäkelä --- .../innodb/r/innodb_row_lock_time_ms.result | 40 ++++++++++++++++++ .../innodb/t/innodb_row_lock_time_ms.test | 42 +++++++++++++++++++ storage/innobase/handler/ha_innodb.cc | 4 +- storage/innobase/include/lock0lock.h | 8 ++-- storage/innobase/include/srv0srv.h | 11 ++--- storage/innobase/lock/lock0lock.cc | 4 +- storage/innobase/srv/srv0mon.cc | 7 ++-- storage/innobase/srv/srv0srv.cc | 7 ++-- 8 files changed, 100 insertions(+), 23 deletions(-) create mode 100644 mysql-test/suite/innodb/r/innodb_row_lock_time_ms.result create mode 100644 mysql-test/suite/innodb/t/innodb_row_lock_time_ms.test diff --git a/mysql-test/suite/innodb/r/innodb_row_lock_time_ms.result b/mysql-test/suite/innodb/r/innodb_row_lock_time_ms.result new file mode 100644 index 00000000000..984d789e058 --- /dev/null +++ b/mysql-test/suite/innodb/r/innodb_row_lock_time_ms.result @@ -0,0 +1,40 @@ +CREATE TABLE `t`(`id` INT, PRIMARY KEY(`id`)) ENGINE=InnoDB STATS_PERSISTENT=0; +INSERT INTO t VALUES (1); +SET GLOBAL innodb_monitor_reset = "module_innodb"; +BEGIN; +SELECT * FROM t FOR UPDATE; +id +1 +connect con1,localhost,root,,; +SET innodb_lock_wait_timeout = 1; +SELECT * FROM t FOR UPDATE; +ERROR HY000: Lock wait timeout exceeded; try restarting transaction +disconnect con1; +connection default; +COMMIT; +SELECT variable_value > 100 FROM information_schema.global_status +WHERE LOWER(variable_name) = 'innodb_row_lock_time'; +variable_value > 100 +1 +SELECT variable_value > 100 FROM information_schema.global_status +WHERE LOWER(variable_name) = 'innodb_row_lock_time_max'; +variable_value > 100 +1 +SELECT variable_value > 100 FROM information_schema.global_status +WHERE LOWER(variable_name) = 'innodb_row_lock_time_avg'; +variable_value > 100 +1 +SELECT count_reset > 100 FROM INFORMATION_SCHEMA.INNODB_METRICS +WHERE NAME="lock_row_lock_time"; +count_reset > 100 +1 +SELECT count_reset > 100 FROM INFORMATION_SCHEMA.INNODB_METRICS +WHERE NAME="lock_row_lock_time_max"; +count_reset > 100 +1 +SELECT count_reset > 100 FROM INFORMATION_SCHEMA.INNODB_METRICS +WHERE NAME="lock_row_lock_time_avg"; +count_reset > 100 +1 +DROP TABLE t; +SET GLOBAL innodb_monitor_reset=default; diff --git a/mysql-test/suite/innodb/t/innodb_row_lock_time_ms.test b/mysql-test/suite/innodb/t/innodb_row_lock_time_ms.test new file mode 100644 index 00000000000..4a100821819 --- /dev/null +++ b/mysql-test/suite/innodb/t/innodb_row_lock_time_ms.test @@ -0,0 +1,42 @@ +--source include/have_innodb.inc +--source include/count_sessions.inc + +CREATE TABLE `t`(`id` INT, PRIMARY KEY(`id`)) ENGINE=InnoDB STATS_PERSISTENT=0; + +INSERT INTO t VALUES (1); + +SET GLOBAL innodb_monitor_reset = "module_innodb"; + +BEGIN; +SELECT * FROM t FOR UPDATE; + +--connect(con1,localhost,root,,) +SET innodb_lock_wait_timeout = 1; +--error ER_LOCK_WAIT_TIMEOUT +SELECT * FROM t FOR UPDATE; +--disconnect con1 + +--connection default +COMMIT; + +SELECT variable_value > 100 FROM information_schema.global_status + WHERE LOWER(variable_name) = 'innodb_row_lock_time'; +SELECT variable_value > 100 FROM information_schema.global_status + WHERE LOWER(variable_name) = 'innodb_row_lock_time_max'; +SELECT variable_value > 100 FROM information_schema.global_status + WHERE LOWER(variable_name) = 'innodb_row_lock_time_avg'; + +SELECT count_reset > 100 FROM INFORMATION_SCHEMA.INNODB_METRICS + WHERE NAME="lock_row_lock_time"; +SELECT count_reset > 100 FROM INFORMATION_SCHEMA.INNODB_METRICS + WHERE NAME="lock_row_lock_time_max"; +SELECT count_reset > 100 FROM INFORMATION_SCHEMA.INNODB_METRICS + WHERE NAME="lock_row_lock_time_avg"; + +DROP TABLE t; + +--disable_warnings +SET GLOBAL innodb_monitor_reset=default; +--enable_warnings + +--source include/wait_until_count_sessions.inc diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc index 3d0da6bbf74..c44748d3c5f 100644 --- a/storage/innobase/handler/ha_innodb.cc +++ b/storage/innobase/handler/ha_innodb.cc @@ -1010,8 +1010,8 @@ static SHOW_VAR innodb_status_variables[]= { {"row_lock_current_waits", &export_vars.innodb_row_lock_current_waits, SHOW_SIZE_T}, {"row_lock_time", &export_vars.innodb_row_lock_time, SHOW_LONGLONG}, - {"row_lock_time_avg", &export_vars.innodb_row_lock_time_avg, SHOW_SIZE_T}, - {"row_lock_time_max", &export_vars.innodb_row_lock_time_max, SHOW_SIZE_T}, + {"row_lock_time_avg", &export_vars.innodb_row_lock_time_avg, SHOW_ULONGLONG}, + {"row_lock_time_max", &export_vars.innodb_row_lock_time_max, SHOW_ULONGLONG}, {"row_lock_waits", &export_vars.innodb_row_lock_waits, SHOW_SIZE_T}, {"rows_deleted", &export_vars.innodb_rows_deleted, SHOW_SIZE_T}, {"rows_inserted", &export_vars.innodb_rows_inserted, SHOW_SIZE_T}, diff --git a/storage/innobase/include/lock0lock.h b/storage/innobase/include/lock0lock.h index e8299bb1189..4c92984f2f6 100644 --- a/storage/innobase/include/lock0lock.h +++ b/storage/innobase/include/lock0lock.h @@ -755,9 +755,9 @@ private: /** waits and total number of lock waits; protected by wait_mutex */ uint64_t wait_count; /** Cumulative wait time; protected by wait_mutex */ - uint32_t wait_time; + uint64_t wait_time; /** Longest wait time; protected by wait_mutex */ - uint32_t wait_time_max; + uint64_t wait_time_max; public: /** number of deadlocks detected; protected by wait_mutex */ ulint deadlocks; @@ -916,9 +916,9 @@ public: ulint get_wait_cumulative() const { return static_cast(wait_count / WAIT_COUNT_STEP); } /** Cumulative wait time; protected by wait_mutex */ - ulint get_wait_time_cumulative() const { return wait_time; } + uint64_t get_wait_time_cumulative() const { return wait_time; } /** Longest wait time; protected by wait_mutex */ - ulint get_wait_time_max() const { return wait_time_max; } + uint64_t get_wait_time_max() const { return wait_time_max; } /** Get the lock hash table for a mode */ hash_table &hash_get(ulint mode) diff --git a/storage/innobase/include/srv0srv.h b/storage/innobase/include/srv0srv.h index c4c854f6b9c..0052f015239 100644 --- a/storage/innobase/include/srv0srv.h +++ b/storage/innobase/include/srv0srv.h @@ -708,13 +708,10 @@ struct export_var_t{ ulint innodb_os_log_pending_fsyncs; /*!< n_pending_log_flushes */ ulint innodb_row_lock_waits; /*!< srv_n_lock_wait_count */ ulint innodb_row_lock_current_waits; /*!< srv_n_lock_wait_current_count */ - int64_t innodb_row_lock_time; /*!< srv_n_lock_wait_time - / 1000 */ - ulint innodb_row_lock_time_avg; /*!< srv_n_lock_wait_time - / 1000 - / srv_n_lock_wait_count */ - ulint innodb_row_lock_time_max; /*!< srv_n_lock_max_wait_time - / 1000 */ + int64_t innodb_row_lock_time; /*!< srv_n_lock_wait_time */ + uint64_t innodb_row_lock_time_avg; /*!< srv_n_lock_wait_time + / srv_n_lock_wait_count */ + uint64_t innodb_row_lock_time_max; /*!< srv_n_lock_max_wait_time */ ulint innodb_rows_read; /*!< srv_n_rows_read */ ulint innodb_rows_inserted; /*!< srv_n_rows_inserted */ ulint innodb_rows_updated; /*!< srv_n_rows_updated */ diff --git a/storage/innobase/lock/lock0lock.cc b/storage/innobase/lock/lock0lock.cc index 08547f169f3..6a7e4a2843e 100644 --- a/storage/innobase/lock/lock0lock.cc +++ b/storage/innobase/lock/lock0lock.cc @@ -1648,8 +1648,8 @@ void lock_sys_t::wait_resume(THD *thd, my_hrtime_t start, my_hrtime_t now) wait_count--; if (now.val >= start.val) { - const uint32_t diff_time= - static_cast((now.val - start.val) / 1000); + const uint64_t diff_time= + static_cast((now.val - start.val) / 1000); wait_time+= diff_time; if (diff_time > wait_time_max) diff --git a/storage/innobase/srv/srv0mon.cc b/storage/innobase/srv/srv0mon.cc index 3065ab19462..aa14bc00976 100644 --- a/storage/innobase/srv/srv0mon.cc +++ b/storage/innobase/srv/srv0mon.cc @@ -1677,21 +1677,20 @@ srv_mon_process_existing_counter( /* innodb_row_lock_time */ case MONITOR_OVLD_LOCK_WAIT_TIME: // dirty read without lock_sys.wait_mutex - value = lock_sys.get_wait_time_cumulative() / 1000; + value = lock_sys.get_wait_time_cumulative(); break; /* innodb_row_lock_time_max */ case MONITOR_OVLD_LOCK_MAX_WAIT_TIME: // dirty read without lock_sys.wait_mutex - value = lock_sys.get_wait_time_max() / 1000; + value = lock_sys.get_wait_time_max(); break; /* innodb_row_lock_time_avg */ case MONITOR_OVLD_LOCK_AVG_WAIT_TIME: mysql_mutex_lock(&lock_sys.wait_mutex); if (auto count = lock_sys.get_wait_cumulative()) { - value = lock_sys.get_wait_time_cumulative() / 1000 - / count; + value = lock_sys.get_wait_time_cumulative() / count; } else { value = 0; } diff --git a/storage/innobase/srv/srv0srv.cc b/storage/innobase/srv/srv0srv.cc index 8a4df1b0d14..38ec7377fa4 100644 --- a/storage/innobase/srv/srv0srv.cc +++ b/storage/innobase/srv/srv0srv.cc @@ -1057,10 +1057,9 @@ srv_export_innodb_status(void) export_vars.innodb_row_lock_current_waits= lock_sys.get_wait_pending(); - export_vars.innodb_row_lock_time = lock_sys.get_wait_time_cumulative() - / 1000; - export_vars.innodb_row_lock_time_max = lock_sys.get_wait_time_max() - / 1000; + export_vars.innodb_row_lock_time = lock_sys.get_wait_time_cumulative(); + export_vars.innodb_row_lock_time_max = lock_sys.get_wait_time_max(); + mysql_mutex_unlock(&lock_sys.wait_mutex); export_vars.innodb_row_lock_time_avg= export_vars.innodb_row_lock_waits