List:Commits« Previous MessageNext Message »
From:marko.makela Date:March 30 2011 11:26am
Subject:bzr commit into mysql-5.1-innodb branch (marko.makela:3719) Bug#11877216
View as plain text  
#At file:///home/marko/innobase/dev/mysql2a/5.1-innodb/ based on revid:vasil.dimov@strippedy0rkbeenhd1

 3719 Marko Mäkelä	2011-03-30
      Bug#11877216 InnoDB too eager to commit suicide on a busy server
      
      sync_array_print_long_waits(): Return the longest waiting thread ID
      and the longest waited-for lock. Only if those remain unchanged
      between calls in srv_error_monitor_thread(), increment
      fatal_cnt. Otherwise, reset fatal_cnt.
      
      Background: There is a built-in watchdog in InnoDB whose purpose is to
      kill the server when some thread is stuck waiting for a mutex or
      rw-lock. Before this fix, the logic was flawed.
      
      The function sync_array_print_long_waits() returns TRUE if it finds a
      lock wait that exceeds 10 minutes (srv_fatal_semaphore_wait_threshold).
      The function srv_error_monitor_thread() will kill the server if this
      happens 10 times in a row (fatal_cnt reaches 10), checked every 30
      seconds. This is wrong, because this situation does not mean that the
      server is hung. If the server is very busy for a little over 15
      minutes, it will be killed.
      
      Consider this example. Thread T1 is waiting for mutex M. Some time
      later, threads T2..Tn start waiting for the same mutex M. If T1 keeps
      waiting for 600 seconds, fatal_cnt will be incremented to 1. So far,
      so good. Now, if M is granted to T1, the server was obviously not
      stuck. But, T2..Tn keeps waiting, and their wait time will be longer
      than 600 seconds. If 5 minutes later, some Tn has still been waiting
      for more than 10 minutes for the mutex M, the server can be killed,
      even though it is not stuck.
      
      rb:622 approved by Jimmy Yang

    modified:
      storage/innobase/include/sync0arr.h
      storage/innobase/srv/srv0srv.c
      storage/innobase/sync/sync0arr.c
      storage/innodb_plugin/ChangeLog
      storage/innodb_plugin/include/sync0arr.h
      storage/innodb_plugin/srv/srv0srv.c
      storage/innodb_plugin/sync/sync0arr.c
=== modified file 'storage/innobase/include/sync0arr.h'
--- a/storage/innobase/include/sync0arr.h	revid:vasil.dimov@stripped110328083412-odusry0rkbeenhd1
+++ b/storage/innobase/include/sync0arr.h	revid:marko.makela@stripped58-5qleclsijpqg52bf
@@ -93,10 +93,13 @@ sync_arr_wake_threads_if_sema_free(void)
 Prints warnings of long semaphore waits to stderr. */
 
 ibool
-sync_array_print_long_waits(void);
-/*=============================*/
-			/* out: TRUE if fatal semaphore wait threshold
-			was exceeded */
+sync_array_print_long_waits(
+/*========================*/
+				/* out: TRUE if fatal semaphore wait threshold
+				was exceeded */
+	os_thread_id_t*	waiter,	/* out: longest waiting thread */
+	const void**	sema)	/* out: longest-waited-for semaphore */
+	__attribute__((nonnull));
 /************************************************************************
 Validates the integrity of the wait array. Checks
 that the number of reserved cells equals the count variable. */

