MDEV-29984 innodb_fast_shutdown=0 fails to report change buffer merge progress

ibuf.size, ibuf.max_size: Changed the type to Atomic_relaxed<ulint>
in order to fix some (not all) race conditions.

ibuf_contract(): Renamed from ibuf_merge_pages(ulint*).

ibuf_merge(), ibuf_merge_all(): Removed.

srv_shutdown(): Invoke log_free_check() and ibuf_contract(). Even though
ibuf_contract() is not writing anything, it will trigger calls of
ibuf_merge_or_delete_for_page(), which will write something. Because
we cannot invoke log_free_check() at that low level, we must invoke
it at the high level.

srv_shutdown_print(): Replaces srv_shutdown_print_master_pending().
Report progress and remaining work every 15 seconds. For the
change buffer merge, the remaining work is indicated by ibuf.size.

storage/innobase/ibuf/ibuf0ibuf.cc

@@ -2392,16 +2392,11 @@ static void ibuf_read_merge_pages(const uint32_t* space_ids,
 #endif
 }
 
-/*********************************************************************//**
-Contracts insert buffer trees by reading pages to the buffer pool.
+/** Contract the change buffer by reading pages to the buffer pool.
 @return a lower limit for the combined size in bytes of entries which
-will be merged from ibuf trees to the pages read, 0 if ibuf is
-empty */
-static
-ulint
-ibuf_merge_pages(
-/*=============*/
-	ulint*	n_pages)	/*!< out: number of pages to which merged */
+will be merged from ibuf trees to the pages read
+@retval 0 if ibuf.empty */
+ulint ibuf_contract()
 {
 	mtr_t		mtr;
 	btr_pcur_t	pcur;
@@ -2409,8 +2404,6 @@ ibuf_merge_pages(
 	uint32_t	page_nos[IBUF_MAX_N_PAGES_MERGED];
 	uint32_t	space_ids[IBUF_MAX_N_PAGES_MERGED];
 
-	*n_pages = 0;
-
 	ibuf_mtr_start(&mtr);
 
 	/* Open a cursor to a randomly chosen leaf of the tree, at a random
@@ -2438,14 +2431,15 @@ ibuf_merge_pages(
 		return(0);
 	}
 
+	ulint n_pages = 0;
 	sum_sizes = ibuf_get_merge_page_nos(TRUE,
 					    btr_pcur_get_rec(&pcur), &mtr,
 					    space_ids,
-					    page_nos, n_pages);
+					    page_nos, &n_pages);
 	ibuf_mtr_commit(&mtr);
 	btr_pcur_close(&pcur);
 
-	ibuf_read_merge_pages(space_ids, page_nos, *n_pages);
+	ibuf_read_merge_pages(space_ids, page_nos, n_pages);
 
 	return(sum_sizes + 1);
 }
@@ -2519,73 +2513,6 @@ ibuf_merge_space(
 	return(n_pages);
 }
 
-/** Contract the change buffer by reading pages to the buffer pool.
-@param[out]	n_pages		number of pages merged
-@param[in]	sync		whether the caller waits for
-the issued reads to complete
-@return a lower limit for the combined size in bytes of entries which
-will be merged from ibuf trees to the pages read, 0 if ibuf is
-empty */
-MY_ATTRIBUTE((warn_unused_result))
-static ulint ibuf_merge(ulint* n_pages)
-{
-	*n_pages = 0;
-
-	/* We perform a dirty read of ibuf.empty, without latching
-	the insert buffer root page. We trust this dirty read except
-	when a slow shutdown is being executed. During a slow
-	shutdown, the insert buffer merge must be completed. */
-
-	if (ibuf.empty && srv_shutdown_state <= SRV_SHUTDOWN_INITIATED) {
-		return(0);
-#if defined UNIV_DEBUG || defined UNIV_IBUF_DEBUG
-	} else if (ibuf_debug) {
-		return(0);
-#endif /* UNIV_DEBUG || UNIV_IBUF_DEBUG */
-	} else {
-		return ibuf_merge_pages(n_pages);
-	}
-}
-
-/** Contract the change buffer by reading pages to the buffer pool.
-@return a lower limit for the combined size in bytes of entries which
-will be merged from ibuf trees to the pages read, 0 if ibuf is empty */
-static ulint ibuf_contract()
-{
-	ulint n_pages;
-	return ibuf_merge_pages(&n_pages);
-}
-
-/** Contract the change buffer by reading pages to the buffer pool.
-@return a lower limit for the combined size in bytes of entries which
-will be merged from ibuf trees to the pages read, 0 if ibuf is
-empty */
-ulint ibuf_merge_all()
-{
-#if defined UNIV_DEBUG || defined UNIV_IBUF_DEBUG
-	if (ibuf_debug) {
-		return(0);
-	}
-#endif /* UNIV_DEBUG || UNIV_IBUF_DEBUG */
-
-	ulint	sum_bytes	= 0;
-	ulint	n_pages = srv_io_capacity;
-
-	for (ulint sum_pages = 0; sum_pages < n_pages; ) {
-		log_free_check();
-		ulint n_pag2;
-		ulint n_bytes = ibuf_merge(&n_pag2);
-
-		if (n_bytes == 0) {
-			break;
-		}
-
-		sum_bytes += n_bytes;
-	}
-
-	return sum_bytes;
-}
-
 /*********************************************************************//**
 Contract insert buffer trees after insert if they are too big. */
 UNIV_INLINE
@@ -2595,13 +2522,7 @@ ibuf_contract_after_insert(
 	ulint	entry_size)	/*!< in: size of a record which was inserted
 				into an ibuf tree */
 {
-	/* Perform dirty reads of ibuf.size and ibuf.max_size, to
-	reduce ibuf_mutex contention. ibuf.max_size remains constant
-	after ibuf_init_at_db_start(), but ibuf.size should be
-	protected by ibuf_mutex. Given that ibuf.size fits in a
-	machine word, this should be OK; at worst we are doing some
-	excessive ibuf_contract() or occasionally skipping a
-	ibuf_contract(). */
+	/* dirty comparison, to avoid contention on ibuf_mutex */
 	if (ibuf.size < ibuf.max_size) {
 		return;
 	}
@@ -3221,16 +3142,17 @@ ibuf_insert_low(
 
 	do_merge = FALSE;
 
-	/* Perform dirty reads of ibuf.size and ibuf.max_size, to
-	reduce ibuf_mutex contention. Given that ibuf.max_size and
-	ibuf.size fit in a machine word, this should be OK; at worst
-	we are doing some excessive ibuf_contract() or occasionally
+	/* Perform dirty comparison of ibuf.max_size and ibuf.size to
+	reduce ibuf_mutex contention. This should be OK; at worst we
+	are doing some excessive ibuf_contract() or occasionally
 	skipping an ibuf_contract(). */
-	if (ibuf.max_size == 0) {
+	const ulint max_size = ibuf.max_size;
+
+	if (max_size == 0) {
 		return(DB_STRONG_FAIL);
 	}
 
-	if (ibuf.size >= ibuf.max_size + IBUF_CONTRACT_DO_NOT_INSERT) {
+	if (ibuf.size >= max_size + IBUF_CONTRACT_DO_NOT_INSERT) {
 		/* Insert buffer is now too big, contract it but do not try
 		to insert */
 
@@ -4625,7 +4547,7 @@ ibuf_print(
 	fprintf(file,
 		"Ibuf: size " ULINTPF ", free list len " ULINTPF ","
 		" seg size " ULINTPF ", " ULINTPF " merges\n",
-		ibuf.size,
+		ulint{ibuf.size},
 		ibuf.free_list_len,
 		ibuf.seg_size,
 		ulint{ibuf.n_merges});

storage/innobase/include/ibuf0ibuf.h

@@ -62,9 +62,9 @@ extern ulong		innodb_change_buffering;
 
 /** Insert buffer struct */
 struct ibuf_t{
-	ulint		size;		/*!< current size of the ibuf index
+	Atomic_relaxed<ulint> size;	/*!< current size of the ibuf index
 					tree, in pages */
-	ulint		max_size;	/*!< recommended maximum size of the
+	Atomic_relaxed<ulint> max_size;	/*!< recommended maximum size of the
 					ibuf index tree, in pages */
 	ulint		seg_size;	/*!< allocated pages of the file
 					segment containing ibuf header and
@@ -371,9 +371,9 @@ void ibuf_delete_for_discarded_space(ulint space);
 
 /** Contract the change buffer by reading pages to the buffer pool.
 @return a lower limit for the combined size in bytes of entries which
-will be merged from ibuf trees to the pages read, 0 if ibuf is
-empty */
-ulint ibuf_merge_all();
+will be merged from ibuf trees to the pages read
+@retval 0 if ibuf.empty */
+ulint ibuf_contract();
 
 /** Contracts insert buffer trees by reading pages referring to space_id
 to the buffer pool.

storage/innobase/srv/srv0srv.cc

@@ -73,6 +73,7 @@ Created 10/8/1995 Heikki Tuuri
 #include "fil0pagecompress.h"
 #include "trx0types.h"
 #include <list>
+#include "log.h"
 
 #include <my_service_manager.h>
 /* The following is the maximum allowed duration of a lock wait. */
@@ -1495,38 +1496,42 @@ srv_master_evict_from_table_cache(
 	return(n_tables_evicted);
 }
 
-/*********************************************************************//**
-This function prints progress message every 60 seconds during server
-shutdown, for any activities that master thread is pending on. */
-static
-void
-srv_shutdown_print_master_pending(
-/*==============================*/
-	time_t*		last_print_time,	/*!< last time the function
-						print the message */
-	ulint		n_tables_to_drop,	/*!< number of tables to
-						be dropped */
-	ulint		n_bytes_merged)		/*!< number of change buffer
-						just merged */
+/** Report progress during shutdown.
+@param last   time of last output
+@param n_drop number of tables to be dropped
+@param n_read number of page reads initiated for change buffer merge */
+static void srv_shutdown_print(time_t &last, ulint n_drop, ulint n_read)
 {
-	time_t current_time = time(NULL);
-
-	if (difftime(current_time, *last_print_time) > 60) {
-		*last_print_time = current_time;
+  time_t now= time(nullptr);
+  if (now - last >= 15)
+  {
+    last= now;
 
-		if (n_tables_to_drop) {
-			ib::info() << "Waiting for " << n_tables_to_drop
-				<< " table(s) to be dropped";
-		}
+    if (n_drop)
+    {
+      sql_print_information("InnoDB: Waiting for %zu table(s) to be dropped",
+                            n_drop);
+#if defined HAVE_SYSTEMD && !defined EMBEDDED_LIBRARY
+      service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+                                     "InnoDB: Waiting for %zu table(s)"
+                                     " to be dropped", n_drop);
+#endif
+      return;
+    }
 
-		/* Check change buffer merge, we only wait for change buffer
-		merge if it is a slow shutdown */
-		if (!srv_fast_shutdown && n_bytes_merged) {
-			ib::info() << "Waiting for change buffer merge to"
-				" complete number of bytes of change buffer"
-				" just merged: " << n_bytes_merged;
-		}
-	}
+    const ulint ibuf_size= ibuf.size;
+    sql_print_information("Completing change buffer merge;"
+                          " %zu page reads initiated;"
+                          " %zu change buffer pages remain",
+                          n_read, ibuf_size);
+#if defined HAVE_SYSTEMD && !defined EMBEDDED_LIBRARY
+    service_manager_extend_timeout(INNODB_EXTEND_TIMEOUT_INTERVAL,
+                                   "Completing change buffer merge;"
+                                   " %zu page reads initiated;"
+                                   " %zu change buffer pages remain",
+                                   n_read, ibuf_size);
+#endif
+  }
 }
 
 /*********************************************************************//**
@@ -1654,7 +1659,7 @@ Complete the shutdown tasks such as background DROP TABLE,
 and optionally change buffer merge (on innodb_fast_shutdown=0). */
 void srv_shutdown(bool ibuf_merge)
 {
-	ulint		n_bytes_merged	= 0;
+	ulint		n_read = 0;
 	ulint		n_tables_to_drop;
 	time_t		now = time(NULL);
 
@@ -1670,15 +1675,14 @@ void srv_shutdown(bool ibuf_merge)
 
 		if (ibuf_merge) {
 			srv_main_thread_op_info = "doing insert buffer merge";
-			n_bytes_merged = ibuf_merge_all();
+			log_free_check();
+			n_read = ibuf_contract();
 		}
 
-		/* Print progress message every 60 seconds during shutdown */
-		if (srv_print_verbose_log) {
-			srv_shutdown_print_master_pending(
-				&now, n_tables_to_drop, n_bytes_merged);
+		if (n_tables_to_drop || ibuf_merge) {
+			srv_shutdown_print(now, n_tables_to_drop, n_read);
 		}
-	} while (n_bytes_merged || n_tables_to_drop);
+	} while (n_read || n_tables_to_drop);
 }
 
 /** The periodic master task controlling the server. */