logging_ok:

  Logging to logging@openlogging.org accepted
sql_yacc.yy, sql_parse.cc, sql_lex.h, lex.h:
  Implements the SHOW MUTEX STATUS command
set_var.cc, mysqld.cc, mysql_priv.h:
  Added new GLOBAL variable timed_mutexes
ha_innodb.h:
  New function innodb_mutex_show_status
ha_innodb.cc:
  Added new innodb variables in SHOW STATUS
  Implements the SHOW MUTEX STATUS command
innodb.test, innodb.result:
  Added new row_lock_waits status variables tests.
variables.test, variables.result:
  test new variable timed_mutexes
ut0ut.c:
  New function ut_usectime.
sync0sync.c:
  Mutex counting.
sync0rw.c:
  New mutex parameters initialization.
srv0srv.c:
  Counting row lock waits
row0sel.c, row0mysql.c:
  Setting row_lock or table_lock state to thd.
que0que.c:
  Added default no_lock_state to thd.
univ.i:
  Added UNIV_SRV_PRINT_LATCH_WAITS debug define
sync0sync.ic:
  Count mutex using.
sync0sync.h:
  Added new parameters to mutex structure for counting.
sync0rw.h:
  Added new parameters to rw_create_func.
srv0srv.h:
  Added new innodb varuables to SHOW STATUS.
que0que.h:
  Added thread lock states.


innobase/include/que0que.h:
  Added thread lock states.
innobase/include/srv0srv.h:
  Added new innodb varuables to SHOW STATUS.
innobase/include/sync0rw.h:
  Added new parameters to rw_create_func.
innobase/include/sync0sync.h:
  Added new parameters to mutex structure for counting.
innobase/include/sync0sync.ic:
  Count mutex using.
innobase/include/univ.i:
  Added UNIV_SRV_PRINT_LATCH_WAITS debug define
innobase/que/que0que.c:
  Added default no_lock_state to thd.
innobase/row/row0mysql.c:
  Setting row_lock or table_lock state to thd.
innobase/row/row0sel.c:
  Setting row_lock or table_lock state to thd.
innobase/srv/srv0srv.c:
  Counting row lock waits
innobase/sync/sync0rw.c:
  New mutex parameters initialization.
innobase/sync/sync0sync.c:
  Mutex counting.
innobase/ut/ut0ut.c:
  New function ut_usectime.
mysql-test/r/variables.result:
  test new variable timed_mutexes
mysql-test/r/innodb.result:
  Added new row_lock_waits status variables tests.
mysql-test/t/variables.test:
  test new variable timed_mutexes
mysql-test/t/innodb.test:
  Added new row_lock_waits status variables tests.
sql/ha_innodb.cc:
  Added new innodb variables in SHOW STATUS
  Implements the SHOW MUTEX STATUS command
sql/ha_innodb.h:
  New function innodb_mutex_show_status
sql/lex.h:
  Implements the SHOW MUTEX STATUS command
sql/mysql_priv.h:
  Added new GLOBAL variable timed_mutexes
sql/mysqld.cc:
  Added new GLOBAL variable timed_mutexes
sql/set_var.cc:
  Added new GLOBAL variable timed_mutexes
sql/sql_lex.h:
  Implements the SHOW MUTEX STATUS command
sql/sql_parse.cc:
  Implements the SHOW MUTEX STATUS command
sql/sql_yacc.yy:
  Implements the SHOW MUTEX STATUS command
BitKeeper/etc/logging_ok:
  Logging to logging@openlogging.org accepted

BitKeeper/etc/logging_ok

@@ -230,6 +230,7 @@ ulli@morbus.(none)
 venu@hundin.mysql.fi
 venu@myvenu.com
 venu@work.mysql.com
+vtkachenko@intelp4d.mysql.com
 vva@eagle.mysql.r18.ru
 vva@genie.(none)
 vva@mysql.r18.ru

innobase/include/que0que.h

@@ -359,6 +359,7 @@ struct que_thr_struct{
 					the control came */
 	ulint		resource;	/* resource usage of the query thread
 					thus far */
+  ulint		lock_state;	/* lock state of thread (table or row) */
 };
 
 #define QUE_THR_MAGIC_N		8476583
@@ -482,6 +483,11 @@ struct que_fork_struct{
 #define QUE_THR_SUSPENDED	7
 #define QUE_THR_ERROR		8
 
+/* Query thread lock states */
+#define QUE_THR_LOCK_NOLOCK    0
+#define QUE_THR_LOCK_ROW       1
+#define QUE_THR_LOCK_TABLE     2
+
 /* From where the cursor position is counted */
 #define QUE_CUR_NOT_DEFINED	1
 #define QUE_CUR_START		2

innobase/include/srv0srv.h

@@ -525,6 +525,11 @@ struct export_var_struct{
         ulint innodb_pages_created;
         ulint innodb_pages_read;
         ulint innodb_pages_written;
+        ulint innodb_row_lock_waits;
+        ulint innodb_row_lock_current_waits;
+        ib_longlong innodb_row_lock_time;
+        ulint innodb_row_lock_time_avg;
+        ulint innodb_row_lock_time_max;
         ulint innodb_rows_read;
         ulint innodb_rows_inserted;
         ulint innodb_rows_updated;

innobase/include/sync0rw.h

@@ -61,8 +61,9 @@ Creates, or rather, initializes an rw-lock object in a specified memory
 location (which must be appropriately aligned). The rw-lock is initialized
 to the non-locked state. Explicit freeing of the rw-lock with rw_lock_free
 is necessary only if the memory block containing it is freed. */
-
-#define rw_lock_create(L)	rw_lock_create_func((L), __FILE__, __LINE__)
+#define rw_lock_create(L)	rw_lock_create_func(\
+            (L), __FILE__, __LINE__, __STRING(L))
+          
 /*=====================*/
 /**********************************************************************
 Creates, or rather, initializes an rw-lock object in a specified memory
@@ -75,7 +76,8 @@ rw_lock_create_func(
 /*================*/
 	rw_lock_t*	lock,		/* in: pointer to memory */
 	const char*	cfile_name,	/* in: file name where created */
-	ulint		cline);		/* in: file line where created */
+  ulint		cline,		/* in: file line where created */
+  const char*	cmutex_name);	/* in: mutex name */
 /**********************************************************************
 Calling this function is obligatory only if the memory buffer containing
 the rw-lock is freed. Removes an rw-lock object from the global list. The

innobase/include/sync0sync.h

@@ -17,6 +17,8 @@ Created 9/5/1995 Heikki Tuuri
 #include "os0sync.h"
 #include "sync0arr.h"
 
+extern my_bool	timed_mutexes;
+
 /**********************************************************************
 Initializes the synchronization data structures. */
 
