Skip to content

Commit b1977a3

Browse files
dr-mdr-m
committed
MDEV-12323 Rollback progress log messages during crash recovery are intermixed with unrelated log messages
trx_roll_must_shutdown(): During the rollback of recovered transactions, report progress and check if the rollback should be interrupted because of a pending shutdown. trx_roll_max_undo_no, trx_roll_progress_printed_pct: Remove, along with the messages that were interleaved with other messages.
1 parent 08d0ea1 commit b1977a3

File tree

6 files changed

+96
-112
lines changed

6 files changed

+96
-112
lines changed

‎storage/innobase/include/trx0roll.h‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -105,6 +105,11 @@ trx_undo_rec_release(
105105
/*=================*/
106106
trx_t*trx,/*!< in/out: transaction */
107107
undo_no_tundo_no);/*!< in: undo number */
108+
/** Report progress when rolling back a row of a recovered transaction.
109+
@return whether the rollback should be aborted due to pending shutdown */
110+
UNIV_INTERN
111+
bool
112+
trx_roll_must_shutdown();
108113
/*******************************************************************//**
109114
Rollback or clean up any incomplete transactions which were
110115
encountered in crash recovery. If the transaction already was

‎storage/innobase/row/row0undo.cc‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,6 @@ Created 1/8/1997 Heikki Tuuri
4545
#include "row0upd.h"
4646
#include "row0mysql.h"
4747
#include "srv0srv.h"
48-
#include "srv0start.h"
4948

5049
/* How to undo row operations?
5150
(1) For an insert, we have stored a prefix of the clustered index record
@@ -351,8 +350,7 @@ row_undo_step(
351350
ut_ad(que_node_get_type(node) == QUE_NODE_UNDO);
352351

353352
if (UNIV_UNLIKELY(trx == trx_roll_crash_recv_trx)
354-
&& trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
355-
&& !srv_undo_sources && srv_fast_shutdown) {
353+
&& trx_roll_must_shutdown()) {
356354
/* Shutdown has been initiated. */
357355
trx->error_state = DB_INTERRUPTED;
358356
return(NULL);

‎storage/innobase/trx/trx0roll.cc‎

Lines changed: 42 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -57,13 +57,6 @@ bool trx_rollback_or_clean_is_active;
5757
/** In crash recovery, the current trx to be rolled back; NULL otherwise */
5858
const trx_t* trx_roll_crash_recv_trx;
5959

