MDEV-29311 Server Status Innodb_row_lock_time% is reported in seconds

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ä

mysql-test/suite/innodb/r/innodb_row_lock_time_ms.result

+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;

mysql-test/suite/innodb/t/innodb_row_lock_time_ms.test

+--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

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},

storage/innobase/include/lock0lock.h

@@ -755,9 +755,9 @@ class lock_sys_t
   /** 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 @@ class lock_sys_t
   ulint get_wait_cumulative() const
   { return static_cast<ulint>(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)

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 */

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<uint32_t>((now.val - start.val) / 1000);
+    const uint64_t diff_time=
+      static_cast<uint64_t>((now.val - start.val) / 1000);
     wait_time+= diff_time;
 
     if (diff_time > wait_time_max)

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;
 		}

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