@@ -35,8 +37,7 @@ location (which must be appropriately aligned). The mutex is initialized
 in the reset state. Explicit freeing of the mutex with mutex_free is
 necessary only if the memory block containing it is freed. */
 
-
-#define mutex_create(M)	mutex_create_func((M), __FILE__, __LINE__)
+#define mutex_create(M)	mutex_create_func((M), __FILE__, __LINE__, __STRING(M))
 /*===================*/
 /**********************************************************************
 Creates, or rather, initializes a mutex object in a specified memory
@@ -49,7 +50,8 @@ mutex_create_func(
 /*==============*/
 	mutex_t*	mutex,		/* in: pointer to memory */
 	const char*	cfile_name,	/* in: file name where created */
-	ulint		cline);		/* in: file line where created */
+	ulint		cline,		/* in: file line where created */
+	const char*	cmutex_name);	/* in: mutex name */
 /**********************************************************************
 Calling this function is obligatory only if the memory buffer containing
 the mutex is freed. Removes a mutex object from the mutex list. The mutex
@@ -471,6 +473,15 @@ struct mutex_struct {
 	const char*	cfile_name;/* File name where mutex created */
 	ulint	cline;		/* Line where created */
 	ulint	magic_n;
+  ulong count_using; /* count of times mutex used */
+  ulong count_spin_loop; /* count of spin loops */
+  ulong count_spin_rounds; /* count of spin rounds */
+  ulong count_os_wait; /* count of os_wait */
+  ulong count_os_yield; /* count of os_wait */
+  ulonglong lspent_time; /* mutex os_wait timer msec */
+  ulonglong lmax_spent_time; /* mutex os_wait timer msec */
+  const char*	cmutex_name;/* mutex name  */
+  ulint mutex_type;/* 0 - usual mutex 1 - rw_lock mutex  */
 };
 
 #define MUTEX_MAGIC_N	(ulint)979585
@@ -504,6 +515,13 @@ extern ibool	sync_order_checks_on;
 /* This variable is set to TRUE when sync_init is called */
 extern ibool	sync_initialized;
 
+/* Global list of database mutexes (not OS mutexes) created. */
+UT_LIST_BASE_NODE_T(mutex_t)	mutex_list;
+
+/* Mutex protecting the mutex_list variable */
+mutex_t		mutex_list_mutex;
+
+
 #ifndef UNIV_NONINL
 #include "sync0sync.ic"
 #endif

innobase/include/sync0sync.ic

