MDEV-12323 Rollback progress log messages during crash recovery are intermixed...

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.

storage/innobase/include/trx0roll.h

@@ -105,6 +105,11 @@ trx_undo_rec_release(
 /*=================*/
 	trx_t*		trx,	/*!< in/out: transaction */
 	undo_no_t	undo_no);/*!< in: undo number */
+/** Report progress when rolling back a row of a recovered transaction.
+@return	whether the rollback should be aborted due to pending shutdown */
+UNIV_INTERN
+bool
+trx_roll_must_shutdown();
 /*******************************************************************//**
 Rollback or clean up any incomplete transactions which were
 encountered in crash recovery.  If the transaction already was

storage/innobase/row/row0undo.cc

@@ -45,7 +45,6 @@ Created 1/8/1997 Heikki Tuuri
 #include "row0upd.h"
 #include "row0mysql.h"
 #include "srv0srv.h"
-#include "srv0start.h"
 
 /* How to undo row operations?
 (1) For an insert, we have stored a prefix of the clustered index record
@@ -351,8 +350,7 @@ row_undo_step(
 	ut_ad(que_node_get_type(node) == QUE_NODE_UNDO);
 
 	if (UNIV_UNLIKELY(trx == trx_roll_crash_recv_trx)
-	    && trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
-	    && !srv_undo_sources && srv_fast_shutdown) {
+	    && trx_roll_must_shutdown()) {
 		/* Shutdown has been initiated. */
 		trx->error_state = DB_INTERRUPTED;
 		return(NULL);

storage/innobase/trx/trx0roll.cc

@@ -57,13 +57,6 @@ bool			trx_rollback_or_clean_is_active;
 /** In crash recovery, the current trx to be rolled back; NULL otherwise */
 const trx_t*		trx_roll_crash_recv_trx;
 
-/** In crash recovery we set this to the undo n:o of the current trx to be
-rolled back. Then we can print how many % the rollback has progressed. */
-static undo_no_t	trx_roll_max_undo_no;
-
-/** Auxiliary variable which tells the previous progress % we printed */
-static ulint		trx_roll_progress_printed_pct;
-
 /****************************************************************//**
 Finishes a transaction rollback. */
 static
