------------------------------------------------------------ revno: 3379 revision-id: vasil.dimov@oracle.com-20101213120811-k2ldtnao2t6zrxfn parent: vasil.dimov@oracle.com-20101212092901-yvlhd9xby5xtc3fn committer: Vasil Dimov branch nick: mysql-trunk-innodb timestamp: Mon 2010-12-13 14:08:11 +0200 message: Implement WL#5674 InnoDB: report all deadlocks (Bug#1784) Bug#1784 ability to log details on all deadlocks When InnoDB encounters a deadlock it prints the information to a dedicated file. Later when SHOW ENGINE INNODB STATUS is called, it reads the data from this file and sends it to the user. When a new deadlock occurs, the dedicated file is rewind(3)ed and the information about the new deadlock is printed into it. The implementation of this WorkLog simply duplicates what is printed into the dedicated file into stderr. A new configuration parameter is added --innodb-print-all-deadlocks (off by default) which when enabled causes the deadlock info to be printed to stderr. Approved by: Jimmy (rb://533) diff: === modified file 'storage/innobase/handler/ha_innodb.cc' --- storage/innobase/handler/ha_innodb.cc revid:vasil.dimov@oracle.com-20101212092901-yvlhd9xby5xtc3fn +++ storage/innobase/handler/ha_innodb.cc revid:vasil.dimov@oracle.com-20101213120811-k2ldtnao2t6zrxfn @@ -12245,6 +12245,11 @@ innodb_monitor_validate, innodb_reset_all_monitor_update, NULL); +static MYSQL_SYSVAR_BOOL(print_all_deadlocks, srv_print_all_deadlocks, + PLUGIN_VAR_OPCMDARG, + "Print all deadlocks to MySQL error log (off by default)", + NULL, NULL, FALSE); + static struct st_mysql_sys_var* innobase_system_variables[]= { MYSQL_SYSVAR(additional_mem_pool_size), MYSQL_SYSVAR(autoextend_increment), @@ -12319,6 +12324,7 @@ #if defined UNIV_DEBUG || defined UNIV_PERF_DEBUG MYSQL_SYSVAR(page_hash_locks), #endif /* defined UNIV_DEBUG || defined UNIV_PERF_DEBUG */ + MYSQL_SYSVAR(print_all_deadlocks), NULL }; === modified file 'storage/innobase/include/srv0srv.h' --- storage/innobase/include/srv0srv.h revid:vasil.dimov@oracle.com-20101212092901-yvlhd9xby5xtc3fn +++ storage/innobase/include/srv0srv.h revid:vasil.dimov@oracle.com-20101213120811-k2ldtnao2t6zrxfn @@ -322,6 +322,9 @@ reading of a disk page */ extern ulint srv_buf_pool_reads; +/* print all user-level transactions deadlocks to mysqld stderr */ +extern my_bool srv_print_all_deadlocks; + /** Status variables to be passed to MySQL */ typedef struct export_var_struct export_struc; === modified file 'storage/innobase/lock/lock0lock.c' --- storage/innobase/lock/lock0lock.c revid:vasil.dimov@oracle.com-20101212092901-yvlhd9xby5xtc3fn +++ storage/innobase/lock/lock0lock.c revid:vasil.dimov@oracle.com-20101213120811-k2ldtnao2t6zrxfn @@ -3328,6 +3328,80 @@ /*=========== DEADLOCK CHECKING ======================================*/ +/*********************************************************************//** +rewind(3) the file used for storing the latest detected deadlock and +print a heading message to stderr if printing of all deadlocks to stderr +is enabled. */ +UNIV_INLINE +void +lock_deadlock_start_print() +/*=======================*/ +{ + rewind(lock_latest_err_file); + ut_print_timestamp(lock_latest_err_file); + + if (srv_print_all_deadlocks) { + fprintf(stderr, "InnoDB: transactions deadlock detected, " + "dumping detailed information.\n"); + ut_print_timestamp(stderr); + } +} + +/*********************************************************************//** +Print a message to the deadlock file and possibly to stderr. */ +UNIV_INLINE +void +lock_deadlock_fputs( +/*================*/ + const char* msg) /*!< in: message to print */ +{ + fputs(msg, lock_latest_err_file); + + if (srv_print_all_deadlocks) { + fputs(msg, stderr); + } +} + +/*********************************************************************//** +Print transaction data to the deadlock file and possibly to stderr. */ +UNIV_INLINE +void +lock_deadlock_trx_print( +/*====================*/ + trx_t* trx, /*!< in: transaction */ + ulint max_query_len) /*!< in: max query length to print, or 0 to + use the default max length */ +{ + trx_print(lock_latest_err_file, trx, max_query_len); + + if (srv_print_all_deadlocks) { + trx_print(stderr, trx, max_query_len); + } +} + +/*********************************************************************//** +Print lock data to the deadlock file and possibly to stderr. */ +UNIV_INLINE +void +lock_deadlock_lock_print( +/*=====================*/ + const lock_t* lock) /*!< in: record or table type lock */ +{ + if (lock_get_type_low(lock) == LOCK_REC) { + lock_rec_print(lock_latest_err_file, lock); + + if (srv_print_all_deadlocks) { + lock_rec_print(stderr, lock); + } + } else { + lock_table_print(lock_latest_err_file, lock); + + if (srv_print_all_deadlocks) { + lock_table_print(stderr, lock); + } + } +} + /********************************************************************//** Checks if a lock request results in a deadlock. @return TRUE if a deadlock was detected and we chose trx as a victim; @@ -3383,38 +3457,32 @@ /* If the lock search exceeds the max step or the max depth, the current trx will be the victim. Print its information. */ - rewind(lock_latest_err_file); - ut_print_timestamp(lock_latest_err_file); - - fputs("TOO DEEP OR LONG SEARCH IN THE LOCK TABLE" - " WAITS-FOR GRAPH, WE WILL ROLL BACK" - " FOLLOWING TRANSACTION \n", - lock_latest_err_file); - - fputs("\n*** TRANSACTION:\n", lock_latest_err_file); + lock_deadlock_start_print(); + + lock_deadlock_fputs( + "TOO DEEP OR LONG SEARCH IN THE LOCK TABLE" + " WAITS-FOR GRAPH, WE WILL ROLL BACK" + " FOLLOWING TRANSACTION \n\n" + "*** TRANSACTION:\n"); /* To obey the latching order */ trx_mutex_exit(trx); rw_lock_s_lock(&trx_sys->lock); - trx_print(lock_latest_err_file, trx, 3000); + lock_deadlock_trx_print(trx, 3000); rw_lock_s_unlock(&trx_sys->lock); trx_mutex_enter(trx); - fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n", - lock_latest_err_file); - - if (lock_get_type(lock) == LOCK_REC) { - lock_rec_print(lock_latest_err_file, lock); - } else { - lock_table_print(lock_latest_err_file, lock); - } + lock_deadlock_fputs( + "*** WAITING FOR THIS LOCK TO BE GRANTED:\n"); + + lock_deadlock_lock_print(lock); + break; case LOCK_VICTIM_IS_START: - fputs("*** WE ROLL BACK TRANSACTION (2)\n", - lock_latest_err_file); + lock_deadlock_fputs("*** WE ROLL BACK TRANSACTION (2)\n"); break; default: @@ -3516,8 +3584,6 @@ if (lock_trx == start) { - FILE* ef; - /* To obey the latching order */ trx_mutex_exit(start); @@ -3525,51 +3591,36 @@ point: a deadlock detected; or we have searched the waits-for graph too long */ - ef = lock_latest_err_file; - - rewind(ef); - ut_print_timestamp(ef); - - fputs("\n*** (1) TRANSACTION:\n", ef); - - rw_lock_s_lock(&trx_sys->lock); - trx_print(ef, wait_lock->trx, 3000); - rw_lock_s_unlock(&trx_sys->lock); - - fputs("*** (1) WAITING FOR THIS LOCK" - " TO BE GRANTED:\n", ef); - - if (lock_get_type_low(wait_lock) == LOCK_REC) { - lock_rec_print(ef, wait_lock); - } else { - lock_table_print(ef, wait_lock); - } - - fputs("*** (2) TRANSACTION:\n", ef); - - rw_lock_s_lock(&trx_sys->lock); - trx_print(ef, lock->trx, 3000); - rw_lock_s_unlock(&trx_sys->lock); - - fputs("*** (2) HOLDS THE LOCK(S):\n", ef); - - if (lock_get_type_low(lock) == LOCK_REC) { - lock_rec_print(ef, lock); - } else { - lock_table_print(ef, lock); - } - - fputs("*** (2) WAITING FOR THIS LOCK" - " TO BE GRANTED:\n", ef); - - if (lock_get_type_low(start->lock.wait_lock) - == LOCK_REC) { - lock_rec_print(ef, - start->lock.wait_lock); - } else { - lock_table_print(ef, - start->lock.wait_lock); - } + lock_deadlock_start_print(); + + lock_deadlock_fputs("\n*** (1) TRANSACTION:\n"); + + rw_lock_s_lock(&trx_sys->lock); + lock_deadlock_trx_print(wait_lock->trx, 3000); + rw_lock_s_unlock(&trx_sys->lock); + + lock_deadlock_fputs( + "*** (1) WAITING FOR THIS LOCK" + " TO BE GRANTED:\n"); + + lock_deadlock_lock_print(wait_lock); + + lock_deadlock_fputs("*** (2) TRANSACTION:\n"); + + rw_lock_s_lock(&trx_sys->lock); + lock_deadlock_trx_print(lock->trx, 3000); + rw_lock_s_unlock(&trx_sys->lock); + + lock_deadlock_fputs( + "*** (2) HOLDS THE LOCK(S):\n"); + + lock_deadlock_lock_print(lock); + + lock_deadlock_fputs( + "*** (2) WAITING FOR THIS LOCK" + " TO BE GRANTED:\n"); + + lock_deadlock_lock_print(start->lock.wait_lock); #ifdef UNIV_DEBUG if (lock_print_waits) { fputs("Deadlock detected\n", @@ -3595,8 +3646,8 @@ as a victim to try to avoid deadlocking our recursion starting point transaction */ - fputs("*** WE ROLL BACK TRANSACTION (1)\n", - ef); + lock_deadlock_fputs( + "*** WE ROLL BACK TRANSACTION (1)\n"); wait_lock->trx->lock.was_chosen_as_deadlock_victim = TRUE; === modified file 'storage/innobase/srv/srv0srv.c' --- storage/innobase/srv/srv0srv.c revid:vasil.dimov@oracle.com-20101212092901-yvlhd9xby5xtc3fn +++ storage/innobase/srv/srv0srv.c revid:vasil.dimov@oracle.com-20101213120811-k2ldtnao2t6zrxfn @@ -327,6 +327,9 @@ assertions to catch any corner cases that we may have missed. */ UNIV_INTERN lint srv_conc_n_threads = 0; +/* print all user-level transactions deadlocks to mysqld stderr */ +UNIV_INTERN my_bool srv_print_all_deadlocks = FALSE; + /* this mutex protects srv_conc data structures */ static os_fast_mutex_t srv_conc_mutex;