@@ -249,8 +249,11 @@ mutex_enter_func(
 
 	/* Note that we do not peek at the value of lock_word before trying
 	the atomic test_and_set; we could peek, and possibly save time. */
+
+  mutex->count_using++;
 	
-	if (!mutex_test_and_set(mutex)) {
+	if (!mutex_test_and_set(mutex))
+	{
 #ifdef UNIV_SYNC_DEBUG
 		mutex_set_debug_info(mutex, file_name, line);
 #endif
@@ -258,4 +261,5 @@ mutex_enter_func(
 	}
 
 	mutex_spin_wait(mutex, file_name, line);
+
 }

innobase/include/univ.i

@@ -88,6 +88,7 @@ memory is read outside the allocated blocks. */
 #define UNIV_SEARCH_DEBUG
 #define UNIV_SYNC_PERF_STAT
 #define UNIV_SEARCH_PERF_STAT
+#define UNIV_SRV_PRINT_LATCH_WAITS;
 */
 #define UNIV_LIGHT_MEM_DEBUG
 

innobase/que/que0que.c

@@ -163,6 +163,7 @@ que_thr_create(
 
 	thr->run_node = NULL;
 	thr->resource = 0;
+  thr->lock_state = QUE_THR_LOCK_NOLOCK;
 
 	UT_LIST_ADD_LAST(thrs, parent->thrs, thr);
 

innobase/row/row0mysql.c

@@ -937,9 +937,10 @@ row_insert_for_mysql(
 
 	if (err != DB_SUCCESS) {
 		que_thr_stop_for_mysql(thr);
-
+    thr->lock_state= QUE_THR_LOCK_ROW;
 		was_lock_wait = row_mysql_handle_errors(&err, trx, thr,
 								&savept);
+    thr->lock_state= QUE_THR_LOCK_NOLOCK;
 		if (was_lock_wait) {
 			goto run_again;
 		}
@@ -1171,9 +1172,11 @@ row_update_for_mysql(
 
 			return((int) err);
 		}
-	
+
+    thr->lock_state= QUE_THR_LOCK_ROW;
 		was_lock_wait = row_mysql_handle_errors(&err, trx, thr,
 								&savept);
+    thr->lock_state= QUE_THR_LOCK_NOLOCK;;
 		if (was_lock_wait) {
 			goto run_again;
 		}

innobase/row/row0sel.c

@@ -3791,8 +3791,10 @@ row_search_for_mysql(
 
 	que_thr_stop_for_mysql(thr);
 
+  thr->lock_state= QUE_THR_LOCK_ROW;
 	was_lock_wait = row_mysql_handle_errors(&err, trx, thr, NULL);
-	
+	thr->lock_state= QUE_THR_LOCK_NOLOCK;
+
 	if (was_lock_wait) {
 		mtr_start(&mtr);
 

innobase/srv/srv0srv.c

@@ -346,6 +346,12 @@ static ulint	srv_n_rows_updated_old		= 0;
 static ulint	srv_n_rows_deleted_old		= 0;
 static ulint	srv_n_rows_read_old		= 0;
 
+ulint srv_n_lock_wait_count=          0;
+ulint srv_n_lock_wait_current_count=  0;
+ib_longlong srv_n_lock_wait_time=       0;
+ulint srv_n_lock_max_wait_time=   0;
+
+
 /*
   Set the following to 0 if you want InnoDB to write messages on
   stderr on startup/shutdown
@@ -1378,7 +1384,11 @@ srv_suspend_mysql_thread(
 	trx_t*		trx;
 	ibool		had_dict_lock			= FALSE;
 	ibool		was_declared_inside_innodb	= FALSE;
-	
+	ib_longlong   start_time, finish_time;
+  ulint   diff_time;
+  ulint   sec;
+  ulint   ms;
+
 #ifdef UNIV_SYNC_DEBUG
 	ut_ad(!mutex_own(&kernel_mutex));
 #endif /* UNIV_SYNC_DEBUG */
@@ -1420,7 +1430,15 @@ srv_suspend_mysql_thread(
 	os_event_reset(event);	
 
 	slot->suspend_time = ut_time();
+  if (thr->lock_state == QUE_THR_LOCK_ROW)
+  {
+    srv_n_lock_wait_count++;
+    srv_n_lock_wait_current_count++;
+
+    ut_usectime(&sec, &ms);
+    start_time= (ib_longlong)sec * 1000000 + ms;
 
+  }
 	/* Wake the lock timeout monitor thread, if it is suspended */
 
 	os_event_set(srv_lock_timeout_thread_event);
@@ -1471,7 +1489,22 @@ srv_suspend_mysql_thread(
 	slot->in_use = FALSE;
 
 	wait_time = ut_difftime(ut_time(), slot->suspend_time);
-	
+
+  if (thr->lock_state == QUE_THR_LOCK_ROW)
+  {
+      ut_usectime(&sec, &ms);
+      finish_time= (ib_longlong)sec * 1000000 + ms;
+  
+      diff_time= finish_time-start_time;
+  
+      srv_n_lock_wait_current_count--;
+      srv_n_lock_wait_time= srv_n_lock_wait_time + diff_time;
+      if (diff_time > srv_n_lock_max_wait_time)
+      {
+        srv_n_lock_max_wait_time= diff_time;
+      }
+  }
+
 	if (trx->was_chosen_as_deadlock_victim) {
 
 		trx->error_state = DB_DEADLOCK;
@@ -1689,15 +1722,14 @@ srv_printf_innodb_monitor(
 			(srv_n_rows_read - srv_n_rows_read_old)
 						/ time_elapsed);
 
-	srv_n_rows_inserted_old = srv_n_rows_inserted;
+  srv_n_rows_inserted_old = srv_n_rows_inserted;
 	srv_n_rows_updated_old = srv_n_rows_updated;
 	srv_n_rows_deleted_old = srv_n_rows_deleted;
 	srv_n_rows_read_old = srv_n_rows_read;
 
-	fputs("----------------------------\n"
+  fputs("----------------------------\n"
 		       "END OF INNODB MONITOR OUTPUT\n"
 		"============================\n", file);
-
 	mutex_exit(&srv_innodb_monitor_mutex);
 	fflush(file);
 }
@@ -1746,11 +1778,19 @@ srv_export_innodb_status(void)
         export_vars.innodb_pages_created= buf_pool->n_pages_created;
         export_vars.innodb_pages_read= buf_pool->n_pages_read;
         export_vars.innodb_pages_written= buf_pool->n_pages_written;
+        export_vars.innodb_row_lock_waits= srv_n_lock_wait_count;
+        export_vars.innodb_row_lock_current_waits= srv_n_lock_wait_current_count;
+        export_vars.innodb_row_lock_time= srv_n_lock_wait_time / 10000;
+        export_vars.innodb_row_lock_time_avg= 
+            (srv_n_lock_wait_count > 0) ? 
+            (srv_n_lock_wait_time / 10000 / srv_n_lock_wait_count) : 0;
+        export_vars.innodb_row_lock_time_max= srv_n_lock_max_wait_time / 10000;
         export_vars.innodb_rows_read= srv_n_rows_read;
         export_vars.innodb_rows_inserted= srv_n_rows_inserted;
         export_vars.innodb_rows_updated= srv_n_rows_updated;
         export_vars.innodb_rows_deleted= srv_n_rows_deleted;
         mutex_exit(&srv_innodb_monitor_mutex);
+
 }
 
 /*************************************************************************

innobase/sync/sync0rw.c

@@ -90,7 +90,8 @@ rw_lock_create_func(
 /*================*/
 	rw_lock_t*	lock,		/* in: pointer to memory */
 	const char*	cfile_name,	/* in: file name where created */
-	ulint		cline)		/* in: file line where created */
+  ulint		cline,		/* in: file line where created */
+  const char*	cmutex_name)	/* in: mutex name */
 {
 	/* If this is the very first time a synchronization
 	object is created, then the following call initializes
@@ -101,7 +102,9 @@ rw_lock_create_func(
 
 	lock->mutex.cfile_name = cfile_name;
 	lock->mutex.cline = cline;
-
+  lock->mutex.cmutex_name = cmutex_name;
+  lock->mutex.mutex_type = 1;
+  
 	rw_lock_set_waiters(lock, 0);
 	rw_lock_set_writer(lock, RW_LOCK_NOT_LOCKED);
 	lock->writer_count = 0;

innobase/sync/sync0sync.c

@@ -129,11 +129,6 @@ sync_array_t*	sync_primary_wait_array;
 /* This variable is set to TRUE when sync_init is called */
 ibool	sync_initialized	= FALSE;
 
-/* Global list of database mutexes (not OS mutexes) created. */
-UT_LIST_BASE_NODE_T(mutex_t)	mutex_list;
-
-/* Mutex protecting the mutex_list variable */
-mutex_t		mutex_list_mutex;
 
 typedef struct sync_level_struct	sync_level_t;
 typedef struct sync_thread_struct	sync_thread_t;
@@ -202,7 +197,8 @@ mutex_create_func(
 /*==============*/
 	mutex_t*	mutex,		/* in: pointer to memory */
 	const char*	cfile_name,	/* in: file name where created */
-	ulint		cline)		/* in: file line where created */
+  ulint		cline,		/* in: file line where created */
+  const char*	cmutex_name)	/* in: mutex name */
 {
 #if defined(_WIN32) && defined(UNIV_CAN_USE_X86_ASSEMBLER)
 	mutex_reset_lock_word(mutex);
@@ -219,6 +215,16 @@ mutex_create_func(
 	mutex->level = SYNC_LEVEL_NONE;
 	mutex->cfile_name = cfile_name;
 	mutex->cline = cline;
+  mutex->cmutex_name=     cmutex_name;
+  mutex->count_using=     0;
+  mutex->mutex_type=      0;
+  mutex->lspent_time=     0;
+  mutex->lmax_spent_time=     0;
+  mutex->count_spin_loop= 0;
+  mutex->count_spin_rounds=   0; 
+  mutex->count_os_wait=   0;
+  mutex->count_os_yield=  0;
+
 	
 	/* Check that lock_word is aligned; this is important on Intel */
 	ut_ad(((ulint)(&(mutex->lock_word))) % 4 == 0);
@@ -355,135 +361,180 @@ for the mutex before suspending the thread. */
 void
 mutex_spin_wait(
 /*============*/
-        mutex_t*	   mutex,     	/* in: pointer to mutex */
-	const char*	   file_name, 	/* in: file name where
-					mutex requested */
-	ulint		   line)	/* in: line where requested */
+  mutex_t*	   mutex,     	/* in: pointer to mutex */
+  const char*	   file_name, 	/* in: file name where
+  				                    mutex requested */
+  ulint		   line)	/* in: line where requested */
 {
-        ulint    index; /* index of the reserved wait cell */
-        ulint    i;   	/* spin round count */
-        
-        ut_ad(mutex);
+  ulint    index; /* index of the reserved wait cell */
+  ulint    i;     /* spin round count */
+  ib_longlong lstart_time, lfinish_time; /* for timing os_wait */
+  ulint ltime_diff;
+  ulint sec;
+  ulint ms;
 
-mutex_loop:
+  uint timer_started = 0;
 
-        i = 0;
+  ut_ad(mutex);
 
-        /* Spin waiting for the lock word to become zero. Note that we do not
-	have to assume that the read access to the lock word is atomic, as the
-	actual locking is always committed with atomic test-and-set. In
-	reality, however, all processors probably have an atomic read of a
-	memory word. */
-        
-spin_loop:
-	mutex_spin_wait_count++;
+mutex_loop:
 
-        while (mutex_get_lock_word(mutex) != 0 && i < SYNC_SPIN_ROUNDS) {
+  i = 0;
 
-        	if (srv_spin_wait_delay) {
-        		ut_delay(ut_rnd_interval(0, srv_spin_wait_delay));
-        	}
-        
-             	i++;
-        }
+/* Spin waiting for the lock word to become zero. Note that we do not
+  have to assume that the read access to the lock word is atomic, as the
+  actual locking is always committed with atomic test-and-set. In
+  reality, however, all processors probably have an atomic read of a
+  memory word. */
 
-	if (i == SYNC_SPIN_ROUNDS) {
-		os_thread_yield();
-	}
+spin_loop:
+  mutex_spin_wait_count++;
+  mutex->count_spin_loop++;
+
+  while (mutex_get_lock_word(mutex) != 0 && i < SYNC_SPIN_ROUNDS)
+  {
+    if (srv_spin_wait_delay)
+    {
+      ut_delay(ut_rnd_interval(0, srv_spin_wait_delay));
+    }
+
+    i++;
+  }
+
+  if (i == SYNC_SPIN_ROUNDS)
+  {
+    mutex->count_os_yield++;
+    if (timed_mutexes == 1 && timer_started==0)
+    {
+      ut_usectime(&sec, &ms);
+      lstart_time= (ib_longlong)sec * 1000000 + ms;
+      timer_started = 1;
+    }
+    os_thread_yield();
+  }
+
+#ifdef UNIV_SRV_PRINT_LATCH_WAITS
+    fprintf(stderr,
+            "Thread %lu spin wait mutex at %p cfile %s cline %lu rnds %lu\n",
+            (ulong) os_thread_pf(os_thread_get_curr_id()), mutex,
+            mutex->cfile_name, (ulong) mutex->cline, (ulong) i);
+#endif
 
-	if (srv_print_latch_waits) {
-		fprintf(stderr,
-	"Thread %lu spin wait mutex at %p cfile %s cline %lu rnds %lu\n",
-		(ulong) os_thread_pf(os_thread_get_curr_id()), mutex,
-		mutex->cfile_name, (ulong) mutex->cline, (ulong) i);
-	}
+  mutex_spin_round_count += i;
 
-	mutex_spin_round_count += i;
+  mutex->count_spin_rounds += i;
 
-        if (mutex_test_and_set(mutex) == 0) {
-		/* Succeeded! */
+  if (mutex_test_and_set(mutex) == 0)
+  {
+    /* Succeeded! */
 
 #ifdef UNIV_SYNC_DEBUG
-		mutex_set_debug_info(mutex, file_name, line);
+    mutex_set_debug_info(mutex, file_name, line);
 #endif
 
-                return;
-   	}
+    goto finish_timing;
+  }
 
-	/* We may end up with a situation where lock_word is
-	0 but the OS fast mutex is still reserved. On FreeBSD
-	the OS does not seem to schedule a thread which is constantly
-	calling pthread_mutex_trylock (in mutex_test_and_set
-	implementation). Then we could end up spinning here indefinitely.
-	The following 'i++' stops this infinite spin. */
+  /* We may end up with a situation where lock_word is
+  0 but the OS fast mutex is still reserved. On FreeBSD
+  the OS does not seem to schedule a thread which is constantly
+  calling pthread_mutex_trylock (in mutex_test_and_set
+  implementation). Then we could end up spinning here indefinitely.
+  The following 'i++' stops this infinite spin. */
 
-	i++;
-        
-	if (i < SYNC_SPIN_ROUNDS) {
+  i++;
 
-		goto spin_loop;
-	}
+  if (i < SYNC_SPIN_ROUNDS)
+  {
+    goto spin_loop;
+  }
 
-        sync_array_reserve_cell(sync_primary_wait_array, mutex,
-        			SYNC_MUTEX,
-				file_name, line,
-				&index);
+  sync_array_reserve_cell(sync_primary_wait_array, mutex,
+                          SYNC_MUTEX, file_name, line, &index);
 
-	mutex_system_call_count++;
+  mutex_system_call_count++;
 
-	/* The memory order of the array reservation and the change in the
-	waiters field is important: when we suspend a thread, we first
-	reserve the cell and then set waiters field to 1. When threads are
-	released in mutex_exit, the waiters field is first set to zero and
-	then the event is set to the signaled state. */
-        
-	mutex_set_waiters(mutex, 1);
+  /* The memory order of the array reservation and the change in the
+  waiters field is important: when we suspend a thread, we first
+  reserve the cell and then set waiters field to 1. When threads are
+  released in mutex_exit, the waiters field is first set to zero and
+  then the event is set to the signaled state. */
+
+  mutex_set_waiters(mutex, 1);
 
-	/* Try to reserve still a few times */
-	for (i = 0; i < 4; i++) {
-            if (mutex_test_and_set(mutex) == 0) {
+  /* Try to reserve still a few times */
+  for (i = 0; i < 4; i++)
+  {
+    if (mutex_test_and_set(mutex) == 0)
+    {
+      /* Succeeded! Free the reserved wait cell */
 
-                /* Succeeded! Free the reserved wait cell */
+      sync_array_free_cell(sync_primary_wait_array, index);
 
-                sync_array_free_cell(sync_primary_wait_array, index);
-                
 #ifdef UNIV_SYNC_DEBUG
-		mutex_set_debug_info(mutex, file_name, line);
+      mutex_set_debug_info(mutex, file_name, line);
 #endif
 
-		if (srv_print_latch_waits) {
-			fprintf(stderr,
-				"Thread %lu spin wait succeeds at 2:"
-				" mutex at %p\n",
-			(ulong) os_thread_pf(os_thread_get_curr_id()),
-			mutex);
-		}
-		
-                return;
+#ifdef UNIV_SRV_PRINT_LATCH_WAITS
+        fprintf(stderr, "Thread %lu spin wait succeeds at 2:"
+                " mutex at %p\n",
+                (ulong) os_thread_pf(os_thread_get_curr_id()),
+                mutex);
+#endif
 
-                /* Note that in this case we leave the waiters field
-                set to 1. We cannot reset it to zero, as we do not know
-                if there are other waiters. */
-            }
-        }
+      goto finish_timing;
 
-        /* Now we know that there has been some thread holding the mutex
-        after the change in the wait array and the waiters field was made.
-	Now there is no risk of infinite wait on the event. */
+      /* Note that in this case we leave the waiters field
+      set to 1. We cannot reset it to zero, as we do not know
+      if there are other waiters. */
+    }
+  }
 
-	if (srv_print_latch_waits) {
-		fprintf(stderr,
-	"Thread %lu OS wait mutex at %p cfile %s cline %lu rnds %lu\n",
-		(ulong) os_thread_pf(os_thread_get_curr_id()), mutex,
-		mutex->cfile_name, (ulong) mutex->cline, (ulong) i);
-	}
-	
-	mutex_system_call_count++;
-	mutex_os_wait_count++;
+  /* Now we know that there has been some thread holding the mutex
+  after the change in the wait array and the waiters field was made.
+Now there is no risk of infinite wait on the event. */
 
-        sync_array_wait_event(sync_primary_wait_array, index);
+#ifdef UNIV_SRV_PRINT_LATCH_WAITS
+    fprintf(stderr,
+            "Thread %lu OS wait mutex at %p cfile %s cline %lu rnds %lu\n",
+            (ulong) os_thread_pf(os_thread_get_curr_id()), mutex,
+            mutex->cfile_name, (ulong) mutex->cline, (ulong) i);
+#endif
 
-        goto mutex_loop;        
+  mutex_system_call_count++;
+  mutex_os_wait_count++;
+
+  mutex->count_os_wait++;
+
+  /*
+    !!!!! Sometimes os_wait can be called without  os_thread_yield
+  */
+
+  if (timed_mutexes == 1 && timer_started==0)
+  {
+    ut_usectime(&sec, &ms);
+    lstart_time= (ib_longlong)sec * 1000000 + ms;
+    timer_started = 1;
+  }
+
+
+  sync_array_wait_event(sync_primary_wait_array, index);
+  goto mutex_loop;  
+
+finish_timing:
+  if (timed_mutexes == 1 && timer_started==1)
+  {
+    ut_usectime(&sec, &ms);
+    lfinish_time= (ib_longlong)sec * 1000000 + ms;
+
+    ltime_diff= lfinish_time - lstart_time;
+    mutex->lspent_time += ltime_diff;
+    if (mutex->lmax_spent_time < ltime_diff)
+    {
+      mutex->lmax_spent_time= ltime_diff;
+    }
+  }
+  return;
 }
 
 /**********************************************************************
@@ -555,6 +606,7 @@ mutex_set_level(
 	mutex->level = level;
 }
 
+
 #ifdef UNIV_SYNC_DEBUG
 /**********************************************************************
 Checks that the current thread owns the mutex. Works only in the debug

innobase/ut/ut0ut.c

@@ -73,6 +73,21 @@ ut_time(void)
 	return(time(NULL));
 }
 
+/**************************************************************
+Returns system time. We do not specify the format of the time returned:
+the only way to manipulate it is to use the function ut_difftime. */
+
+void
+ut_usectime(ulint* sec, ulint* ms)
+/*=========*/
+{
+  struct timeval tv;
+  gettimeofday(&tv,NULL);
+  *sec = (ulint) tv.tv_sec;
+  *ms  = (ulint) tv.tv_usec;
+  return;
+}
+
 /**************************************************************
 Returns the difference of two times in seconds. */
 

mysql-test/r/innodb.result

@@ -1700,5 +1700,20 @@ Innodb_rows_read	80161
 show status like "Innodb_rows_updated";
 Variable_name	Value
 Innodb_rows_updated	29530
+show status like "Innodb_row_lock_waits";
+Variable_name	Value
+Innodb_row_lock_waits	0
+show status like "Innodb_row_lock_current_waits";
+Variable_name	Value
+Innodb_row_lock_current_waits	0
+show status like "Innodb_row_lock_time";
+Variable_name	Value
+Innodb_row_lock_time	0
+show status like "Innodb_row_lock_time_max";
+Variable_name	Value
+Innodb_row_lock_time_max	0
+show status like "Innodb_row_lock_time_avg";
+Variable_name	Value
+Innodb_row_lock_time_avg	0
 create table t1 (v varchar(16384)) engine=innodb;
 ERROR 42000: Column length too big for column 'v' (max = 255); use BLOB instead

mysql-test/r/variables.result

@@ -137,6 +137,14 @@ set global concurrent_insert=DEFAULT;
 show variables like 'concurrent_insert';
 Variable_name	Value
 concurrent_insert	ON
+set global timed_mutexes=1;
+show variables like 'timed_mutexes';
+Variable_name	Value
+timed_mutexes	ON
+set global timed_mutexes=0;
+show variables like 'timed_mutexes';
+Variable_name	Value
+timed_mutexes	OFF
 set storage_engine=MYISAM, storage_engine="HEAP", global storage_engine="INNODB";
 show local variables like 'storage_engine';
 Variable_name	Value

mysql-test/t/innodb.test

@@ -1210,6 +1210,14 @@ show status like "Innodb_rows_deleted";
 show status like "Innodb_rows_inserted";
 show status like "Innodb_rows_read";
 show status like "Innodb_rows_updated";
+
+# Test for row locks InnoDB status variables.
+show status like "Innodb_row_lock_waits";
+show status like "Innodb_row_lock_current_waits";
+show status like "Innodb_row_lock_time";
+show status like "Innodb_row_lock_time_max";
+show status like "Innodb_row_lock_time_avg";
+
 #
 # Test varchar
 #

mysql-test/t/variables.test

@@ -83,6 +83,12 @@ show variables like 'concurrent_insert';
 set global concurrent_insert=DEFAULT;
 show variables like 'concurrent_insert';
 
+set global timed_mutexes=1;
+show variables like 'timed_mutexes';
+set global timed_mutexes=0;
+show variables like 'timed_mutexes';
+
+
 set storage_engine=MYISAM, storage_engine="HEAP", global storage_engine="INNODB";
 show local variables like 'storage_engine';
 show global variables like 'storage_engine';

sql/ha_innodb.cc

@@ -231,6 +231,16 @@ struct show_var_st innodb_status_variables[]= {
   (char*) &export_vars.innodb_pages_read,                 SHOW_LONG},
   {"pages_written",
   (char*) &export_vars.innodb_pages_written,              SHOW_LONG},
+  {"row_lock_waits",
+  (char*) &export_vars.innodb_row_lock_waits,             SHOW_LONG},
+  {"row_lock_current_waits",
+  (char*) &export_vars.innodb_row_lock_current_waits,     SHOW_LONG},
+  {"row_lock_time",
+  (char*) &export_vars.innodb_row_lock_time,              SHOW_LONGLONG},
+  {"row_lock_time_max",
+  (char*) &export_vars.innodb_row_lock_time_max,          SHOW_LONG},
+  {"row_lock_time_avg",
+  (char*) &export_vars.innodb_row_lock_time_avg,          SHOW_LONG},
   {"rows_deleted",
   (char*) &export_vars.innodb_rows_deleted,               SHOW_LONG},
   {"rows_inserted",
@@ -5505,6 +5515,103 @@ innodb_show_status(
   	DBUG_RETURN(FALSE);
 }
 
+/****************************************************************************
+Implements the SHOW MUTEX STATUS command. . */
+
+bool
+innodb_mutex_show_status(
+/*===============*/
+  THD*  thd)  /* in: the MySQL query thread of the caller */
+{
+  Protocol        *protocol= thd->protocol;
+  List<Item> field_list;
+  mutex_t*  mutex;
+  const char* file_name;
+  ulint   line;
+  ulint   rw_lock_count= 0;
+  ulint   rw_lock_count_spin_loop= 0;
+  ulint   rw_lock_count_spin_rounds= 0;
+  ulint   rw_lock_count_os_wait= 0;
+  ulint   rw_lock_count_os_yield= 0;
+  ulonglong rw_lock_wait_time= 0;
+
+  DBUG_ENTER("innodb_mutex_show_status");
+
+  field_list.push_back(new Item_empty_string("Mutex", FN_REFLEN));
+  field_list.push_back(new Item_empty_string("Module", FN_REFLEN));
+  field_list.push_back(new Item_uint("Count", 21));
+  field_list.push_back(new Item_uint("Spin_waits", 21));
+  field_list.push_back(new Item_uint("Spin_rounds", 21));
+  field_list.push_back(new Item_uint("OS_waits", 21));
+  field_list.push_back(new Item_uint("OS_yields", 21));
+  field_list.push_back(new Item_uint("OS_waits_time", 21));
+
+  if (protocol->send_fields(&field_list,
+                            Protocol::SEND_NUM_ROWS | Protocol::SEND_EOF))
+    DBUG_RETURN(TRUE);
+
+//  mutex_enter(&mutex_list_mutex);
+
+  mutex = UT_LIST_GET_FIRST(mutex_list);
+
+  while ( mutex != NULL )
+  {
+    if (mutex->mutex_type != 1)
+    {
+      if (mutex->count_using > 0)
+      {
+        protocol->prepare_for_resend();
+        protocol->store(mutex->cmutex_name, system_charset_info);
+        protocol->store(mutex->cfile_name, system_charset_info);
+        protocol->store((ulonglong)mutex->count_using);
+        protocol->store((ulonglong)mutex->count_spin_loop);
+        protocol->store((ulonglong)mutex->count_spin_rounds);
+        protocol->store((ulonglong)mutex->count_os_wait);
+        protocol->store((ulonglong)mutex->count_os_yield);
+        protocol->store((ulonglong)mutex->lspent_time/1000);
+
+        if (protocol->write())
+        {
+//          mutex_exit(&mutex_list_mutex);
+          DBUG_RETURN(1);
+        }
+      }
+    }
+    else
+    {
+      rw_lock_count += mutex->count_using;
+      rw_lock_count_spin_loop += mutex->count_spin_loop;
+      rw_lock_count_spin_rounds += mutex->count_spin_rounds;
+      rw_lock_count_os_wait += mutex->count_os_wait;
+      rw_lock_count_os_yield += mutex->count_os_yield;
+      rw_lock_wait_time += mutex->lspent_time;
+    }
+
+    mutex = UT_LIST_GET_NEXT(list, mutex);
+  }
+
+  protocol->prepare_for_resend();
+  protocol->store("rw_lock_mutexes", system_charset_info);
+  protocol->store("", system_charset_info);
+  protocol->store((ulonglong)rw_lock_count);
+  protocol->store((ulonglong)rw_lock_count_spin_loop);
+  protocol->store((ulonglong)rw_lock_count_spin_rounds);
+  protocol->store((ulonglong)rw_lock_count_os_wait);
+  protocol->store((ulonglong)rw_lock_count_os_yield);
+  protocol->store((ulonglong)rw_lock_wait_time/1000);
+
+  if (protocol->write())
+  {
+//          mutex_exit(&mutex_list_mutex);
+    DBUG_RETURN(1);
+  }
+
+
+//          mutex_exit(&mutex_list_mutex);
+  send_eof(thd);
+  DBUG_RETURN(FALSE);
+}
+
 /****************************************************************************
  Handling the shared INNOBASE_SHARE structure that is needed to provide table
  locking.

sql/ha_innodb.h

@@ -242,6 +242,7 @@ int innobase_savepoint(
 int innobase_close_connection(THD *thd);
 int innobase_drop_database(char *path);
 bool innodb_show_status(THD* thd);
+bool innodb_mutex_show_status(THD* thd);
 void innodb_export_status(void);
 
 my_bool innobase_query_caching_of_table_permitted(THD* thd, char* full_name,

sql/lex.h

@@ -323,6 +323,7 @@ static SYMBOL symbols[] = {
   { "MULTILINESTRING",	SYM(MULTILINESTRING)},
   { "MULTIPOINT",	SYM(MULTIPOINT)},
   { "MULTIPOLYGON",	SYM(MULTIPOLYGON)},
+  { "MUTEX",	SYM(MUTEX_SYM)},
   { "NAME",             SYM(NAME_SYM)},
   { "NAMES",		SYM(NAMES_SYM)},
   { "NATIONAL",		SYM(NATIONAL_SYM)},

sql/mysql_priv.h

@@ -998,6 +998,7 @@ extern ulong table_cache_size;
 extern ulong max_connections,max_connect_errors, connect_timeout;
 extern ulong slave_net_timeout;
 extern ulong max_user_connections;
+extern my_bool timed_mutexes;
 extern ulong what_to_log,flush_time;
 extern ulong query_buff_size, thread_stack,thread_stack_min;
 extern ulong binlog_cache_size, max_binlog_cache_size, open_files_limit;

sql/mysqld.cc

@@ -325,6 +325,7 @@ ulong binlog_cache_use= 0, binlog_cache_disk_use= 0;
 ulong max_connections,max_used_connections,
       max_connect_errors, max_user_connections = 0;
 ulong thread_id=1L,current_pid;
+my_bool timed_mutexes= 0;
 ulong slow_launch_threads = 0, sync_binlog_period;
 ulong expire_logs_days = 0;
 ulong rpl_recovery_rank=0;
@@ -4200,7 +4201,8 @@ enum options_mysqld
   OPT_OPTIMIZER_PRUNE_LEVEL,
   OPT_UPDATABLE_VIEWS_WITH_LIMIT,
   OPT_AUTO_INCREMENT, OPT_AUTO_INCREMENT_OFFSET,
-  OPT_ENABLE_LARGE_PAGES
+  OPT_ENABLE_LARGE_PAGES,
+  OPT_TIMED_MUTEXES
 };
 
 
@@ -4799,6 +4801,10 @@ log and this option does nothing anymore.",
    "Using this option will cause most temporary files created to use a small set of names, rather than a unique name for each new file.",
    (gptr*) &use_temp_pool, (gptr*) &use_temp_pool, 0, GET_BOOL, NO_ARG, 1,
    0, 0, 0, 0, 0},
+  {"timed_mutexes", OPT_TIMED_MUTEXES,
+   "Specify whether to time mutexes (only InnoDB mutexes are currently supported)",
+   (gptr*) &timed_mutexes, (gptr*) &timed_mutexes, 0, GET_BOOL, NO_ARG, 0, 
+    0, 0, 0, 0, 0},
   {"tmpdir", 't',
    "Path for temporary files. Several paths may be specified, separated by a "
 #if defined(__WIN__) || defined(OS2) || defined(__NETWARE__)

sql/set_var.cc

@@ -361,6 +361,8 @@ sys_var_thd_enum	sys_tx_isolation("tx_isolation",
 					 fix_tx_isolation);
 sys_var_thd_ulong	sys_tmp_table_size("tmp_table_size",
 					   &SV::tmp_table_size);
+sys_var_bool_ptr	sys_timed_mutexes("timed_mutexes",
+					    &timed_mutexes);
 sys_var_thd_ulong	sys_net_wait_timeout("wait_timeout",
 					     &SV::net_wait_timeout);
 
@@ -635,6 +637,7 @@ sys_var *sys_variables[]=
   &sys_table_type,
   &sys_thread_cache_size,
   &sys_time_format,
+  &sys_timed_mutexes,
   &sys_timestamp,
   &sys_time_zone,
   &sys_tmp_table_size,
@@ -901,6 +904,7 @@ struct show_var_st init_vars[]= {
   {"thread_stack",            (char*) &thread_stack,                SHOW_LONG},
   {sys_time_format.name,      (char*) &sys_time_format,		    SHOW_SYS},
   {"time_zone",               (char*) &sys_time_zone,               SHOW_SYS},
+  {sys_timed_mutexes.name,    (char*) &sys_timed_mutexes,	      SHOW_SYS},
   {sys_tmp_table_size.name,   (char*) &sys_tmp_table_size,	    SHOW_SYS},
   {"tmpdir",                  (char*) &opt_mysql_tmpdir,            SHOW_CHAR_PTR},
   {sys_trans_alloc_block_size.name, (char*) &sys_trans_alloc_block_size,

sql/sql_lex.h

@@ -53,7 +53,7 @@ enum enum_sql_command {
 
   SQLCOM_SHOW_DATABASES, SQLCOM_SHOW_TABLES, SQLCOM_SHOW_FIELDS,
   SQLCOM_SHOW_KEYS, SQLCOM_SHOW_VARIABLES, SQLCOM_SHOW_LOGS, SQLCOM_SHOW_STATUS,
-  SQLCOM_SHOW_INNODB_STATUS,
+  SQLCOM_SHOW_INNODB_STATUS, SQLCOM_SHOW_MUTEX_STATUS,
   SQLCOM_SHOW_PROCESSLIST, SQLCOM_SHOW_MASTER_STAT, SQLCOM_SHOW_SLAVE_STAT,
   SQLCOM_SHOW_GRANTS, SQLCOM_SHOW_CREATE, SQLCOM_SHOW_CHARSETS,
   SQLCOM_SHOW_COLLATIONS, SQLCOM_SHOW_CREATE_DB, SQLCOM_SHOW_TABLE_STATUS,

sql/sql_parse.cc

@@ -2488,6 +2488,13 @@ mysql_execute_command(THD *thd)
       res = innodb_show_status(thd);
       break;
     }
+  case SQLCOM_SHOW_MUTEX_STATUS:
+    {
+      if (check_global_access(thd, SUPER_ACL))
+	goto error;
+      res = innodb_mutex_show_status(thd);
+      break;
+    }
 #endif
 #ifdef HAVE_REPLICATION
   case SQLCOM_LOAD_MASTER_TABLE:

sql/sql_yacc.yy

@@ -337,6 +337,7 @@ bool my_yyoverflow(short **a, YYSTYPE **b, ulong *yystacksize);
 %token	MAX_UPDATES_PER_HOUR
 %token	MEDIUM_SYM
 %token	MIN_ROWS
+%token	MUTEX_SYM
 %token	NAMES_SYM
 %token	NAME_SYM
 %token	NATIONAL_SYM
@@ -5986,6 +5987,8 @@ show_param:
 	  }	
         | INNOBASE_SYM STATUS_SYM
           { Lex->sql_command = SQLCOM_SHOW_INNODB_STATUS; WARN_DEPRECATED("SHOW INNODB STATUS", "SHOW ENGINE INNODB STATUS"); }
+        | MUTEX_SYM STATUS_SYM
+          { Lex->sql_command = SQLCOM_SHOW_MUTEX_STATUS; }
 	| opt_full PROCESSLIST_SYM
 	  { Lex->sql_command= SQLCOM_SHOW_PROCESSLIST;}
 	| opt_var_type VARIABLES wild
@@ -6987,6 +6990,7 @@ keyword:
 	| MULTILINESTRING	{}
 	| MULTIPOINT		{}
 	| MULTIPOLYGON		{}
+	| MUTEX_SYM		{}
 	| NAME_SYM              {}
 	| NAMES_SYM		{}
 	| NATIONAL_SYM		{}