@@ -551,8 +544,6 @@ trx_rollback_active(
 	que_thr_t*	thr;
 	roll_node_t*	roll_node;
 	dict_table_t*	table;
-	ib_int64_t	rows_to_undo;
-	const char*	unit		= "";
 	ibool		dictionary_locked = FALSE;
 
 	heap = mem_heap_create(512);
@@ -571,30 +562,8 @@ trx_rollback_active(
 
 	ut_a(thr == que_fork_start_command(fork));
 
-	mutex_enter(&trx_sys->mutex);
-
 	trx_roll_crash_recv_trx	= trx;
 
-	trx_roll_max_undo_no = trx->undo_no;
-
-	trx_roll_progress_printed_pct = 0;
-
-	rows_to_undo = trx_roll_max_undo_no;
-
-	mutex_exit(&trx_sys->mutex);
-
-	if (rows_to_undo > 1000000000) {
-		rows_to_undo = rows_to_undo / 1000000;
-		unit = "M";
-	}
-
-	ut_print_timestamp(stderr);
-	fprintf(stderr,
-		"  InnoDB: Rolling back trx with id " TRX_ID_FMT ", %lu%s"
-		" rows to undo\n",
-		trx->id,
-		(ulong) rows_to_undo, unit);
-
 	if (trx_get_dict_operation(trx) != TRX_DICT_OP_NONE) {
 		row_mysql_lock_data_dictionary(trx);
 		dictionary_locked = TRUE;
@@ -744,6 +713,48 @@ trx_rollback_resurrected(
 	goto func_exit;
 }
 
+/** Report progress when rolling back a row of a recovered transaction.
+@return	whether the rollback should be aborted due to pending shutdown */
+UNIV_INTERN
+bool
+trx_roll_must_shutdown()
+{
+	const trx_t* trx = trx_roll_crash_recv_trx;
+	ut_ad(trx);
+	ut_ad(trx_state_eq(trx, TRX_STATE_ACTIVE));
+
+	if (trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
+	    && !srv_undo_sources && srv_fast_shutdown) {
+		return true;
+	}
+
+	ib_time_t time = ut_time();
+	mutex_enter(&trx_sys->mutex);
+	mutex_enter(&recv_sys->mutex);
+
+	if (recv_sys->report(time)) {
+		ulint n_trx = 0, n_rows = 0;
+		for (const trx_t* t = UT_LIST_GET_FIRST(trx_sys->rw_trx_list);
+		     t != NULL;
+		     t = UT_LIST_GET_NEXT(trx_list, t)) {
+
+			assert_trx_in_rw_list(t);
+			if (t->is_recovered
+			    && trx_state_eq(t, TRX_STATE_ACTIVE)) {
+				n_trx++;
+				n_rows += t->undo_no;
+			}
+		}
+		ib_logf(IB_LOG_LEVEL_INFO,
+			"To roll back: " ULINTPF " transactions, "
+			ULINTPF " rows", n_trx, n_rows);
+	}
+
+	mutex_exit(&recv_sys->mutex);
+	mutex_exit(&trx_sys->mutex);
+	return false;
+}
+
 /*******************************************************************//**
 Rollback or clean up any incomplete transactions which were
 encountered in crash recovery.  If the transaction already was
@@ -1119,7 +1130,6 @@ trx_roll_pop_top_rec_of_trx(
 	undo_no_t	undo_no;
 	ibool		is_insert;
 	trx_rseg_t*	rseg;
-	ulint		progress_pct;
 	mtr_t		mtr;
 
 	rseg = trx->rseg;
@@ -1177,27 +1187,6 @@ trx_roll_pop_top_rec_of_trx(
 
 	ut_ad(undo_no + 1 == trx->undo_no);
 
-	/* We print rollback progress info if we are in a crash recovery
-	and the transaction has at least 1000 row operations to undo. */
-
-	if (trx == trx_roll_crash_recv_trx && trx_roll_max_undo_no > 1000) {
-
-		progress_pct = 100 - (ulint)
-			((undo_no * 100) / trx_roll_max_undo_no);
-		if (progress_pct != trx_roll_progress_printed_pct) {
-			if (trx_roll_progress_printed_pct == 0) {
-				fprintf(stderr,
-					"\nInnoDB: Progress in percents:"
-					" %lu", (ulong) progress_pct);
-			} else {
-				fprintf(stderr,
-					" %lu", (ulong) progress_pct);
-			}
-			fflush(stderr);
-			trx_roll_progress_printed_pct = progress_pct;
-		}
-	}
-
 	trx->undo_no = undo_no;
 
 	if (!trx_undo_arr_store_info(trx, undo_no)) {

storage/xtradb/include/trx0roll.h

@@ -106,6 +106,11 @@ trx_undo_rec_release(
 /*=================*/
 	trx_t*		trx,	/*!< in/out: transaction */
 	undo_no_t	undo_no);/*!< in: undo number */
+/** Report progress when rolling back a row of a recovered transaction.
+@return	whether the rollback should be aborted due to pending shutdown */
+UNIV_INTERN
+bool
+trx_roll_must_shutdown();
 /*******************************************************************//**
 Rollback or clean up any incomplete transactions which were
 encountered in crash recovery.  If the transaction already was

storage/xtradb/row/row0undo.cc

@@ -45,7 +45,6 @@ Created 1/8/1997 Heikki Tuuri
 #include "row0upd.h"
 #include "row0mysql.h"
 #include "srv0srv.h"
-#include "srv0start.h"
 
 /* How to undo row operations?
 (1) For an insert, we have stored a prefix of the clustered index record
@@ -351,8 +350,7 @@ row_undo_step(
 	ut_ad(que_node_get_type(node) == QUE_NODE_UNDO);
 
 	if (UNIV_UNLIKELY(trx == trx_roll_crash_recv_trx)
-	    && trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
-	    && !srv_undo_sources && srv_fast_shutdown) {
+	    && trx_roll_must_shutdown()) {
 		/* Shutdown has been initiated. */
 		trx->error_state = DB_INTERRUPTED;
 		return(NULL);

storage/xtradb/trx/trx0roll.cc

@@ -57,13 +57,6 @@ bool			trx_rollback_or_clean_is_active;
 /** In crash recovery, the current trx to be rolled back; NULL otherwise */
 const trx_t*		trx_roll_crash_recv_trx;
 
-/** In crash recovery we set this to the undo n:o of the current trx to be
-rolled back. Then we can print how many % the rollback has progressed. */
-static undo_no_t	trx_roll_max_undo_no;
-
-/** Auxiliary variable which tells the previous progress % we printed */
-static ulint		trx_roll_progress_printed_pct;
-
 /****************************************************************//**
 Finishes a transaction rollback. */
 static
@@ -551,8 +544,6 @@ trx_rollback_active(
 	que_thr_t*	thr;
 	roll_node_t*	roll_node;
 	dict_table_t*	table;
-	ib_int64_t	rows_to_undo;
-	const char*	unit		= "";
 	ibool		dictionary_locked = FALSE;
 
 	heap = mem_heap_create(512);
@@ -571,30 +562,8 @@ trx_rollback_active(
 
 	ut_a(thr == que_fork_start_command(fork));
 
-	mutex_enter(&trx_sys->mutex);
-
 	trx_roll_crash_recv_trx	= trx;
 
-	trx_roll_max_undo_no = trx->undo_no;
-
-	trx_roll_progress_printed_pct = 0;
-
-	rows_to_undo = trx_roll_max_undo_no;
-
-	mutex_exit(&trx_sys->mutex);
-
-	if (rows_to_undo > 1000000000) {
-		rows_to_undo = rows_to_undo / 1000000;
-		unit = "M";
-	}
-
-	ut_print_timestamp(stderr);
-	fprintf(stderr,
-		"  InnoDB: Rolling back trx with id " TRX_ID_FMT ", %lu%s"
-		" rows to undo\n",
-		trx->id,
-		(ulong) rows_to_undo, unit);
-
 	if (trx_get_dict_operation(trx) != TRX_DICT_OP_NONE) {
 		row_mysql_lock_data_dictionary(trx);
 		dictionary_locked = TRUE;
@@ -744,6 +713,48 @@ trx_rollback_resurrected(
 	goto func_exit;
 }
 
+/** Report progress when rolling back a row of a recovered transaction.
+@return	whether the rollback should be aborted due to pending shutdown */
+UNIV_INTERN
+bool
+trx_roll_must_shutdown()
+{
+	const trx_t* trx = trx_roll_crash_recv_trx;
+	ut_ad(trx);
+	ut_ad(trx_state_eq(trx, TRX_STATE_ACTIVE));
+
+	if (trx_get_dict_operation(trx) == TRX_DICT_OP_NONE
+	    && !srv_undo_sources && srv_fast_shutdown) {
+		return true;
+	}
+
+	ib_time_t time = ut_time();
+	mutex_enter(&trx_sys->mutex);
+	mutex_enter(&recv_sys->mutex);
+
+	if (recv_sys->report(time)) {
+		ulint n_trx = 0, n_rows = 0;
+		for (const trx_t* t = UT_LIST_GET_FIRST(trx_sys->rw_trx_list);
+		     t != NULL;
+		     t = UT_LIST_GET_NEXT(trx_list, t)) {
+
+			assert_trx_in_rw_list(t);
+			if (t->is_recovered
+			    && trx_state_eq(t, TRX_STATE_ACTIVE)) {
+				n_trx++;
+				n_rows += t->undo_no;
+			}
+		}
+		ib_logf(IB_LOG_LEVEL_INFO,
+			"To roll back: " ULINTPF " transactions, "
+			ULINTPF " rows", n_trx, n_rows);
+	}
+
+	mutex_exit(&recv_sys->mutex);
+	mutex_exit(&trx_sys->mutex);
+	return false;
+}
+
 /*******************************************************************//**
 Rollback or clean up any incomplete transactions which were
 encountered in crash recovery.  If the transaction already was
@@ -1119,7 +1130,6 @@ trx_roll_pop_top_rec_of_trx(
 	undo_no_t	undo_no;
 	ibool		is_insert;
 	trx_rseg_t*	rseg;
-	ulint		progress_pct;
 	mtr_t		mtr;
 
 	rseg = trx->rseg;
@@ -1177,27 +1187,6 @@ trx_roll_pop_top_rec_of_trx(
 
 	ut_ad(undo_no + 1 == trx->undo_no);
 
-	/* We print rollback progress info if we are in a crash recovery
-	and the transaction has at least 1000 row operations to undo. */
-
-	if (trx == trx_roll_crash_recv_trx && trx_roll_max_undo_no > 1000) {
-
-		progress_pct = 100 - (ulint)
-			((undo_no * 100) / trx_roll_max_undo_no);
-		if (progress_pct != trx_roll_progress_printed_pct) {
-			if (trx_roll_progress_printed_pct == 0) {
-				fprintf(stderr,
-					"\nInnoDB: Progress in percents:"
-					" %lu", (ulong) progress_pct);
-			} else {
-				fprintf(stderr,
-					" %lu", (ulong) progress_pct);
-			}
-			fflush(stderr);
-			trx_roll_progress_printed_pct = progress_pct;
-		}
-	}
-
 	trx->undo_no = undo_no;
 
 	if (!trx_undo_arr_store_info(trx, undo_no)) {