MDEV-12103 Reduce the time of looking for MLOG_CHECKPOINT during crash recovery

This fixes MySQL Bug#80788 in MariaDB 10.2.5.

When I made the InnoDB crash recovery more robust by implementing
WL#7142, I also introduced an extra redo log scan pass that can be
shortened.

This fix will slightly extend the InnoDB redo log format that I
introduced in MySQL 5.7.9 by writing the start LSN of the MLOG_CHECKPOINT
mini-transaction to the end of the log checkpoint page, so that recovery
can jump straight to it without scanning all the preceding redo log.

LOG_CHECKPOINT_END_LSN: At the end of the checkpoint page, the start LSN
of the MLOG_CHECKPOINT mini-transaction. Previously, these bytes were
written as 0.

log_write_checkpoint_info(), log_group_checkpoint(): Add the parameter
end_lsn for writing LOG_CHECKPOINT_END_LSN.

log_checkpoint(): Remember the LSN at which the MLOG_CHECKPOINT
mini-transaction is starting (or at which the redo log ends on
shutdown).

recv_init_crash_recovery(): Remove.

recv_group_scan_log_recs(): Add the parameter checkpoint_lsn.

recv_recovery_from_checkpoint_start(): Read LOG_CHECKPOINT_END_LSN
and if it is set, start the first scan from it instead of the
checkpoint LSN. Improve some messages and remove bogus assertions.

recv_parse_log_recs(): Do not skip DBUG_PRINT("ib_log") for some
file-level redo log records.

recv_parse_or_apply_log_rec_body(): If we have not parsed all redo
log between the checkpoint and the corresponding MLOG_CHECKPOINT
record, defer the check for MLOG_FILE_DELETE or MLOG_FILE_NAME records
to recv_init_crash_recovery_spaces().

recv_init_crash_recovery_spaces(): Refuse recovery if
MLOG_FILE_NAME or MLOG_FILE_DELETE records are missing.

Author: dr-m

mysql-test/suite/encryption/r/innodb_encrypt_log_corruption.result

@@ -84,6 +84,12 @@ WHERE engine = 'innodb'
 AND support IN ('YES', 'DEFAULT', 'ENABLED');
 ENGINE	SUPPORT	COMMENT	TRANSACTIONS	XA	SAVEPOINTS
 FOUND /len 22; hex 38000000000012860cb7809781e800066269676f7400; asc 8               bigot ;/ in mysqld.1.err
+# missing MLOG_FILE_NAME or MLOG_FILE_DELETE before MLOG_CHECKPOINT
+SELECT * FROM INFORMATION_SCHEMA.ENGINES
+WHERE engine = 'innodb'
+AND support IN ('YES', 'DEFAULT', 'ENABLED');
+ENGINE	SUPPORT	COMMENT	TRANSACTIONS	XA	SAVEPOINTS
+NOT FOUND /InnoDB: Missing MLOG_FILE_NAME or MLOG_FILE_DELETE before MLOG_CHECKPOINT for tablespace 42$/ in mysqld.1.err
 # Minimal MariaDB 10.1.21 encrypted redo log
 SELECT COUNT(*) `1` FROM INFORMATION_SCHEMA.ENGINES WHERE engine='innodb'
 AND support IN ('YES', 'DEFAULT', 'ENABLED');

mysql-test/suite/innodb/r/log_corruption.result

@@ -84,6 +84,12 @@ WHERE engine = 'innodb'
 AND support IN ('YES', 'DEFAULT', 'ENABLED');
 ENGINE	SUPPORT	COMMENT	TRANSACTIONS	XA	SAVEPOINTS
 FOUND /len 22; hex 38000000000012860cb7809781e800066269676f7400; asc 8               bigot ;/ in mysqld.1.err
+# missing MLOG_FILE_NAME or MLOG_FILE_DELETE before MLOG_CHECKPOINT
+SELECT * FROM INFORMATION_SCHEMA.ENGINES
+WHERE engine = 'innodb'
+AND support IN ('YES', 'DEFAULT', 'ENABLED');
+ENGINE	SUPPORT	COMMENT	TRANSACTIONS	XA	SAVEPOINTS
+NOT FOUND /InnoDB: Missing MLOG_FILE_NAME or MLOG_FILE_DELETE before MLOG_CHECKPOINT for tablespace 42$/ in mysqld.1.err
 # Minimal MariaDB 10.1.21 encrypted redo log
 SELECT * FROM INFORMATION_SCHEMA.ENGINES
 WHERE engine = 'innodb'

mysql-test/suite/innodb/t/log_corruption.test

