Bug#21924224 POTENTIAL RUNNING OUT OF SPACE IN REDO

Problem:
--------
The key issue is the margin calculation for foreground threads.
If innodb_thread_concurrency = 0 (default), no margin for
foreground threads are allocated. For small redo size and
large write concurrency, concurrent threads loop and perform
checkpoint to free redo space at mtr commit.

If one of the mtrs is holding latch on the oldest modified page
then checkpoint fails to create more space for redo and whole
system hangs. It could also lead to redo overwrite eventually by
repeated calls to checkpoint.

Solution:
---------
By current design we could avoid this scenario by reserving enough
space for all running mtrs. However, currently it is not easy to
arrive at correct foreground and background write concurrency
and reserving too much space could have impact on existing use
cases.

We thus take the following approach to resolve the hang and
reduce the possibility of redo overwrite.

1. Change innobase_log_file_size minimum value from 1M to 4M.
This would need documentation change.

2. Correct length calculation log_margin_checkpoint_age() at mtr commit.

3. AT mtr commit if not enough free margin attempt to do checkpoint once
and continue.

4. For write_always option don't overwrite redo log header with older lsn.

Reviewed-by: Marko Makela <marko.makela@oracle.com>
Reviewed-by: Pawel Olchawa <pawel.olchawa@oracle.com>

RB: 10957

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

@@ -1,11 +1,11 @@
-# restart: --innodb-fast-shutdown=2 --innodb-log-file-size=1M
+# restart: --innodb-fast-shutdown=2 --innodb-log-file-size=4M
 call mtr.add_suppression("InnoDB: Resizing redo log");
 call mtr.add_suppression("InnoDB: Starting to delete and rewrite log files");
 call mtr.add_suppression("InnoDB: New log files created");
 call mtr.add_suppression("InnoDB: The log sequence numbers [0-9]+ and [0-9]+ in ibdata files do not match the log sequence number [0-9]+ in the ib_logfiles");
 SELECT @@innodb_log_file_size;
 @@innodb_log_file_size
-1048576
+4194304
 SELECT @@innodb_log_files_in_group;
 @@innodb_log_files_in_group
 2
@@ -43,11 +43,11 @@ id	LEFT(bfield,20)
 11	aaaaaaaaaaaaaaaaaaaa
 12	bbbbbbbbbbbbbbbbbbbb
 13	cccccccccccccccccccc
-The size of the ib_logfile0 file: 2 
-The size of the ib_logfile1 file: 2 
-The size of the ib_logfile2 file: 2 
-The size of the ib_logfile3 file: 2 
-The size of the ib_logfile4 file: 2 
+The size of the ib_logfile0 file: 4
+The size of the ib_logfile1 file: 4
+The size of the ib_logfile2 file: 4
+The size of the ib_logfile3 file: 4
+The size of the ib_logfile4 file: 4
 USE db_wl6494;
 SELECT id,LEFT(bfield,20) FROM t1;
 id	LEFT(bfield,20)
@@ -75,10 +75,10 @@ id	LEFT(bfield,20)
 23	cccccccccccccccccccc
 DROP TABLE t1;
 DROP DATABASE db_wl6494;
-# restart: --innodb-fast-shutdown=2 --innodb-log-file-size=3M --innodb_log_files_in_group=3
+# restart: --innodb-fast-shutdown=2 --innodb-log-file-size=6M --innodb_log_files_in_group=3
 SELECT @@innodb_log_file_size;
 @@innodb_log_file_size
-3145728
+6291456
 SELECT @@innodb_log_files_in_group;
 @@innodb_log_files_in_group
 3
@@ -118,7 +118,7 @@ id	LEFT(bfield,20)
 13	cccccccccccccccccccc
 SELECT @@innodb_log_file_size;
 @@innodb_log_file_size
-2097152
+4194304
 SELECT @@innodb_log_files_in_group;
 @@innodb_log_files_in_group
 2

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

@@ -23,7 +23,7 @@ if (`SELECT @@innodb_log_file_size = 2097152`) {
 }
 
 # restart with innodb-fast-shutdown=2 to on stopping it , behave as crash
-let $restart_parameters = restart: --innodb-fast-shutdown=2 --innodb-log-file-size=1M;
+let $restart_parameters = restart: --innodb-fast-shutdown=2 --innodb-log-file-size=4M;
 --source include/restart_mysqld.inc
 
 call mtr.add_suppression("InnoDB: Resizing redo log");
@@ -62,8 +62,8 @@ SELECT id,LEFT(bfield,20) FROM t1;
 --source include/shutdown_mysqld.inc
 
 # restart with different redo log size
-# set log size from 2*1M to 5*2M
---exec echo "restart: --innodb-log-file-size=2M --innodb_log_files_in_group=5  --log-error=$MYSQLTEST_VARDIR/log/case1.err" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+# set log size from 2*4M to 5*4M
+--exec echo "restart: --innodb-log-file-size=4M --innodb_log_files_in_group=5 --log-error=$MYSQLTEST_VARDIR/log/case1.err" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 --enable_reconnect
 --source include/wait_until_connected_again.inc
 --disable_reconnect
