diff options
| -rw-r--r-- | storage/innobase/include/lock0lock.h | 16 | ||||
| -rw-r--r-- | storage/innobase/include/lock0priv.h | 12 | ||||
| -rw-r--r-- | storage/innobase/include/srv0srv.h | 12 | ||||
| -rw-r--r-- | storage/innobase/include/trx0i_s.h | 3 | ||||
| -rw-r--r-- | storage/innobase/lock/lock0lock.cc | 233 | ||||
| -rw-r--r-- | storage/innobase/lock/lock0wait.cc | 15 | ||||
| -rw-r--r-- | storage/xtradb/include/lock0lock.h | 16 | ||||
| -rw-r--r-- | storage/xtradb/include/lock0priv.h | 12 | ||||
| -rw-r--r-- | storage/xtradb/include/srv0srv.h | 5 | ||||
| -rw-r--r-- | storage/xtradb/include/trx0i_s.h | 3 | ||||
| -rw-r--r-- | storage/xtradb/lock/lock0lock.cc | 236 | ||||
| -rw-r--r-- | storage/xtradb/lock/lock0wait.cc | 15 |
12 files changed, 284 insertions, 294 deletions
diff --git a/storage/innobase/include/lock0lock.h b/storage/innobase/include/lock0lock.h index 615ebec16d3..2628cdfc461 100644 --- a/storage/innobase/include/lock0lock.h +++ b/storage/innobase/include/lock0lock.h @@ -615,22 +615,6 @@ lock_report_trx_id_insanity( trx_id_t max_trx_id) /*!< in: trx_sys_get_max_trx_id() */ MY_ATTRIBUTE((nonnull)); /*********************************************************************//** -Prints info of a table lock. */ -UNIV_INTERN -void -lock_table_print( -/*=============*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock); /*!< in: table type lock */ -/*********************************************************************//** -Prints info of a record lock. */ -UNIV_INTERN -void -lock_rec_print( -/*===========*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock); /*!< in: record type lock */ -/*********************************************************************//** Prints info of locks for all transactions. @return FALSE if not able to obtain lock mutex and exits without printing info */ diff --git a/storage/innobase/include/lock0priv.h b/storage/innobase/include/lock0priv.h index eee46e0a1bd..ef502be9044 100644 --- a/storage/innobase/include/lock0priv.h +++ b/storage/innobase/include/lock0priv.h @@ -74,10 +74,14 @@ struct lock_t { 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 */ + /** time(NULL) of the lock request creation. + Used for computing wait_time and diagnostics only. + Note: bogus durations may be reported + when the system time is adjusted! */ + time_t requested_time; + /** Cumulated wait time in seconds. + Note: may be bogus when the system time is adjusted! */ + ulint wait_time; union { lock_table_t tab_lock;/*!< table lock */ diff --git a/storage/innobase/include/srv0srv.h b/storage/innobase/include/srv0srv.h index 7e83f9fa725..37e249f3f07 100644 --- a/storage/innobase/include/srv0srv.h +++ b/storage/innobase/include/srv0srv.h @@ -1078,10 +1078,14 @@ struct srv_slot_t{ ibool suspended; /*!< TRUE if the thread is waiting for the event of this slot */ - ib_time_t suspend_time; /*!< time when the thread was - suspended. Initialized by - lock_wait_table_reserve_slot() - for lock wait */ + /** time(NULL) when the thread was suspended. + FIXME: Use my_interval_timer() or similar, to avoid bogus + timeouts in lock_wait_check_and_cancel() or lock_wait_suspend_thread() + when the system time is adjusted to the past! + + FIXME: This is duplicating trx_lock_t::wait_started, + which is being used for diagnostic purposes only. */ + time_t suspend_time; ulong wait_timeout; /*!< wait time that if exceeded the thread will be timed out. Initialized by diff --git a/storage/innobase/include/trx0i_s.h b/storage/innobase/include/trx0i_s.h index 3ee2ad63ab5..2d0b7f01f7e 100644 --- a/storage/innobase/include/trx0i_s.h +++ b/storage/innobase/include/trx0i_s.h @@ -1,6 +1,7 @@ /***************************************************************************** Copyright (c) 2007, 2011, Oracle and/or its affiliates. All Rights Reserved. +Copyright (c) 2019, 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 @@ -133,7 +134,7 @@ struct i_s_trx_row_t { /*!< pointer to a row in innodb_locks if trx is waiting, or NULL */ - ib_time_t trx_wait_started; /*!< trx_t::wait_started */ + time_t trx_wait_started; /*!< trx->lock.wait_started */ ullint trx_weight; /*!< TRX_WEIGHT() */ ulint trx_mysql_thread_id; /*!< thd_get_thread_id() */ const char* trx_query; /*!< MySQL statement being diff --git a/storage/innobase/lock/lock0lock.cc b/storage/innobase/lock/lock0lock.cc index c0933ee7fdf..ab2b536a7d7 100644 --- a/storage/innobase/lock/lock0lock.cc +++ b/storage/innobase/lock/lock0lock.cc @@ -383,6 +383,20 @@ struct lock_stack_t { ulint heap_no; /*!< heap number if rec lock */ }; +/** Pretty-print a table lock. +@param[in,out] file output stream +@param[in] lock table lock +@param[in] now current time */ +static void lock_table_print(FILE* file, const lock_t* lock, time_t now); + +/** Pretty-print a record lock. +@param[in,out] file output stream +@param[in] lock record lock +@param[in] now current time +@param[in,out] mtr mini-transaction */ +static void lock_rec_print(FILE* file, const lock_t* lock, time_t now, + mtr_t* mtr = NULL); + /*********************************************************************//** Checks if a waiting record lock request still has to wait in a queue. @return lock that is causing the wait */ @@ -466,20 +480,18 @@ UNIV_INTERN ibool lock_deadlock_found = FALSE; /** Only created if !srv_read_only_mode */ static FILE* lock_latest_err_file; -/********************************************************************//** -Checks if a joining lock request results in a deadlock. If a deadlock is +/** Check if a joining lock request results in a deadlock. If a deadlock is found this function will resolve the dadlock by choosing a victim transaction -and rolling it back. It will attempt to resolve all deadlocks. The returned -transaction id will be the joining transaction id or 0 if some other -transaction was chosen as a victim and rolled back or no deadlock found. - -@return id of transaction chosen as victim or 0 */ -static -trx_id_t -lock_deadlock_check_and_resolve( -/*===========================*/ - const lock_t* lock, /*!< in: lock the transaction is requesting */ - const trx_t* trx); /*!< in: transaction */ +and rolling it back. It will attempt to resolve all deadlocks. +@param[in] trx joining transaction +@param[in] lock the requested lock +@param[in] now current time +@return trx->id of the victim transaction +@retval 0 if some other transaction was chosen as a victim and +rolled back, or no deadlock was found. */ +static trx_id_t lock_deadlock_check_and_resolve(const trx_t* trx, + const lock_t* lock, + time_t now); /*********************************************************************//** Gets the nth bit of a record lock. @@ -1135,12 +1147,11 @@ lock_rec_has_to_wait( thread, we need to look at trx ordering and lock types */ if (wsrep_thd_is_BF(trx->mysql_thd, FALSE) && wsrep_thd_is_BF(lock2->trx->mysql_thd, TRUE)) { - if (wsrep_debug) { fprintf(stderr, "BF-BF lock conflict, locking: %lu\n", for_locking); - lock_rec_print(stderr, lock2); + lock_rec_print(stderr, lock2, time(NULL)); } if (wsrep_trx_order_before(trx->mysql_thd, @@ -1159,7 +1170,8 @@ lock_rec_has_to_wait( "conflicts states: my %d locked %d\n", wsrep_thd_conflict_state(trx->mysql_thd, FALSE), wsrep_thd_conflict_state(lock2->trx->mysql_thd, FALSE) ); - lock_rec_print(stderr, lock2); + lock_rec_print(stderr, lock2, + time(NULL)); if (for_locking) return FALSE; //abort(); } @@ -1786,10 +1798,12 @@ wsrep_kill_victim( fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n", stderr); + time_t now = time(NULL); + if (lock_get_type(lock) == LOCK_REC) { - lock_rec_print(stderr, lock); + lock_rec_print(stderr, lock, now); } else { - lock_table_print(stderr, lock); + lock_table_print(stderr, lock, now); } } @@ -2032,16 +2046,20 @@ wsrep_print_wait_locks( { if (wsrep_debug && c_lock->trx->lock.wait_lock != c_lock) { fprintf(stderr, "WSREP: c_lock != wait lock\n"); + time_t now = time(NULL); + if (lock_get_type_low(c_lock) & LOCK_TABLE) { - lock_table_print(stderr, c_lock); + lock_table_print(stderr, c_lock, now); } else { - lock_rec_print(stderr, c_lock); + lock_rec_print(stderr, c_lock, now); } if (lock_get_type_low(c_lock->trx->lock.wait_lock) & LOCK_TABLE) { - lock_table_print(stderr, c_lock->trx->lock.wait_lock); + lock_table_print(stderr, c_lock->trx->lock.wait_lock, + now); } else { - lock_rec_print(stderr, c_lock->trx->lock.wait_lock); + lock_rec_print(stderr, c_lock->trx->lock.wait_lock, + now); } } } @@ -2477,7 +2495,8 @@ lock_rec_enqueue_waiting( trx_mutex_exit(trx); - victim_trx_id = lock_deadlock_check_and_resolve(lock, trx); + const time_t now = time(NULL); + victim_trx_id = lock_deadlock_check_and_resolve(trx, lock, now); trx_mutex_enter(trx); @@ -2501,7 +2520,7 @@ lock_rec_enqueue_waiting( trx->lock.que_state = TRX_QUE_LOCK_WAIT; trx->lock.was_chosen_as_deadlock_victim = FALSE; - trx->lock.wait_started = ut_time(); + trx->lock.wait_started = now; ut_a(que_thr_stop(thr)); @@ -2642,7 +2661,8 @@ lock_rec_add_to_queue( "BF skipping wait: " TRX_ID_FMT "\n", trx->id); - lock_rec_print(stderr, lock); + lock_rec_print(stderr, lock, + time(NULL)); } } else #endif @@ -2958,13 +2978,14 @@ lock_rec_has_to_wait_in_queue( if (wsrep_thd_is_BF(wait_lock->trx->mysql_thd, FALSE) && wsrep_thd_is_BF(lock->trx->mysql_thd, TRUE)) { if (wsrep_debug) { + time_t now = time(NULL); fprintf(stderr, "BF-BF lock conflict " TRX_ID_FMT " : " TRX_ID_FMT "\n", wait_lock->trx->id, lock->trx->id); - lock_rec_print(stderr, wait_lock); - lock_rec_print(stderr, lock); + lock_rec_print(stderr, wait_lock, now); + lock_rec_print(stderr, lock, now); } /* don't wait for another BF lock */ continue; @@ -4293,28 +4314,26 @@ lock_deadlock_trx_print( mutex_exit(&trx_sys->mutex); } -/*********************************************************************//** -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 */ +/** Print lock data to the deadlock file and possibly to stderr. +@param[in] lock record or table lock +@param[in] now current time */ +static void lock_deadlock_lock_print(const lock_t* lock, time_t now) { ut_ad(lock_mutex_own()); ut_ad(!srv_read_only_mode); if (lock_get_type_low(lock) == LOCK_REC) { - lock_rec_print(lock_latest_err_file, lock); + mtr_t mtr; + lock_rec_print(lock_latest_err_file, lock, now, &mtr); if (srv_print_all_deadlocks) { - lock_rec_print(stderr, lock); + lock_rec_print(stderr, lock, now, &mtr); } } else { - lock_table_print(lock_latest_err_file, lock); + lock_table_print(lock_latest_err_file, lock, now); if (srv_print_all_deadlocks) { - lock_table_print(stderr, lock); + lock_table_print(stderr, lock, now); } } } @@ -4427,6 +4446,8 @@ lock_deadlock_notify( ut_ad(lock_mutex_own()); ut_ad(!srv_read_only_mode); + const time_t now = time(NULL); + lock_deadlock_start_print(); lock_deadlock_fputs("\n*** (1) TRANSACTION:\n"); @@ -4435,7 +4456,7 @@ lock_deadlock_notify( lock_deadlock_fputs("*** (1) WAITING FOR THIS LOCK TO BE GRANTED:\n"); - lock_deadlock_lock_print(ctx->wait_lock); + lock_deadlock_lock_print(ctx->wait_lock, now); lock_deadlock_fputs("*** (2) TRANSACTION:\n"); @@ -4443,7 +4464,7 @@ lock_deadlock_notify( lock_deadlock_fputs("*** (2) HOLDS THE LOCK(S):\n"); - lock_deadlock_lock_print(lock); + lock_deadlock_lock_print(lock, now); /* It is possible that the joining transaction was granted its lock when we rolled back some other waiting transaction. */ @@ -4452,7 +4473,7 @@ lock_deadlock_notify( lock_deadlock_fputs( "*** (2) WAITING FOR THIS LOCK TO BE GRANTED:\n"); - lock_deadlock_lock_print(ctx->start->lock.wait_lock); + lock_deadlock_lock_print(ctx->start->lock.wait_lock, now); } #ifdef UNIV_DEBUG @@ -4700,14 +4721,12 @@ lock_deadlock_search( return(0); } -/********************************************************************//** -Print info about transaction that was rolled back. */ -static -void -lock_deadlock_joining_trx_print( -/*============================*/ - const trx_t* trx, /*!< in: transaction rolled back */ - const lock_t* lock) /*!< in: lock trx wants */ +/** Print info about transaction that was rolled back. +@param[in] trx victim transaction +@param[in] lock the requested lock +@param[in] now current time */ +static void lock_deadlock_joining_trx_print(const trx_t* trx, + const lock_t* lock, time_t now) { ut_ad(lock_mutex_own()); ut_ad(!srv_read_only_mode); @@ -4727,7 +4746,7 @@ lock_deadlock_joining_trx_print( lock_deadlock_fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n"); - lock_deadlock_lock_print(lock); + lock_deadlock_lock_print(lock, now); } /********************************************************************//** @@ -4797,20 +4816,17 @@ lock_report_waiters_to_mysql( } -/********************************************************************//** -Checks if a joining lock request results in a deadlock. If a deadlock is +/** Check if a joining lock request results in a deadlock. If a deadlock is found this function will resolve the dadlock by choosing a victim transaction -and rolling it back. It will attempt to resolve all deadlocks. The returned -transaction id will be the joining transaction id or 0 if some other -transaction was chosen as a victim and rolled back or no deadlock found. - -@return id of transaction chosen as victim or 0 */ -static -trx_id_t -lock_deadlock_check_and_resolve( -/*============================*/ - const lock_t* lock, /*!< in: lock the transaction is requesting */ - const trx_t* trx) /*!< in: transaction */ +and rolling it back. It will attempt to resolve all deadlocks. +@param[in] trx joining transaction +@param[in] lock the requested lock +@param[in] now current time +@return trx->id of the victim transaction +@retval 0 if some other transaction was chosen as a victim and +rolled back, or no deadlock was found. */ +static trx_id_t lock_deadlock_check_and_resolve(const trx_t* trx, + const lock_t* lock, time_t now) { trx_id_t victim_trx_id; struct thd_wait_reports waitee_buf; @@ -4862,17 +4878,12 @@ lock_deadlock_check_and_resolve( ut_a(victim_trx_id == trx->id); #ifdef WITH_WSREP - if (!wsrep_thd_is_BF(ctx.start->mysql_thd, TRUE)) - { + if (!wsrep_thd_is_BF(ctx.start->mysql_thd, TRUE)); else #endif /* WITH_WSREP */ - if (!srv_read_only_mode) { - lock_deadlock_joining_trx_print(trx, lock); - } -#ifdef WITH_WSREP - } else { - /* BF processor */; + if (!srv_read_only_mode) { + lock_deadlock_joining_trx_print(trx, lock, + now); } -#endif /* WITH_WSREP */ MONITOR_INC(MONITOR_DEADLOCK); @@ -5218,7 +5229,9 @@ lock_table_enqueue_waiting( trx_mutex_exit(trx); - victim_trx_id = lock_deadlock_check_and_resolve(lock, trx); + const time_t now = time(NULL); + + victim_trx_id = lock_deadlock_check_and_resolve(trx, lock, now); trx_mutex_enter(trx); @@ -5240,7 +5253,7 @@ lock_table_enqueue_waiting( trx->lock.que_state = TRX_QUE_LOCK_WAIT; - trx->lock.wait_started = ut_time(); + trx->lock.wait_started = now; trx->lock.was_chosen_as_deadlock_victim = FALSE; trx->n_table_lock_waits++; @@ -5984,14 +5997,11 @@ lock_remove_all_on_table( /*===================== VALIDATION AND DEBUGGING ====================*/ -/*********************************************************************//** -Prints info of a table lock. */ -UNIV_INTERN -void -lock_table_print( -/*=============*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock) /*!< in: table type lock */ +/** Pretty-print a table lock. +@param[in,out] file output stream +@param[in] lock table lock +@param[in] now current time */ +static void lock_table_print(FILE* file, const lock_t* lock, time_t now) { ut_ad(lock_mutex_own()); ut_a(lock_get_type_low(lock) == LOCK_TABLE); @@ -6021,30 +6031,22 @@ lock_table_print( } fprintf(file, " lock hold time %lu wait time before grant %lu ", - (ulint)difftime(ut_time(), lock->requested_time), + (ulint)difftime(now, lock->requested_time), lock->wait_time); putc('\n', file); } -/*********************************************************************//** -Prints info of a record lock. */ -UNIV_INTERN -void -lock_rec_print( -/*===========*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock) /*!< in: record type lock */ +/** Pretty-print a record lock. +@param[in,out] file output stream +@param[in] lock record lock +@param[in] now current time +@param[in,out] mtr mini-transaction */ +static void lock_rec_print(FILE* file, const lock_t* lock, time_t now, + mtr_t* mtr) { - const buf_block_t* block; ulint space; ulint page_no; - ulint i; - mtr_t mtr; - mem_heap_t* heap = NULL; - ulint offsets_[REC_OFFS_NORMAL_SIZE]; - ulint* offsets = offsets_; - rec_offs_init(offsets_); ut_ad(lock_mutex_own()); ut_a(lock_get_type_low(lock) == LOCK_REC); @@ -6089,17 +6091,25 @@ lock_rec_print( fputs(" waiting", file); } - mtr_start(&mtr); - fprintf(file, " lock hold time %lu wait time before grant %lu ", - (ulint)difftime(ut_time(), lock->requested_time), + (ulint)difftime(now, lock->requested_time), lock->wait_time); putc('\n', file); - block = buf_page_try_get(space, page_no, &mtr); + if (!mtr) { + return; + } + + mem_heap_t* heap = NULL; + ulint offsets_[REC_OFFS_NORMAL_SIZE]; + ulint* offsets = offsets_; + rec_offs_init(offsets_); + + mtr_start(mtr); + const buf_block_t* block = buf_page_try_get(space, page_no, mtr); - for (i = 0; i < lock_rec_get_n_bits(lock); ++i) { + for (ulint i = 0; i < lock_rec_get_n_bits(lock); ++i) { if (!lock_rec_get_nth_bit(lock, i)) { continue; @@ -6124,7 +6134,7 @@ lock_rec_print( putc('\n', file); } - mtr_commit(&mtr); + mtr_commit(mtr); if (UNIV_LIKELY_NULL(heap)) { mem_heap_free(heap); } @@ -6280,6 +6290,8 @@ lock_print_info_all_transactions( ut_ad(lock_mutex_own()); + const time_t now = time(NULL); + mutex_enter(&trx_sys->mutex); /* First print info on non-active transactions */ @@ -6366,13 +6378,14 @@ loop: fprintf(file, "------- TRX HAS BEEN WAITING %lu SEC" " FOR THIS LOCK TO BE GRANTED:\n", - (ulong) difftime(ut_time(), - trx->lock.wait_started)); + (ulong) difftime(now, trx->lock.wait_started)); if (lock_get_type_low(trx->lock.wait_lock) == LOCK_REC) { - lock_rec_print(file, trx->lock.wait_lock); + lock_rec_print(file, trx->lock.wait_lock, now, + &mtr); } else { - lock_table_print(file, trx->lock.wait_lock); + lock_table_print(file, trx->lock.wait_lock, + now); } fputs("------------------\n", file); @@ -6457,11 +6470,11 @@ loop: } print_rec: - lock_rec_print(file, lock); + lock_rec_print(file, lock, now, &mtr); } else { ut_ad(lock_get_type_low(lock) & LOCK_TABLE); - lock_table_print(file, lock); + lock_table_print(file, lock, now); } load_page_first = TRUE; diff --git a/storage/innobase/lock/lock0wait.cc b/storage/innobase/lock/lock0wait.cc index 5d6db2f171a..2be579bf644 100644 --- a/storage/innobase/lock/lock0wait.cc +++ b/storage/innobase/lock/lock0wait.cc @@ -226,7 +226,6 @@ lock_wait_suspend_thread( user OS thread */ { srv_slot_t* slot; - double wait_time; trx_t* trx; ulint had_dict_lock; ibool was_declared_inside_innodb; @@ -360,7 +359,7 @@ lock_wait_suspend_thread( row_mysql_freeze_data_dictionary(trx); } - wait_time = ut_difftime(ut_time(), slot->suspend_time); + double wait_time = difftime(time(NULL), slot->suspend_time); /* Release the slot for others to use */ @@ -451,19 +450,12 @@ lock_wait_check_and_cancel( const srv_slot_t* slot) /*!< in: slot reserved by a user thread when the wait started */ { - trx_t* trx; - double wait_time; - ib_time_t suspend_time = slot->suspend_time; - ut_ad(lock_wait_mutex_own()); - ut_ad(slot->in_use); - ut_ad(slot->suspended); - wait_time = ut_difftime(ut_time(), suspend_time); - - trx = thr_get_trx(slot->thr); + double wait_time = difftime(time(NULL), slot->suspend_time); + trx_t* trx = thr_get_trx(slot->thr); if (trx_is_interrupted(trx) || (slot->wait_timeout < 100000000 @@ -497,7 +489,6 @@ lock_wait_check_and_cancel( trx_mutex_exit(trx); } - } /*********************************************************************//** diff --git a/storage/xtradb/include/lock0lock.h b/storage/xtradb/include/lock0lock.h index c57c25ae827..878a42ea81b 100644 --- a/storage/xtradb/include/lock0lock.h +++ b/storage/xtradb/include/lock0lock.h @@ -629,22 +629,6 @@ lock_report_trx_id_insanity( trx_id_t max_trx_id) /*!< in: trx_sys_get_max_trx_id() */ MY_ATTRIBUTE((nonnull)); /*********************************************************************//** -Prints info of a table lock. */ -UNIV_INTERN -void -lock_table_print( -/*=============*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock); /*!< in: table type lock */ -/*********************************************************************//** -Prints info of a record lock. */ -UNIV_INTERN -void -lock_rec_print( -/*===========*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock); /*!< in: record type lock */ -/*********************************************************************//** Prints info of locks for all transactions. @return FALSE if not able to obtain lock mutex and exits without printing info */ diff --git a/storage/xtradb/include/lock0priv.h b/storage/xtradb/include/lock0priv.h index 0107d7cd2ba..3b2c7f08020 100644 --- a/storage/xtradb/include/lock0priv.h +++ b/storage/xtradb/include/lock0priv.h @@ -74,10 +74,14 @@ struct lock_t { 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 */ + /** time(NULL) of the lock request creation. + Used for computing wait_time and diagnostics only. + Note: bogus durations may be reported + when the system time is adjusted! */ + time_t requested_time; + /** Cumulated wait time in seconds. + Note: may be bogus when the system time is adjusted! */ + ulint wait_time; union { lock_table_t tab_lock;/*!< table lock */ diff --git a/storage/xtradb/include/srv0srv.h b/storage/xtradb/include/srv0srv.h index e8dd1954797..c222c419f9d 100644 --- a/storage/xtradb/include/srv0srv.h +++ b/storage/xtradb/include/srv0srv.h @@ -1332,7 +1332,10 @@ struct srv_slot_t{ /** time(NULL) when the thread was suspended. FIXME: Use my_interval_timer() or similar, to avoid bogus timeouts in lock_wait_check_and_cancel() or lock_wait_suspend_thread() - when the system time is adjusted to the past! */ + when the system time is adjusted to the past! + + FIXME: This is duplicating trx_lock_t::wait_started, + which is being used for diagnostic purposes only. */ time_t suspend_time; ulong wait_timeout; /*!< wait time that if exceeded the thread will be timed out. diff --git a/storage/xtradb/include/trx0i_s.h b/storage/xtradb/include/trx0i_s.h index c71def52b61..96646613847 100644 --- a/storage/xtradb/include/trx0i_s.h +++ b/storage/xtradb/include/trx0i_s.h @@ -1,6 +1,7 @@ /***************************************************************************** Copyright (c) 2007, 2011, Oracle and/or its affiliates. All Rights Reserved. +Copyright (c) 2019, 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 @@ -133,7 +134,7 @@ struct i_s_trx_row_t { /*!< pointer to a row in innodb_locks if trx is waiting, or NULL */ - ib_time_t trx_wait_started; /*!< trx_t::wait_started */ + time_t trx_wait_started; /*!< trx->lock.wait_started */ ullint trx_weight; /*!< TRX_WEIGHT() */ ulint trx_mysql_thread_id; /*!< thd_get_thread_id() */ const char* trx_query; /*!< MySQL statement being diff --git a/storage/xtradb/lock/lock0lock.cc b/storage/xtradb/lock/lock0lock.cc index 061813cd8ab..b0ab3e7a540 100644 --- a/storage/xtradb/lock/lock0lock.cc +++ b/storage/xtradb/lock/lock0lock.cc @@ -383,6 +383,20 @@ struct lock_stack_t { ulint heap_no; /*!< heap number if rec lock */ }; +/** Pretty-print a table lock. +@param[in,out] file output stream +@param[in] lock table lock +@param[in] now current time */ +static void lock_table_print(FILE* file, const lock_t* lock, time_t now); + +/** Pretty-print a record lock. +@param[in,out] file output stream +@param[in] lock record lock +@param[in] now current time +@param[in,out] mtr mini-transaction */ +static void lock_rec_print(FILE* file, const lock_t* lock, time_t now, + mtr_t* mtr = NULL); + /*********************************************************************//** Checks if a waiting record lock request still has to wait in a queue. @return lock that is causing the wait */ @@ -466,20 +480,18 @@ UNIV_INTERN ibool lock_deadlock_found = FALSE; /** Only created if !srv_read_only_mode */ static FILE* lock_latest_err_file; -/********************************************************************//** -Checks if a joining lock request results in a deadlock. If a deadlock is +/** Check if a joining lock request results in a deadlock. If a deadlock is found this function will resolve the dadlock by choosing a victim transaction -and rolling it back. It will attempt to resolve all deadlocks. The returned -transaction id will be the joining transaction id or 0 if some other -transaction was chosen as a victim and rolled back or no deadlock found. - -@return id of transaction chosen as victim or 0 */ -static -trx_id_t -lock_deadlock_check_and_resolve( -/*===========================*/ - const lock_t* lock, /*!< in: lock the transaction is requesting */ - const trx_t* trx); /*!< in: transaction */ +and rolling it back. It will attempt to resolve all deadlocks. +@param[in] trx joining transaction +@param[in] lock the requested lock +@param[in] now current time +@return trx->id of the victim transaction +@retval 0 if some other transaction was chosen as a victim and +rolled back, or no deadlock was found. */ +static trx_id_t lock_deadlock_check_and_resolve(const trx_t* trx, + const lock_t* lock, + time_t now); /*********************************************************************//** Gets the nth bit of a record lock. @@ -1147,12 +1159,11 @@ lock_rec_has_to_wait( thread, we need to look at trx ordering and lock types */ if (wsrep_thd_is_BF(trx->mysql_thd, FALSE) && wsrep_thd_is_BF(lock2->trx->mysql_thd, TRUE)) { - if (wsrep_debug) { fprintf(stderr, "BF-BF lock conflict, locking: %lu\n", for_locking); - lock_rec_print(stderr, lock2); + lock_rec_print(stderr, lock2, time(NULL)); } if (wsrep_trx_order_before(trx->mysql_thd, @@ -1171,7 +1182,8 @@ lock_rec_has_to_wait( "conflicts states: my %d locked %d\n", wsrep_thd_conflict_state(trx->mysql_thd, FALSE), wsrep_thd_conflict_state(lock2->trx->mysql_thd, FALSE) ); - lock_rec_print(stderr, lock2); + lock_rec_print(stderr, lock2, + time(NULL)); if (for_locking) return FALSE; //abort(); } @@ -1797,10 +1809,12 @@ wsrep_kill_victim( fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n", stderr); + time_t now = time(NULL); + if (lock_get_type(lock) == LOCK_REC) { - lock_rec_print(stderr, lock); + lock_rec_print(stderr, lock, now); } else { - lock_table_print(stderr, lock); + lock_table_print(stderr, lock, now); } } @@ -2055,16 +2069,20 @@ wsrep_print_wait_locks( { if (wsrep_debug && c_lock->trx->lock.wait_lock != c_lock) { fprintf(stderr, "WSREP: c_lock != wait lock\n"); + time_t now = time(NULL); + if (lock_get_type_low(c_lock) & LOCK_TABLE) { - lock_table_print(stderr, c_lock); + lock_table_print(stderr, c_lock, now); } else { - lock_rec_print(stderr, c_lock); + lock_rec_print(stderr, c_lock, now); } if (lock_get_type_low(c_lock->trx->lock.wait_lock) & LOCK_TABLE) { - lock_table_print(stderr, c_lock->trx->lock.wait_lock); + lock_table_print(stderr, c_lock->trx->lock.wait_lock, + now); } else { - lock_rec_print(stderr, c_lock->trx->lock.wait_lock); + lock_rec_print(stderr, c_lock->trx->lock.wait_lock, + now); } } } @@ -2503,7 +2521,8 @@ lock_rec_enqueue_waiting( trx_mutex_exit(trx); - victim_trx_id = lock_deadlock_check_and_resolve(lock, trx); + const time_t now = time(NULL); + victim_trx_id = lock_deadlock_check_and_resolve(trx, lock, now); trx_mutex_enter(trx); @@ -2527,7 +2546,7 @@ lock_rec_enqueue_waiting( trx->lock.que_state = TRX_QUE_LOCK_WAIT; trx->lock.was_chosen_as_deadlock_victim = FALSE; - trx->lock.wait_started = ut_time(); + trx->lock.wait_started = now; if (UNIV_UNLIKELY(trx->take_stats)) { trx->lock_que_wait_nstarted = my_interval_timer(); @@ -2672,7 +2691,8 @@ lock_rec_add_to_queue( "BF skipping wait: " TRX_ID_FMT "\n", trx->id); - lock_rec_print(stderr, lock); + lock_rec_print(stderr, lock, + time(NULL)); } } else #endif @@ -2991,13 +3011,14 @@ lock_rec_has_to_wait_in_queue( if (wsrep_thd_is_BF(wait_lock->trx->mysql_thd, FALSE) && wsrep_thd_is_BF(lock->trx->mysql_thd, TRUE)) { if (wsrep_debug) { + time_t now = time(NULL); fprintf(stderr, "BF-BF lock conflict " TRX_ID_FMT " : " TRX_ID_FMT "\n", wait_lock->trx->id, lock->trx->id); - lock_rec_print(stderr, wait_lock); - lock_rec_print(stderr, lock); + lock_rec_print(stderr, wait_lock, now); + lock_rec_print(stderr, lock, now); } /* don't wait for another BF lock */ continue; @@ -4328,28 +4349,26 @@ lock_deadlock_trx_print( mutex_exit(&trx_sys->mutex); } -/*********************************************************************//** -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 */ +/** Print lock data to the deadlock file and possibly to stderr. +@param[in] lock record or table lock +@param[in] now current time */ +static void lock_deadlock_lock_print(const lock_t* lock, time_t now) { ut_ad(lock_mutex_own()); ut_ad(!srv_read_only_mode); if (lock_get_type_low(lock) == LOCK_REC) { - lock_rec_print(lock_latest_err_file, lock); + mtr_t mtr; + lock_rec_print(lock_latest_err_file, lock, now, &mtr); if (srv_print_all_deadlocks) { - lock_rec_print(stderr, lock); + lock_rec_print(stderr, lock, now, &mtr); } } else { - lock_table_print(lock_latest_err_file, lock); + lock_table_print(lock_latest_err_file, lock, now); if (srv_print_all_deadlocks) { - lock_table_print(stderr, lock); + lock_table_print(stderr, lock, now); } } } @@ -4462,6 +4481,8 @@ lock_deadlock_notify( ut_ad(lock_mutex_own()); ut_ad(!srv_read_only_mode); + const time_t now = time(NULL); + lock_deadlock_start_print(); lock_deadlock_fputs("\n*** (1) TRANSACTION:\n"); @@ -4470,7 +4491,7 @@ lock_deadlock_notify( lock_deadlock_fputs("*** (1) WAITING FOR THIS LOCK TO BE GRANTED:\n"); - lock_deadlock_lock_print(ctx->wait_lock); + lock_deadlock_lock_print(ctx->wait_lock, now); lock_deadlock_fputs("*** (2) TRANSACTION:\n"); @@ -4478,7 +4499,7 @@ lock_deadlock_notify( lock_deadlock_fputs("*** (2) HOLDS THE LOCK(S):\n"); - lock_deadlock_lock_print(lock); + lock_deadlock_lock_print(lock, now); /* It is possible that the joining transaction was granted its lock when we rolled back some other waiting transaction. */ @@ -4487,7 +4508,7 @@ lock_deadlock_notify( lock_deadlock_fputs( "*** (2) WAITING FOR THIS LOCK TO BE GRANTED:\n"); - lock_deadlock_lock_print(ctx->start->lock.wait_lock); + lock_deadlock_lock_print(ctx->start->lock.wait_lock, now); } #ifdef UNIV_DEBUG @@ -4736,14 +4757,12 @@ lock_deadlock_search( return(0); } -/********************************************************************//** -Print info about transaction that was rolled back. */ -static -void -lock_deadlock_joining_trx_print( -/*============================*/ - const trx_t* trx, /*!< in: transaction rolled back */ - const lock_t* lock) /*!< in: lock trx wants */ +/** Print info about transaction that was rolled back. +@param[in] trx victim transaction +@param[in] lock the requested lock +@param[in] now current time */ +static void lock_deadlock_joining_trx_print(const trx_t* trx, + const lock_t* lock, time_t now) { ut_ad(lock_mutex_own()); ut_ad(!srv_read_only_mode); @@ -4763,7 +4782,7 @@ lock_deadlock_joining_trx_print( lock_deadlock_fputs("*** WAITING FOR THIS LOCK TO BE GRANTED:\n"); - lock_deadlock_lock_print(lock); + lock_deadlock_lock_print(lock, now); } /********************************************************************//** @@ -4833,20 +4852,17 @@ lock_report_waiters_to_mysql( } -/********************************************************************//** -Checks if a joining lock request results in a deadlock. If a deadlock is +/** Check if a joining lock request results in a deadlock. If a deadlock is found this function will resolve the dadlock by choosing a victim transaction -and rolling it back. It will attempt to resolve all deadlocks. The returned -transaction id will be the joining transaction id or 0 if some other -transaction was chosen as a victim and rolled back or no deadlock found. - -@return id of transaction chosen as victim or 0 */ -static -trx_id_t -lock_deadlock_check_and_resolve( -/*============================*/ - const lock_t* lock, /*!< in: lock the transaction is requesting */ - const trx_t* trx) /*!< in: transaction */ +and rolling it back. It will attempt to resolve all deadlocks. +@param[in] trx joining transaction +@param[in] lock the requested lock +@param[in] now current time +@return trx->id of the victim transaction +@retval 0 if some other transaction was chosen as a victim and +rolled back, or no deadlock was found. */ +static trx_id_t lock_deadlock_check_and_resolve(const trx_t* trx, + const lock_t* lock, time_t now) { trx_id_t victim_trx_id; struct thd_wait_reports waitee_buf; @@ -4898,18 +4914,12 @@ lock_deadlock_check_and_resolve( ut_a(victim_trx_id == trx->id); #ifdef WITH_WSREP - if (!wsrep_thd_is_BF(ctx.start->mysql_thd, TRUE)) - { + if (wsrep_thd_is_BF(ctx.start->mysql_thd, TRUE)); else #endif /* WITH_WSREP */ - if (!srv_read_only_mode) { - lock_deadlock_joining_trx_print(trx, lock); - } -#ifdef WITH_WSREP - } else { - /* BF processor */; + if (!srv_read_only_mode) { + lock_deadlock_joining_trx_print(trx, lock, + now); } -#endif /* WITH_WSREP */ - } else if (victim_trx_id != 0 && victim_trx_id != trx->id) { ut_ad(victim_trx_id == ctx.wait_lock->trx->id); @@ -5255,7 +5265,9 @@ lock_table_enqueue_waiting( trx_mutex_exit(trx); - victim_trx_id = lock_deadlock_check_and_resolve(lock, trx); + const time_t now = time(NULL); + + victim_trx_id = lock_deadlock_check_and_resolve(trx, lock, now); trx_mutex_enter(trx); @@ -5277,7 +5289,7 @@ lock_table_enqueue_waiting( trx->lock.que_state = TRX_QUE_LOCK_WAIT; - trx->lock.wait_started = ut_time(); + trx->lock.wait_started = now; trx->lock.was_chosen_as_deadlock_victim = FALSE; trx->n_table_lock_waits++; @@ -6029,14 +6041,11 @@ lock_remove_all_on_table( /*===================== VALIDATION AND DEBUGGING ====================*/ -/*********************************************************************//** -Prints info of a table lock. */ -UNIV_INTERN -void -lock_table_print( -/*=============*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock) /*!< in: table type lock */ +/** Pretty-print a table lock. +@param[in,out] file output stream +@param[in] lock table lock +@param[in] now current time */ +static void lock_table_print(FILE* file, const lock_t* lock, time_t now) { ut_ad(lock_mutex_own()); ut_a(lock_get_type_low(lock) == LOCK_TABLE); @@ -6066,30 +6075,22 @@ lock_table_print( } fprintf(file, " lock hold time %lu wait time before grant %lu ", - (ulint)difftime(ut_time(), lock->requested_time), + (ulint)difftime(now, lock->requested_time), lock->wait_time); putc('\n', file); } -/*********************************************************************//** -Prints info of a record lock. */ -UNIV_INTERN -void -lock_rec_print( -/*===========*/ - FILE* file, /*!< in: file where to print */ - const lock_t* lock) /*!< in: record type lock */ +/** Pretty-print a record lock. +@param[in,out] file output stream +@param[in] lock record lock +@param[in] now current time +@param[in,out] mtr mini-transaction */ +static void lock_rec_print(FILE* file, const lock_t* lock, time_t now, + mtr_t* mtr) { - const buf_block_t* block; ulint space; ulint page_no; - ulint i; - mtr_t mtr; - mem_heap_t* heap = NULL; - ulint offsets_[REC_OFFS_NORMAL_SIZE]; - ulint* offsets = offsets_; - rec_offs_init(offsets_); ut_ad(lock_mutex_own()); ut_a(lock_get_type_low(lock) == LOCK_REC); @@ -6134,18 +6135,25 @@ lock_rec_print( fputs(" waiting", file); } - mtr_start(&mtr); - fprintf(file, " lock hold time %lu wait time before grant %lu ", - (ulint)difftime(ut_time(), lock->requested_time), + (ulint)difftime(now, lock->requested_time), lock->wait_time); putc('\n', file); - if ( srv_show_verbose_locks ) { - block = buf_page_try_get(space, page_no, &mtr); + if (!srv_show_verbose_locks || !mtr) { + return; + } - for (i = 0; i < lock_rec_get_n_bits(lock); ++i) { + mem_heap_t* heap = NULL; + ulint offsets_[REC_OFFS_NORMAL_SIZE]; + ulint* offsets = offsets_; + rec_offs_init(offsets_); + + mtr_start(mtr); + const buf_block_t* block = buf_page_try_get(space, page_no, mtr); + + for (ulint i = 0; i < lock_rec_get_n_bits(lock); ++i) { if (!lock_rec_get_nth_bit(lock, i)) { continue; @@ -6169,9 +6177,8 @@ lock_rec_print( putc('\n', file); } - } - mtr_commit(&mtr); + mtr_commit(mtr); if (UNIV_LIKELY_NULL(heap)) { mem_heap_free(heap); } @@ -6327,6 +6334,8 @@ lock_print_info_all_transactions( ut_ad(lock_mutex_own()); + const time_t now = time(NULL); + mutex_enter(&trx_sys->mutex); /* First print info on non-active transactions */ @@ -6413,13 +6422,14 @@ loop: fprintf(file, "------- TRX HAS BEEN WAITING %lu SEC" " FOR THIS LOCK TO BE GRANTED:\n", - (ulong) difftime(ut_time(), - trx->lock.wait_started)); + (ulong) difftime(now, trx->lock.wait_started)); if (lock_get_type_low(trx->lock.wait_lock) == LOCK_REC) { - lock_rec_print(file, trx->lock.wait_lock); + lock_rec_print(file, trx->lock.wait_lock, now, + &mtr); } else { - lock_table_print(file, trx->lock.wait_lock); + lock_table_print(file, trx->lock.wait_lock, + now); } fputs("------------------\n", file); @@ -6508,11 +6518,11 @@ loop: } print_rec: - lock_rec_print(file, lock); + lock_rec_print(file, lock, now, &mtr); } else { ut_ad(lock_get_type_low(lock) & LOCK_TABLE); - lock_table_print(file, lock); + lock_table_print(file, lock, now); } load_page_first = TRUE; diff --git a/storage/xtradb/lock/lock0wait.cc b/storage/xtradb/lock/lock0wait.cc index e9ef6d9d605..b1ee2f7ca12 100644 --- a/storage/xtradb/lock/lock0wait.cc +++ b/storage/xtradb/lock/lock0wait.cc @@ -280,7 +280,6 @@ lock_wait_suspend_thread( user OS thread */ { srv_slot_t* slot; - double wait_time; trx_t* trx; ulint had_dict_lock; ibool was_declared_inside_innodb; @@ -416,7 +415,7 @@ lock_wait_suspend_thread( row_mysql_freeze_data_dictionary(trx); } - wait_time = ut_difftime(ut_time(), slot->suspend_time); + double wait_time = difftime(time(NULL), slot->suspend_time); /* Release the slot for others to use */ @@ -509,19 +508,12 @@ lock_wait_check_and_cancel( const srv_slot_t* slot) /*!< in: slot reserved by a user thread when the wait started */ { - trx_t* trx; - double wait_time; - ib_time_t suspend_time = slot->suspend_time; - ut_ad(lock_wait_mutex_own()); - ut_ad(slot->in_use); - ut_ad(slot->suspended); - wait_time = ut_difftime(ut_time(), suspend_time); - - trx = thr_get_trx(slot->thr); + double wait_time = difftime(time(NULL), slot->suspend_time); + trx_t* trx = thr_get_trx(slot->thr); if (trx_is_interrupted(trx) || (slot->wait_timeout < 100000000 @@ -555,7 +547,6 @@ lock_wait_check_and_cancel( trx_mutex_exit(trx); } - } /*********************************************************************//** |