@@ -13,6 +13,7 @@ call mtr.add_suppression("InnoDB: Missing MLOG_CHECKPOINT");
 call mtr.add_suppression("InnoDB: MLOG_FILE_NAME incorrect");
 call mtr.add_suppression("InnoDB: ############### CORRUPT LOG RECORD FOUND");
 call mtr.add_suppression("InnoDB: Log scan aborted at LSN");
+call mtr.add_suppression("InnoDB: Missing MLOG_FILE_NAME or MLOG_FILE_DELETE before MLOG_CHECKPOINT for tablespace 42\\r?$");
 call mtr.add_suppression("InnoDB: Obtaining redo log encryption key version 1 failed");
 call mtr.add_suppression("InnoDB: Decrypting checkpoint failed");
 --enable_query_log
@@ -316,6 +317,37 @@ eval $check_no_innodb;
 --let SEARCH_PATTERN= len 22; hex 38000000000012860cb7809781e800066269676f7400; asc 8               bigot ;
 --source include/search_pattern_in_file.inc
 
+--echo # missing MLOG_FILE_NAME or MLOG_FILE_DELETE before MLOG_CHECKPOINT
+perl;
+die unless open OUT, "+<", "$ENV{bugdir}/ib_logfile0";
+binmode OUT;
+# header block
+print OUT pack("Nx[5]nx[5]", 1, 0x1286);
+print OUT "ibbackup was here!!!1!";
+print OUT pack("x[470]N", 0x52b54540);
+# invalid (all-zero) checkpoint page 1 and an empty log page
+print OUT chr(0) x 1024;
+# valid checkpoint block 2
+print OUT pack("x[12]NNNx[264]", 0x12860c, 0, 0x80c);
+# pointer to the MLOG_CHECKPOINT record, and checkpoint page checksum
+print OUT pack("H*x[204]NNN", "590DBAACFE922582", 0x128612, 0, 0x101741b);
+# log page
+print OUT pack("H*", "800009440022000c00000001");
+# MLOG_1BYTE record for missing tablespace 42 page 123
+print OUT pack("CCCnC", 128 | 1, 42, 123, 4567, 89);
+# MLOG_CHECKPOINT record
+print OUT pack("CNN", 56, 0, 0x12860c);
+# padding (MLOG_DUMMY_RECORD) and block checksum
+print OUT " " x 481, pack("N", 0x644e6db8);
+close OUT or die;
+EOF
+
+--source include/start_mysqld.inc
+eval $check_no_innodb;
+--source include/shutdown_mysqld.inc
+--let SEARCH_PATTERN= InnoDB: Missing MLOG_FILE_NAME or MLOG_FILE_DELETE before MLOG_CHECKPOINT for tablespace 42\$
+--source include/search_pattern_in_file.inc
+
 --echo # Minimal MariaDB 10.1.21 encrypted redo log
 perl;
 die unless open OUT, "+<", "$ENV{bugdir}/ib_logfile0";

storage/innobase/include/log0log.h

@@ -252,10 +252,10 @@ log_group_header_read(
 	const log_group_t*	group,
 	ulint			header);
 /** Write checkpoint info to the log header and invoke log_mutex_exit().
-@param[in]	sync	whether to wait for the write to complete */
+@param[in]	sync	whether to wait for the write to complete
+@param[in]	end_lsn	start LSN of the MLOG_CHECKPOINT mini-transaction */
 void
-log_write_checkpoint_info(
-	bool	sync);
+log_write_checkpoint_info(bool sync, lsn_t end_lsn);
 
 /** Set extra data to be written to the redo log during checkpoint.
 @param[in]	buf	data to be appended on checkpoint, or NULL
@@ -487,17 +487,26 @@ extern my_bool	innodb_log_checksums;
 					.._HDR_NO */
 #define	LOG_BLOCK_TRL_SIZE	4	/* trailer size in bytes */
 
-/* Offsets inside the checkpoint pages (redo log format version 1) */
+/** Offsets inside the checkpoint pages (redo log format version 1) @{ */
+/** Checkpoint number */
 #define LOG_CHECKPOINT_NO		0
+/** Log sequence number up to which all changes have been flushed */
 #define LOG_CHECKPOINT_LSN		8
+/** Byte offset of the log record corresponding to LOG_CHECKPOINT_LSN */
 #define LOG_CHECKPOINT_OFFSET		16