@@ -77,19 +77,19 @@ perl;
  my $dir = $ENV{'MYSQLD_DATADIR'};
  $file = "ib_logfile0";
  $size_in_MB = (-s "$dir/$file") / (1024 * 1024);;
- print "The size of the $file file: $size_in_MB \n";
+ print "The size of the $file file: $size_in_MB\n";
  $file = "ib_logfile1";
  $size_in_MB = (-s "$dir/$file") / (1024 * 1024);;
- print "The size of the $file file: $size_in_MB \n";
+ print "The size of the $file file: $size_in_MB\n";
  $file = "ib_logfile2";
  $size_in_MB = (-s "$dir/$file") / (1024 * 1024);;
- print "The size of the $file file: $size_in_MB \n";
+ print "The size of the $file file: $size_in_MB\n";
  $file = "ib_logfile3";
  $size_in_MB = (-s "$dir/$file") / (1024 * 1024);;
- print "The size of the $file file: $size_in_MB \n";
+ print "The size of the $file file: $size_in_MB\n";
  $file = "ib_logfile4";
  $size_in_MB = (-s "$dir/$file") / (1024 * 1024);;
- print "The size of the $file file: $size_in_MB \n";
+ print "The size of the $file file: $size_in_MB\n";
 EOF
 
 
@@ -106,8 +106,8 @@ SELECT id,LEFT(bfield,20) FROM t1;
 # restart with different redo log size
 DROP TABLE t1;
 DROP DATABASE db_wl6494;
-# set log size to 3*3M
-let $restart_parameters = restart: --innodb-fast-shutdown=2 --innodb-log-file-size=3M --innodb_log_files_in_group=3;
+# set log size to 3*6M
+let $restart_parameters = restart: --innodb-fast-shutdown=2 --innodb-log-file-size=6M --innodb_log_files_in_group=3;
 --source include/restart_mysqld.inc
 
 SELECT @@innodb_log_file_size;
@@ -137,8 +137,8 @@ SELECT id,LEFT(bfield,20) FROM t1;
 
 # restart with different redo log size
 --source include/shutdown_mysqld.inc
-# set log size from 3*3M to 2*2M
---exec echo "restart: --innodb-log-file-size=2M --innodb_log_files_in_group=2  --log-error=$MYSQLTEST_VARDIR/log/case2.err" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+# set log size from 3*6M to 2*4M
+--exec echo "restart: --innodb-log-file-size=4M --innodb_log_files_in_group=2 --log-error=$MYSQLTEST_VARDIR/log/case2.err" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
 --enable_reconnect
 --source include/wait_until_connected_again.inc
 --disable_reconnect

storage/innobase/handler/ha_innodb.cc

