branches/zip: Introduce UNIV_LOG_LSN_DEBUG and MLOG_LSN for redo log

diagnostics.  This was written in order to better track down
Issue #313 in InnoDB Hot Backup.

MLOG_LSN: A new redo log entry type, for recording the current log
sequence number (LSN).  This will be checked in an assertion in
recv_parse_log_rec().

rb://161, discussed with Sunny and Vasil.

include/log0log.ic

@@ -312,11 +312,20 @@ log_reserve_and_write_fast(
 	ib_uint64_t*	start_lsn)/*!< out: start lsn of the log record */
 {
 	ulint		data_len;
-	ib_uint64_t	lsn;
+#ifdef UNIV_LOG_LSN_DEBUG
+	/* length of the LSN pseudo-record */
+	ulint		lsn_len = 1
+		+ mach_get_compressed_size(log_sys->lsn >> 32)
+		+ mach_get_compressed_size(log_sys->lsn & 0xFFFFFFFFUL);
+#endif /* UNIV_LOG_LSN_DEBUG */
 
 	mutex_enter(&log_sys->mutex);
 
-	data_len = len + log_sys->buf_free % OS_FILE_LOG_BLOCK_SIZE;
+	data_len = len
+#ifdef UNIV_LOG_LSN_DEBUG
+		+ lsn_len
+#endif /* UNIV_LOG_LSN_DEBUG */
+		+ log_sys->buf_free % OS_FILE_LOG_BLOCK_SIZE;
 
 	if (data_len >= OS_FILE_LOG_BLOCK_SIZE - LOG_BLOCK_TRL_SIZE) {
 
@@ -330,7 +339,23 @@ log_reserve_and_write_fast(
 
 	*start_lsn = log_sys->lsn;
 
-	ut_memcpy(log_sys->buf + log_sys->buf_free, str, len);
+#ifdef UNIV_LOG_LSN_DEBUG
+	{
+		/* Write the LSN pseudo-record. */
+		byte* b = &log_sys->buf[log_sys->buf_free];
+		*b++ = MLOG_LSN | (MLOG_SINGLE_REC_FLAG & *(const byte*) str);
+		/* Write the LSN in two parts,
+		as a pseudo page number and space id. */
+		b += mach_write_compressed(b, log_sys->lsn >> 32);
+		b += mach_write_compressed(b, log_sys->lsn & 0xFFFFFFFFUL);
+		ut_a(b - lsn_len == &log_sys->buf[log_sys->buf_free]);
+
+		memcpy(b, str, len);
+		len += lsn_len;
+	}
+#else /* UNIV_LOG_LSN_DEBUG */
+	memcpy(log_sys->buf + log_sys->buf_free, str, len);
+#endif /* UNIV_LOG_LSN_DEBUG */
 
 	log_block_set_data_len((byte*) ut_align_down(log_sys->buf
 						     + log_sys->buf_free,
@@ -344,14 +369,14 @@ log_reserve_and_write_fast(
 
 	ut_ad(log_sys->buf_free <= log_sys->buf_size);
 
-	lsn = log_sys->lsn += len;
+	log_sys->lsn += len;
 
 #ifdef UNIV_LOG_DEBUG
 	log_check_log_recs(log_sys->buf + log_sys->old_buf_free,
 			   log_sys->buf_free - log_sys->old_buf_free,
 			   log_sys->old_lsn);
 #endif
-	return(lsn);
+	return(log_sys->lsn);
 }
 
 /***********************************************************************//**

include/mtr0mtr.h

@@ -106,6 +106,9 @@ For 1 - 8 bytes, the flag value must give the length also! @{ */
 #define MLOG_IBUF_BITMAP_INIT	((byte)27)	/*!< initialize an
 						ibuf bitmap page */
 /*#define	MLOG_FULL_PAGE	((byte)28)	full contents of a page */
+#ifdef UNIV_LOG_LSN_DEBUG
+# define MLOG_LSN		((byte)28)	/* current LSN */
+#endif
 #define MLOG_INIT_FILE_PAGE	((byte)29)	/*!< this means that a
 						file page is taken
 						into use and the prior

include/univ.i

@@ -185,6 +185,9 @@ command. Not tested on Windows. */
 #define UNIV_LRU_DEBUG				/* debug the buffer pool LRU */
 #define UNIV_HASH_DEBUG				/* debug HASH_ macros */
 #define UNIV_LIST_DEBUG				/* debug UT_LIST_ macros */
+#define UNIV_LOG_LSN_DEBUG			/* write LSN to the redo log;
+this will break redo log file compatibility, but it may be useful when
+debugging redo log application problems. */
 #define UNIV_MEM_DEBUG				/* detect memory leaks etc */
 #define UNIV_IBUF_DEBUG				/* debug the insert buffer */
 #define UNIV_IBUF_COUNT_DEBUG			/* debug the insert buffer;

log/log0recv.c

@@ -853,6 +853,11 @@ recv_parse_or_apply_log_rec_body(
 	}
 
 	switch (type) {
+#ifdef UNIV_LOG_LSN_DEBUG
+	case MLOG_LSN:
+		/* The LSN is checked in recv_parse_log_rec(). */
+		break;
+#endif /* UNIV_LOG_LSN_DEBUG */
 	case MLOG_1BYTE: case MLOG_2BYTES: case MLOG_4BYTES: case MLOG_8BYTES:
 #ifdef UNIV_DEBUG
 		if (page && page_type == FIL_PAGE_TYPE_ALLOCATED
@@ -1924,6 +1929,17 @@ recv_parse_log_rec(
 		return(0);
 	}
 
+#ifdef UNIV_LOG_LSN_DEBUG
+	if (*type == MLOG_LSN) {
+		ib_uint64_t	lsn = (ib_uint64_t) *space << 32 | *page_no;
+# ifdef UNIV_LOG_DEBUG
+		ut_a(lsn == log_sys->old_lsn);
+# else /* UNIV_LOG_DEBUG */
+		ut_a(lsn == recv_sys->recovered_lsn);
+# endif /* UNIV_LOG_DEBUG */
+	}
+#endif /* UNIV_LOG_LSN_DEBUG */
+
 	/* Check that page_no is sensible */
 
 	if (UNIV_UNLIKELY(*page_no > 0x8FFFFFFFUL)) {
@@ -2181,6 +2197,12 @@ loop:
 #endif
 			/* In normal mysqld crash recovery we do not try to
 			replay file operations */
+#ifdef UNIV_LOG_LSN_DEBUG
+		} else if (type == MLOG_LSN) {
+			/* Do not add these records to the hash table.
+			The page number and space id fields are misused
+			for something else. */
+#endif /* UNIV_LOG_LSN_DEBUG */
 		} else {
 			recv_add_to_hash_table(type, space, page_no, body,
 					       ptr + len, old_lsn,
@@ -2212,11 +2234,11 @@ loop:
 				= recv_sys->recovered_offset + total_len;
 			recv_previous_parsed_rec_is_multi = 1;
 
-			if ((!store_to_hash) && (type != MLOG_MULTI_REC_END)) {
 #ifdef UNIV_LOG_DEBUG
+			if ((!store_to_hash) && (type != MLOG_MULTI_REC_END)) {
 				recv_check_incomplete_log_recs(ptr, len);
-#endif /* UNIV_LOG_DEBUG */
 			}
+#endif /* UNIV_LOG_DEBUG */
 
 #ifdef UNIV_DEBUG
 			if (log_debug_writes) {
@@ -2280,7 +2302,11 @@ loop:
 				break;
 			}
 
-			if (store_to_hash) {
+			if (store_to_hash
+#ifdef UNIV_LOG_LSN_DEBUG
+			    && type != MLOG_LSN
+#endif /* UNIV_LOG_LSN_DEBUG */
+			    ) {
 				recv_add_to_hash_table(type, space, page_no,
 						       body, ptr + len,
 						       old_lsn,

srv/srv0start.c

@@ -1097,6 +1097,10 @@ innobase_start_or_create_for_mysql(void)
 		"InnoDB: !!!!!!!! UNIV_SEARCH_DEBUG switched on !!!!!!!!!\n");
 #endif
 
+#ifdef UNIV_LOG_LSN_DEBUG
+	fprintf(stderr,
+		"InnoDB: !!!!!!!! UNIV_LOG_LSN_DEBUG switched on !!!!!!!!!\n");
+#endif /* UNIV_LOG_LSN_DEBUG */
 #ifdef UNIV_MEM_DEBUG
 	fprintf(stderr,
 		"InnoDB: !!!!!!!! UNIV_MEM_DEBUG switched on !!!!!!!!!\n");