+/** log_sys_t::buf_size at the time of the checkpoint (not used) */
 #define LOG_CHECKPOINT_LOG_BUF_SIZE	24
 /** MariaDB 10.2.5 encrypted redo log encryption key version (32 bits)*/
 #define LOG_CHECKPOINT_CRYPT_KEY	32
 /** MariaDB 10.2.5 encrypted redo log random nonce (32 bits) */
 #define LOG_CHECKPOINT_CRYPT_NONCE	36
 /** MariaDB 10.2.5 encrypted redo log random message (MY_AES_BLOCK_SIZE) */
 #define LOG_CHECKPOINT_CRYPT_MESSAGE	40
+/** start LSN of the MLOG_CHECKPOINT mini-transaction corresponding
+to this checkpoint, or 0 if the information has not been written */
+#define LOG_CHECKPOINT_END_LSN		OS_FILE_LOG_BLOCK_SIZE - 16
+
+/* @} */
 
 /** Offsets of a log file header */
 /* @{ */

storage/innobase/log/log0log.cc

@@ -1612,19 +1612,22 @@ log_io_complete_checkpoint(void)
 	log_mutex_exit();
 }
 
-/******************************************************//**
-Writes the checkpoint info to a log group header. */
+/** Write checkpoint info to the log header.
+@param[in,out]	group	redo log
+@param[in]	end_lsn	start LSN of the MLOG_CHECKPOINT mini-transaction */
 static
 void
-log_group_checkpoint(
-/*=================*/
-	log_group_t*	group)	/*!< in: log group */
+log_group_checkpoint(log_group_t* group, lsn_t end_lsn)
 {
 	lsn_t		lsn_offset;
 	byte*		buf;
 
 	ut_ad(!srv_read_only_mode);
 	ut_ad(log_mutex_own());
+	ut_ad(end_lsn == 0 || end_lsn >= log_sys->next_checkpoint_lsn);
+	ut_ad(end_lsn <= log_sys->lsn);
+	ut_ad(end_lsn + SIZE_OF_MLOG_CHECKPOINT <= log_sys->lsn
+	      || srv_shutdown_state != SRV_SHUTDOWN_NONE);
 
 	DBUG_PRINT("ib_log", ("checkpoint " UINT64PF " at " LSN_PF
 			      " written to group " ULINTPF,
@@ -1646,6 +1649,7 @@ log_group_checkpoint(
 					       group);
 	mach_write_to_8(buf + LOG_CHECKPOINT_OFFSET, lsn_offset);
 	mach_write_to_8(buf + LOG_CHECKPOINT_LOG_BUF_SIZE, log_sys->buf_size);
+	mach_write_to_8(buf + LOG_CHECKPOINT_END_LSN, end_lsn);
 
 	log_block_set_checksum(buf, log_block_calc_checksum_crc32(buf));
 
@@ -1702,9 +1706,10 @@ log_group_header_read(
 }
 
 /** Write checkpoint info to the log header and invoke log_mutex_exit().
-@param[in]	sync	whether to wait for the write to complete */
+@param[in]	sync	whether to wait for the write to complete
+@param[in]	end_lsn	start LSN of the MLOG_CHECKPOINT mini-transaction */
 void
-log_write_checkpoint_info(bool sync)
+log_write_checkpoint_info(bool sync, lsn_t end_lsn)
 {
 	ut_ad(log_mutex_own());
 	ut_ad(!srv_read_only_mode);
@@ -1713,7 +1718,7 @@ log_write_checkpoint_info(bool sync)
 	     group;
 	     group = UT_LIST_GET_NEXT(log_groups, group)) {
 
-		log_group_checkpoint(group);
+		log_group_checkpoint(group, end_lsn);
 	}
 
 	log_mutex_exit();
@@ -1827,12 +1832,13 @@ log_checkpoint(
 	threads will be blocked, and no pages can be added to the
 	flush lists. */
 	lsn_t		flush_lsn	= oldest_lsn;
+	const lsn_t	end_lsn		= log_sys->lsn;
 	const bool	do_write
 		= srv_shutdown_state == SRV_SHUTDOWN_NONE
-		|| flush_lsn != log_sys->lsn;
+		|| flush_lsn != end_lsn;
 
 	if (fil_names_clear(flush_lsn, do_write)) {
-		ut_ad(log_sys->lsn >= flush_lsn + SIZE_OF_MLOG_CHECKPOINT);
+		ut_ad(log_sys->lsn >= end_lsn + SIZE_OF_MLOG_CHECKPOINT);
 		flush_lsn = log_sys->lsn;
 	}
 
@@ -1878,7 +1884,7 @@ log_checkpoint(
 	}
 
 	log_sys->next_checkpoint_lsn = oldest_lsn;
-	log_write_checkpoint_info(sync);
+	log_write_checkpoint_info(sync, end_lsn);
 	ut_ad(!log_mutex_own());
 
 	return(true);