@@ -1,6 +1,6 @@
 /*****************************************************************************
 
-Copyright (c) 2000, 2015, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 2000, 2016, Oracle and/or its affiliates. All Rights Reserved.
 Copyright (c) 2008, 2009 Google Inc.
 Copyright (c) 2009, Percona Inc.
 Copyright (c) 2012, Facebook Inc.
@@ -19202,7 +19202,7 @@ static MYSQL_SYSVAR_LONG(log_buffer_size, innobase_log_buffer_size,
 static MYSQL_SYSVAR_LONGLONG(log_file_size, innobase_log_file_size,
   PLUGIN_VAR_RQCMDARG | PLUGIN_VAR_READONLY,
   "Size of each log file in a log group.",
-  NULL, NULL, 48*1024*1024L, 1*1024*1024L, LLONG_MAX, 1024*1024L);
+  NULL, NULL, 48*1024*1024L, 4*1024*1024L, LLONG_MAX, 1024*1024L);
 
 static MYSQL_SYSVAR_ULONG(log_files_in_group, srv_n_log_files,
   PLUGIN_VAR_RQCMDARG | PLUGIN_VAR_READONLY,

storage/innobase/log/log0log.cc

@@ -1,6 +1,6 @@
 /*****************************************************************************
 
-Copyright (c) 1995, 2015, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 1995, 2016, Oracle and/or its affiliates. All Rights Reserved.
 Copyright (c) 2009, Google Inc.
 
 Portions of this file contain modifications contributed and copyrighted by
@@ -247,7 +247,36 @@ log_buffer_extend(
 	ib::info() << "innodb_log_buffer_size was extended to "
 		<< LOG_BUFFER_SIZE << ".";
 }
+
 #ifndef UNIV_HOTBACKUP
+/** Calculate actual length in redo buffer and file including
+block header and trailer.
+@param[in]	len	length to write
+@return actual length to write including header and trailer. */
+static inline
+ulint
+log_calculate_actual_len(
+	ulint len)
+{
+	ut_ad(log_mutex_own());
+
+	/* actual length stored per block */
+	const ulint	len_per_blk = OS_FILE_LOG_BLOCK_SIZE
+		- (LOG_BLOCK_HDR_SIZE + LOG_BLOCK_TRL_SIZE);
+
+	/* actual data length in last block already written */
+	ulint	extra_len = (log_sys->buf_free % OS_FILE_LOG_BLOCK_SIZE);
+
+	ut_ad(extra_len >= LOG_BLOCK_HDR_SIZE);
+	extra_len -= LOG_BLOCK_HDR_SIZE;
+
+	/* total extra length for block header and trailer */
+	extra_len = ((len + extra_len) / len_per_blk)
+		* (LOG_BLOCK_HDR_SIZE + LOG_BLOCK_TRL_SIZE);
+
+	return(len + extra_len);
+}
+
 /** Check margin not to overwrite transaction log from the last checkpoint.
 If would estimate the log write to exceed the log_group_capacity,
 waits for the checkpoint is done enough.
@@ -257,7 +286,7 @@ void
 log_margin_checkpoint_age(
 	ulint	len)
 {
-	ulint	margin = len * 2;
+	ulint	margin = log_calculate_actual_len(len);
 
 	ut_ad(log_mutex_own());
 
@@ -279,8 +308,11 @@ log_margin_checkpoint_age(
 		return;
 	}
 
-	while (log_sys->lsn - log_sys->last_checkpoint_lsn + margin
-	       > log_sys->log_group_capacity) {
+	/* Our margin check should ensure that we never reach this condition.
+	Try to do checkpoint once. We cannot keep waiting here as it might
+	result in hang in case the current mtr has latch on oldest lsn */
+	if (log_sys->lsn - log_sys->last_checkpoint_lsn + margin
+	    > log_sys->log_group_capacity) {
 		/* The log write of 'len' might overwrite the transaction log
 		after the last checkpoint. Makes checkpoint. */
 
@@ -1757,9 +1789,10 @@ log_checkpoint(
 	write-ahead-logging algorithm ensures that the log has been
 	flushed up to oldest_lsn. */
 
+	ut_ad(oldest_lsn >= log_sys->last_checkpoint_lsn);
 	if (!write_always
 	    && oldest_lsn
-	    == log_sys->last_checkpoint_lsn + SIZE_OF_MLOG_CHECKPOINT) {
+	    <= log_sys->last_checkpoint_lsn + SIZE_OF_MLOG_CHECKPOINT) {
 		/* Do nothing, because nothing was logged (other than
 		a MLOG_CHECKPOINT marker) since the previous checkpoint. */
 		log_mutex_exit();
@@ -1811,8 +1844,7 @@ log_checkpoint(
 	ut_ad(log_sys->flushed_to_disk_lsn >= flush_lsn);
 	ut_ad(flush_lsn >= oldest_lsn);
 
-	if (!write_always
-	    && log_sys->last_checkpoint_lsn >= oldest_lsn) {
+	if (log_sys->last_checkpoint_lsn >= oldest_lsn) {
 		log_mutex_exit();
 		return(true);
 	}

storage/innobase/mtr/mtr0mtr.cc

@@ -1,6 +1,6 @@
 /*****************************************************************************
 
-Copyright (c) 1995, 2015, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 1995, 2016, Oracle and/or its affiliates. All Rights Reserved.
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -746,8 +746,6 @@ mtr_t::Command::prepare_write()
 
 	log_mutex_enter();
 
-	log_margin_checkpoint_age(len);
-
 	if (fil_names_write_if_was_clean(space, m_impl->m_mtr)) {
 		/* This mini-transaction was the first one to modify
 		this tablespace since the latest checkpoint, so
@@ -781,6 +779,9 @@ mtr_t::Command::prepare_write()
 		}
 	}
 
+	/* check and attempt a checkpoint if exceeding capacity */
+	log_margin_checkpoint_age(len);
+
 	return(len);
 }
 

storage/innobase/row/row0upd.cc

@@ -1,6 +1,6 @@
 /*****************************************************************************
 
-Copyright (c) 1996, 2015, Oracle and/or its affiliates. All Rights Reserved.
+Copyright (c) 1996, 2016, Oracle and/or its affiliates. All Rights Reserved.
 
 This program is free software; you can redistribute it and/or modify it under
 the terms of the GNU General Public License as published by the Free Software
@@ -2986,16 +2986,16 @@ row_upd(
 		}
 	}
 
+	DEBUG_SYNC_C_IF_THD(thr_get_trx(thr)->mysql_thd,
+			    "after_row_upd_clust");
+
 	if (node->index == NULL
 	    || (!node->is_delete
 		&& (node->cmpl_info & UPD_NODE_NO_ORD_CHANGE))) {
 
 		DBUG_RETURN(DB_SUCCESS);
 	}
 
-	DEBUG_SYNC_C_IF_THD(thr_get_trx(thr)->mysql_thd,
-			    "after_row_upd_clust");
-
 	DBUG_EXECUTE_IF("row_upd_skip_sec", node->index = NULL;);
 
 	do {