=== modified file 'storage/innobase/srv/srv0srv.c'
--- a/storage/innobase/srv/srv0srv.c	revid:vasil.dimov@stripped
+++ b/storage/innobase/srv/srv0srv.c	revid:marko.makela@oracle.com-20110330112558-5qleclsijpqg52bf
@@ -2180,9 +2180,15 @@ srv_error_monitor_thread(
 			os_thread_create */
 {
 	/* number of successive fatal timeouts observed */
-	ulint	fatal_cnt	= 0;
-	dulint	old_lsn;
-	dulint	new_lsn;
+	ulint		fatal_cnt	= 0;
+	dulint		old_lsn;
+	dulint		new_lsn;
+	/* longest waiting thread for a semaphore */
+	os_thread_id_t	waiter		= os_thread_get_curr_id();
+	os_thread_id_t	old_waiter	= waiter;
+	/* the semaphore that is being waited for */
+	const void*	sema		= NULL;
+	const void*	old_sema	= NULL;
 
 	old_lsn = srv_start_lsn;
 
@@ -2224,10 +2230,11 @@ loop:
 	/* In case mutex_exit is not a memory barrier, it is
 	theoretically possible some threads are left waiting though
 	the semaphore is already released. Wake up those threads: */
-	
+
 	sync_arr_wake_threads_if_sema_free();
 
-	if (sync_array_print_long_waits()) {
+	if (sync_array_print_long_waits(&waiter, &sema)
+	    && sema == old_sema && os_thread_eq(waiter, old_waiter)) {
 		fatal_cnt++;
 		if (fatal_cnt > 10) {
 
@@ -2242,6 +2249,8 @@ loop:
 		}
 	} else {
 		fatal_cnt = 0;
+		old_waiter = waiter;
+		old_sema = sema;
 	}
 
 	/* Flush stderr so that a database user gets the output

=== modified file 'storage/innobase/sync/sync0arr.c'
--- a/storage/innobase/sync/sync0arr.c	revid:vasil.dimov@stripped0110328083412-odusry0rkbeenhd1
+++ b/storage/innobase/sync/sync0arr.c	revid:marko.makela@stripped-5qleclsijpqg52bf
@@ -916,10 +916,12 @@ sync_arr_wake_threads_if_sema_free(void)
 Prints warnings of long semaphore waits to stderr. */
 
 ibool
-sync_array_print_long_waits(void)
-/*=============================*/
-			/* out: TRUE if fatal semaphore wait threshold
-			was exceeded */
+sync_array_print_long_waits(
+/*========================*/
+				/* out: TRUE if fatal semaphore wait threshold
+				was exceeded */
+	os_thread_id_t*	waiter,	/* out: longest waiting thread */
+	const void**	sema)	/* out: longest-waited-for semaphore */
 {
 	sync_cell_t*	cell;
 	ibool		old_val;
@@ -927,24 +929,40 @@ sync_array_print_long_waits(void)
 	ulint		i;
 	ulint		fatal_timeout = srv_fatal_semaphore_wait_threshold;
 	ibool		fatal = FALSE;
+	double		longest_diff = 0;
 
 	for (i = 0; i < sync_primary_wait_array->n_cells; i++) {
 
+		double	diff;
+		void*	wait_object;
+
 		cell = sync_array_get_nth_cell(sync_primary_wait_array, i);
 
-		if (cell->wait_object != NULL && cell->waiting
-		    && difftime(time(NULL), cell->reservation_time) > 240) {
+		wait_object = cell->wait_object;
+
+		if (wait_object == NULL || !cell->waiting) {
+
+			continue;
+		}
+
+		diff = difftime(time(NULL), cell->reservation_time);
+
+		if (diff > 240) {
 			fputs("InnoDB: Warning: a long semaphore wait:\n",
 			      stderr);
 			sync_array_cell_print(stderr, cell);
 			noticed = TRUE;
 		}
 
-		if (cell->wait_object != NULL && cell->waiting
-		    && difftime(time(NULL), cell->reservation_time)
-		    > fatal_timeout) {
+		if (diff > fatal_timeout) {
 			fatal = TRUE;
 		}
+
+		if (diff > longest_diff) {
+			longest_diff = diff;
+			*sema = wait_object;
+			*waiter = cell->thread;
+		}
 	}
 
 	if (noticed) {

=== modified file 'storage/innodb_plugin/ChangeLog'
--- a/storage/innodb_plugin/ChangeLog	revid:vasil.dimov@stripped28083412-odusry0rkbeenhd1
+++ b/storage/innodb_plugin/ChangeLog	revid:marko.makela@strippedlsijpqg52bf
@@ -1,3 +1,8 @@
+2011-03-30	The InnoDB Team
+
+	* srv/srv0srv.c, sync/sync0arr.h, sync/sync0arr.c:
+	Fix Bug#11877216 InnoDB too eager to commit suicide on a busy server
+
 2011-03-15	The InnoDB Team
 
 	* btr/btr0cur.c, page/page0zip.c:

=== modified file 'storage/innodb_plugin/include/sync0arr.h'
--- a/storage/innodb_plugin/include/sync0arr.h	revid:vasil.dimov@stripped412-odusry0rkbeenhd1
+++ b/storage/innodb_plugin/include/sync0arr.h	revid:marko.makela@strippedqleclsijpqg52bf
@@ -115,8 +115,11 @@ Prints warnings of long semaphore waits
 @return	TRUE if fatal semaphore wait threshold was exceeded */
 UNIV_INTERN
 ibool
-sync_array_print_long_waits(void);
-/*=============================*/
+sync_array_print_long_waits(
+/*========================*/
+	os_thread_id_t*	waiter,	/*!< out: longest waiting thread */
+	const void**	sema)	/*!< out: longest-waited-for semaphore */
+	__attribute__((nonnull));
 /********************************************************************//**
 Validates the integrity of the wait array. Checks
 that the number of reserved cells equals the count variable. */

=== modified file 'storage/innodb_plugin/srv/srv0srv.c'
--- a/storage/innodb_plugin/srv/srv0srv.c	revid:vasil.dimov@stripped
+++ b/storage/innodb_plugin/srv/srv0srv.c	revid:marko.makela@stripped
@@ -2236,6 +2236,12 @@ srv_error_monitor_thread(
 	ulint		fatal_cnt	= 0;
 	ib_uint64_t	old_lsn;
 	ib_uint64_t	new_lsn;
+	/* longest waiting thread for a semaphore */
+	os_thread_id_t	waiter		= os_thread_get_curr_id();
+	os_thread_id_t	old_waiter	= waiter;
+	/* the semaphore that is being waited for */
+	const void*	sema		= NULL;
+	const void*	old_sema	= NULL;
 
 	old_lsn = srv_start_lsn;
 
@@ -2284,7 +2290,8 @@ loop:
 
 	sync_arr_wake_threads_if_sema_free();
 
-	if (sync_array_print_long_waits()) {
+	if (sync_array_print_long_waits(&waiter, &sema)
+	    && sema == old_sema && os_thread_eq(waiter, old_waiter)) {
 		fatal_cnt++;
 		if (fatal_cnt > 10) {
 
@@ -2299,6 +2306,8 @@ loop:
 		}
 	} else {
 		fatal_cnt = 0;
+		old_waiter = waiter;
+		old_sema = sema;
 	}
 
 	/* Flush stderr so that a database user gets the output

=== modified file 'storage/innodb_plugin/sync/sync0arr.c'
--- a/storage/innodb_plugin/sync/sync0arr.c	revid:vasil.dimov@strippedusry0rkbeenhd1
+++ b/storage/innodb_plugin/sync/sync0arr.c	revid:marko.makela@strippedqg52bf
@@ -914,8 +914,10 @@ Prints warnings of long semaphore waits
 @return	TRUE if fatal semaphore wait threshold was exceeded */
 UNIV_INTERN
 ibool
-sync_array_print_long_waits(void)
-/*=============================*/
+sync_array_print_long_waits(
+/*========================*/
+	os_thread_id_t*	waiter,	/*!< out: longest waiting thread */
+	const void**	sema)	/*!< out: longest-waited-for semaphore */
 {
 	sync_cell_t*	cell;
 	ibool		old_val;
@@ -923,24 +925,40 @@ sync_array_print_long_waits(void)
 	ulint		i;
 	ulint		fatal_timeout = srv_fatal_semaphore_wait_threshold;
 	ibool		fatal = FALSE;
+	double		longest_diff = 0;
 
 	for (i = 0; i < sync_primary_wait_array->n_cells; i++) {
 
+		double	diff;
+		void*	wait_object;
+
 		cell = sync_array_get_nth_cell(sync_primary_wait_array, i);
 
-		if (cell->wait_object != NULL && cell->waiting
-		    && difftime(time(NULL), cell->reservation_time) > 240) {
+		wait_object = cell->wait_object;
+
+		if (wait_object == NULL || !cell->waiting) {
+
+			continue;
+		}
+
+		diff = difftime(time(NULL), cell->reservation_time);
+
+		if (diff > 240) {
 			fputs("InnoDB: Warning: a long semaphore wait:\n",
 			      stderr);
 			sync_array_cell_print(stderr, cell);
 			noticed = TRUE;
 		}
 
-		if (cell->wait_object != NULL && cell->waiting
-		    && difftime(time(NULL), cell->reservation_time)
-		    > fatal_timeout) {
+		if (diff > fatal_timeout) {
 			fatal = TRUE;
 		}
+
+		if (diff > longest_diff) {
+			longest_diff = diff;
+			*sema = wait_object;
+			*waiter = cell->thread;
+		}
 	}
 
 	if (noticed) {

Attachment: [text/bzr-bundle] bzr/marko.makela@oracle.com-20110330112558-5qleclsijpqg52bf.bundle
Thread
bzr commit into mysql-5.1-innodb branch (marko.makela:3719) Bug#11877216marko.makela30 Mar