MDEV-7623: Add lock wait time and hold time to every record/table lock in

InnoDB transaction lock printout.

Author: Jan Lindström

storage/innobase/include/lock0priv.h

@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 2007, 2011, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2015, MariaDB Corporation
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -72,6 +73,12 @@ struct lock_t {
 	hash_node_t	hash;		/*!< hash chain node for a record
 					lock */
 	dict_index_t*	index;		/*!< index for a record lock */
+
+	/* Statistics for how long lock has been held and time
+	how long this lock had to be waited before it was granted */
+	time_t		requested_time; /*!< Lock request time */
+	ulint		wait_time;	/*!< Time waited this lock or 0 */
+
 	union {
 		lock_table_t	tab_lock;/*!< table lock */
 		lock_rec_t	rec_lock;/*!< record lock */

storage/innobase/lock/lock0lock.cc

@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1996, 2014, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2014, 2015, MariaDB Corporation
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -1886,6 +1887,9 @@ lock_rec_create(
 	/* Set the bit corresponding to rec */
 	lock_rec_set_nth_bit(lock, heap_no);
 
+	lock->requested_time = ut_time();
+	lock->wait_time = 0;
+
 	index->table->n_rec_locks++;
 
 	ut_ad(index->table->n_ref_count > 0 || !index->table->can_be_evicted);
@@ -2465,6 +2469,8 @@ lock_grant(
 			(ulint)difftime(ut_time(), lock->trx->lock.wait_started);
 	}
 
+	lock->wait_time = (ulint)difftime(ut_time(), lock->requested_time);
+
 	trx_mutex_exit(lock->trx);
 }
 
@@ -4226,6 +4232,8 @@ lock_table_create(
 
 	lock->type_mode = type_mode | LOCK_TABLE;
 	lock->trx = trx;
+	lock->requested_time = ut_time();
+	lock->wait_time = 0;
 
 	lock->un_member.tab_lock.table = table;
 
@@ -5145,6 +5153,10 @@ lock_table_print(
 		fputs(" waiting", file);
 	}
 
+	fprintf(file, " lock hold time %lu wait time before grant %lu ",
+		(ulint)difftime(ut_time(), lock->requested_time),
+		lock->wait_time);
+
 	putc('\n', file);
 }
 
@@ -5212,6 +5224,10 @@ lock_rec_print(
 
 	mtr_start(&mtr);
 
+	fprintf(file, " lock hold time %lu wait time before grant %lu ",
+		(ulint)difftime(ut_time(), lock->requested_time),
+		lock->wait_time);
+
 	putc('\n', file);
 
 	block = buf_page_try_get(space, page_no, &mtr);

storage/xtradb/include/lock0priv.h

@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 2007, 2011, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2015, MariaDB Corporation
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -72,6 +73,12 @@ struct lock_t {
 	hash_node_t	hash;		/*!< hash chain node for a record
 					lock */
 	dict_index_t*	index;		/*!< index for a record lock */
+
+	/* Statistics for how long lock has been held and time
+	how long this lock had to be waited before it was granted */
+	time_t		requested_time; /*!< Lock request time */
+	ulint		wait_time;	/*!< Time waited this lock or 0 */
+
 	union {
 		lock_table_t	tab_lock;/*!< table lock */
 		lock_rec_t	rec_lock;/*!< record lock */

storage/xtradb/lock/lock0lock.cc

@@ -1,6 +1,7 @@
 /*****************************************************************************
 
 Copyright (c) 1996, 2014, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2014, 2015, MariaDB Corporation
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -1897,6 +1898,9 @@ lock_rec_create(
 	/* Set the bit corresponding to rec */
 	lock_rec_set_nth_bit(lock, heap_no);
 
+	lock->requested_time = ut_time();
+	lock->wait_time = 0;
+
 	index->table->n_rec_locks++;
 
 	ut_ad(index->table->n_ref_count > 0 || !index->table->can_be_evicted);
@@ -2485,6 +2489,8 @@ lock_grant(
 			(ulint)difftime(ut_time(), lock->trx->lock.wait_started);
 	}
 
+	lock->wait_time = (ulint)difftime(ut_time(), lock->requested_time);
+
 	trx_mutex_exit(lock->trx);
 }
 
@@ -4250,6 +4256,8 @@ lock_table_create(
 
 	lock->type_mode = type_mode | LOCK_TABLE;
 	lock->trx = trx;
+	lock->requested_time = ut_time();
+	lock->wait_time = 0;
 
 	lock->un_member.tab_lock.table = table;
 
@@ -5180,6 +5188,10 @@ lock_table_print(
 		fputs(" waiting", file);
 	}
 
+	fprintf(file, " lock hold time %lu wait time before grant %lu ",
+		(ulint)difftime(ut_time(), lock->requested_time),
+		lock->wait_time);
+
 	putc('\n', file);
 }
 
@@ -5247,6 +5259,10 @@ lock_rec_print(
 
 	mtr_start(&mtr);
 
+	fprintf(file, " lock hold time %lu wait time before grant %lu ",
+		(ulint)difftime(ut_time(), lock->requested_time),
+		lock->wait_time);
+
 	putc('\n', file);
 
 	if ( srv_show_verbose_locks ) {