60-
/** In crash recovery we set this to the undo n:o of the current trx to be
61-
rolled back. Then we can print how many % the rollback has progressed. */
62-
static undo_no_ttrx_roll_max_undo_no;
63-
64-
/** Auxiliary variable which tells the previous progress % we printed */
65-
static ulint trx_roll_progress_printed_pct;
66-
6760
/****************************************************************//**
6861
Finishes a transaction rollback. */
6962
static
@@ -551,8 +544,6 @@ trx_rollback_active(
551544
que_thr_t* thr;
552545
roll_node_t* roll_node;
553546
dict_table_t* table;
554-
ib_int64_trows_to_undo;
555-
const char* unit = "";
556547
ibool dictionary_locked = FALSE;
557548

558549
heap = mem_heap_create(512);
@@ -571,30 +562,8 @@ trx_rollback_active(
571562

572563
ut_a(thr == que_fork_start_command(fork));
573564

574-
mutex_enter(&trx_sys->mutex);
575-
576565
trx_roll_crash_recv_trx = trx;
577566

578-
trx_roll_max_undo_no = trx->undo_no;
579-
580-
trx_roll_progress_printed_pct = 0;
581-
582-
rows_to_undo = trx_roll_max_undo_no;
583-
584-
mutex_exit(&trx_sys->mutex);
585-
586-
if (rows_to_undo > 1000000000) {
587-
rows_to_undo = rows_to_undo / 1000000;
588-
unit = "M";
589-
}
590-
591-
ut_print_timestamp(stderr);
592-
fprintf(stderr,
593-
" InnoDB: Rolling back trx with id " TRX_ID_FMT ", %lu%s"
594-
" rows to undo\n",
595-
trx->id,
596-
(ulong) rows_to_undo, unit);
597-
598567
if (trx_get_dict_operation(trx) != TRX_DICT_OP_NONE) {
599568
row_mysql_lock_data_dictionary(trx);
600569
dictionary_locked = TRUE;
@@ -744,6 +713,48 @@ trx_rollback_resurrected(
744713
goto func_exit;
745714
}
746715

716+
/** Report progress when rolling back a row of a recovered transaction.
717+
@return whether the rollback should be aborted due to pending shutdown */
718+
UNIV_INTERN
719+
bool
720+
trx_roll_must_shutdown()
721+
{
722+
const trx_t* trx = trx_roll_crash_recv_trx;
723+
ut_ad(trx);
724+
ut_ad(trx_state_eq(trx, TRX_STATE_ACTIVE));
725+
726+
if (trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
727+
&& !srv_undo_sources && srv_fast_shutdown) {
728+
return true;
729+
}
730+
731+
ib_time_t time = ut_time();
732+
mutex_enter(&trx_sys->mutex);
733+
mutex_enter(&recv_sys->mutex);
734+
735+
if (recv_sys->report(time)) {
736+
ulint n_trx = 0, n_rows = 0;
737+
for (const trx_t* t = UT_LIST_GET_FIRST(trx_sys->rw_trx_list);
738+
t != NULL;
739+
t = UT_LIST_GET_NEXT(trx_list, t)) {
740+
741+
assert_trx_in_rw_list(t);
742+
if (t->is_recovered
743+
&& trx_state_eq(t, TRX_STATE_ACTIVE)) {
744+
n_trx++;
745+
n_rows += t->undo_no;
746+
}
747+
}
748+
ib_logf(IB_LOG_LEVEL_INFO,
749+
"To roll back: " ULINTPF " transactions, "
750+
ULINTPF " rows", n_trx, n_rows);
751+
}
752+
753+
mutex_exit(&recv_sys->mutex);
754+
mutex_exit(&trx_sys->mutex);
755+
return false;
756+
}
757+
747758
/*******************************************************************//**
748759
Rollback or clean up any incomplete transactions which were
749760
encountered in crash recovery. If the transaction already was
@@ -1119,7 +1130,6 @@ trx_roll_pop_top_rec_of_trx(
11191130
undo_no_tundo_no;
11201131
ibool is_insert;
11211132
trx_rseg_t* rseg;
1122-
ulint progress_pct;
11231133
mtr_tmtr;
11241134

11251135
rseg = trx->rseg;
@@ -1177,27 +1187,6 @@ trx_roll_pop_top_rec_of_trx(
11771187

11781188
ut_ad(undo_no + 1 == trx->undo_no);
11791189

1180-
/* We print rollback progress info if we are in a crash recovery
1181-
and the transaction has at least 1000 row operations to undo. */
1182-
1183-
if (trx == trx_roll_crash_recv_trx && trx_roll_max_undo_no > 1000) {
1184-
1185-
progress_pct = 100 - (ulint)
1186-
((undo_no * 100) / trx_roll_max_undo_no);
1187-
if (progress_pct != trx_roll_progress_printed_pct) {
1188-
if (trx_roll_progress_printed_pct == 0) {
1189-
fprintf(stderr,
1190-
"\nInnoDB: Progress in percents:"
1191-
" %lu", (ulong) progress_pct);
1192-
} else {
1193-
fprintf(stderr,
1194-
" %lu", (ulong) progress_pct);
1195-
}
1196-
fflush(stderr);
1197-
trx_roll_progress_printed_pct = progress_pct;
1198-
}
1199-
}
1200-
12011190
trx->undo_no = undo_no;
12021191

12031192
if (!trx_undo_arr_store_info(trx, undo_no)) {

‎storage/xtradb/include/trx0roll.h‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -106,6 +106,11 @@ trx_undo_rec_release(
106106
/*=================*/
107107
trx_t*trx,/*!< in/out: transaction */
108108
undo_no_tundo_no);/*!< in: undo number */
109+
/** Report progress when rolling back a row of a recovered transaction.
110+
@return whether the rollback should be aborted due to pending shutdown */
111+
UNIV_INTERN
112+
bool
113+
trx_roll_must_shutdown();
109114
/*******************************************************************//**
110115
Rollback or clean up any incomplete transactions which were
111116
encountered in crash recovery. If the transaction already was

‎storage/xtradb/row/row0undo.cc‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,6 @@ Created 1/8/1997 Heikki Tuuri
4545
#include "row0upd.h"
4646
#include "row0mysql.h"
4747
#include "srv0srv.h"
48-
#include "srv0start.h"
4948

5049
/* How to undo row operations?
5150
(1) For an insert, we have stored a prefix of the clustered index record
@@ -351,8 +350,7 @@ row_undo_step(
351350
ut_ad(que_node_get_type(node) == QUE_NODE_UNDO);
352351

353352
if (UNIV_UNLIKELY(trx == trx_roll_crash_recv_trx)
354-
&& trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
355-
&& !srv_undo_sources && srv_fast_shutdown) {
353+
&& trx_roll_must_shutdown()) {
356354
/* Shutdown has been initiated. */
357355
trx->error_state = DB_INTERRUPTED;
358356
return(NULL);

‎storage/xtradb/trx/trx0roll.cc‎

Lines changed: 42 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -57,13 +57,6 @@ bool trx_rollback_or_clean_is_active;
5757
/** In crash recovery, the current trx to be rolled back; NULL otherwise */
5858
const trx_t* trx_roll_crash_recv_trx;
5959

60-
/** In crash recovery we set this to the undo n:o of the current trx to be
61-
rolled back. Then we can print how many % the rollback has progressed. */
62-
static undo_no_ttrx_roll_max_undo_no;
63-
64-
/** Auxiliary variable which tells the previous progress % we printed */
65-
static ulint trx_roll_progress_printed_pct;
66-
6760
/****************************************************************//**
6861
Finishes a transaction rollback. */
6962
static
@@ -551,8 +544,6 @@ trx_rollback_active(
551544
que_thr_t* thr;
552545
roll_node_t* roll_node;
553546
dict_table_t* table;
554-
ib_int64_trows_to_undo;
555-
const char* unit = "";
556547
ibool dictionary_locked = FALSE;
557548

558549
heap = mem_heap_create(512);
@@ -571,30 +562,8 @@ trx_rollback_active(
571562

572563
ut_a(thr == que_fork_start_command(fork));
573564

574-
mutex_enter(&trx_sys->mutex);
575-
576565
trx_roll_crash_recv_trx = trx;
577566

578-
trx_roll_max_undo_no = trx->undo_no;
579-
580-
trx_roll_progress_printed_pct = 0;
581-
582-
rows_to_undo = trx_roll_max_undo_no;
583-
584-
mutex_exit(&trx_sys->mutex);
585-
586-
if (rows_to_undo > 1000000000) {
587-
rows_to_undo = rows_to_undo / 1000000;
588-
unit = "M";
589-
}
590-
591-
ut_print_timestamp(stderr);
592-
fprintf(stderr,
593-
" InnoDB: Rolling back trx with id " TRX_ID_FMT ", %lu%s"
594-
" rows to undo\n",
595-
trx->id,
596-
(ulong) rows_to_undo, unit);
597-
598567
if (trx_get_dict_operation(trx) != TRX_DICT_OP_NONE) {
599568
row_mysql_lock_data_dictionary(trx);
600569
dictionary_locked = TRUE;
@@ -744,6 +713,48 @@ trx_rollback_resurrected(
744713
goto func_exit;
745714
}
746715

716+
/** Report progress when rolling back a row of a recovered transaction.
717+
@return whether the rollback should be aborted due to pending shutdown */
718+
UNIV_INTERN
719+
bool
720+
trx_roll_must_shutdown()
721+
{
722+
const trx_t* trx = trx_roll_crash_recv_trx;
723+
ut_ad(trx);
724+
ut_ad(trx_state_eq(trx, TRX_STATE_ACTIVE));
725+
726+
if (trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
727+
&& !srv_undo_sources && srv_fast_shutdown) {
728+
return true;
729+
}
730+
731+
ib_time_t time = ut_time();
732+
mutex_enter(&trx_sys->mutex);
733+
mutex_enter(&recv_sys->mutex);
734+
735+
if (recv_sys->report(time)) {
736+
ulint n_trx = 0, n_rows = 0;
737+
for (const trx_t* t = UT_LIST_GET_FIRST(trx_sys->rw_trx_list);
738+
t != NULL;
739+
t = UT_LIST_GET_NEXT(trx_list, t)) {
740+
741+
assert_trx_in_rw_list(t);
742+
if (t->is_recovered
743+
&& trx_state_eq(t, TRX_STATE_ACTIVE)) {
744+
n_trx++;
745+
n_rows += t->undo_no;
746+
}
747+
}
748+
ib_logf(IB_LOG_LEVEL_INFO,
749+
"To roll back: " ULINTPF " transactions, "
750+
ULINTPF " rows", n_trx, n_rows);
751+
}
752+
753+
mutex_exit(&recv_sys->mutex);
754+
mutex_exit(&trx_sys->mutex);
755+
return false;
756+
}
757+
747758
/*******************************************************************//**
748759
Rollback or clean up any incomplete transactions which were
749760
encountered in crash recovery. If the transaction already was
@@ -1119,7 +1130,6 @@ trx_roll_pop_top_rec_of_trx(
11191130
undo_no_tundo_no;
11201131
ibool is_insert;
11211132
trx_rseg_t* rseg;
1122-
ulint progress_pct;
11231133
mtr_tmtr;
11241134

11251135
rseg = trx->rseg;
@@ -1177,27 +1187,6 @@ trx_roll_pop_top_rec_of_trx(
11771187

11781188
ut_ad(undo_no + 1 == trx->undo_no);
11791189

1180-
/* We print rollback progress info if we are in a crash recovery
1181-
and the transaction has at least 1000 row operations to undo. */
1182-
1183-
if (trx == trx_roll_crash_recv_trx && trx_roll_max_undo_no > 1000) {
1184-
1185-
progress_pct = 100 - (ulint)
1186-
((undo_no * 100) / trx_roll_max_undo_no);
1187-
if (progress_pct != trx_roll_progress_printed_pct) {
1188-
if (trx_roll_progress_printed_pct == 0) {
1189-
fprintf(stderr,
1190-
"\nInnoDB: Progress in percents:"
1191-
" %lu", (ulong) progress_pct);
1192-
} else {
1193-
fprintf(stderr,
1194-
" %lu", (ulong) progress_pct);
1195-
}
1196-
fflush(stderr);
1197-
trx_roll_progress_printed_pct = progress_pct;
1198-
}
1199-
}
1200-
12011190
trx->undo_no = undo_no;
12021191

12031192
if (!trx_undo_arr_store_info(trx, undo_no)) {

0 commit comments

Comments
 (0)