Merge lp:~laurynas-biveinis/percona-server/bug1217002-5.1 into lp:percona-server/5.1

[Laurynas Biveinis]

a QA blocker.

http://jenkins.percona.com/job/percona-server-5.1-param/571/

Fix
- bug 1217002 (RENAME/DROP crashes with innodb_track_changed_pages);
- bug 1213885 (Failing assertion: error == DB_SUCCESS in file
  handler0alter.cc line 4897 | abort in commit_cache_rebuild).

Both bugs are caused by a recent upstream change that makes
MLOG_FILE_RENAME to replay unconditionally whenever such log record is
parsed, which includes online log tracking.

Fix by
- asserting in fil_op_log_parse_or_replay() that, if a file operation
  is about to be executed, that recovery is on, and
- adjusting recv_parse_or_apply_log_rec_body() to only pass non-zero
  space_id to fil_op_log_parse_or_replay if recovery is on. A
  non-zero space_id is what causes fil_op_log_parse_or_replay() to
  replay and not only parse the log record.

Changes for testing:
- backport from 5.5+ the debug-only innodb_log_checkpoint_now system
  variable;
- make innodb_track_changed_pages a dynamic variable, for debug builds
  only, to provide the ability to stop log tracking temporarily;
- add a new debug-only system variable innodb_track_redo_log_now, that
  issues a synchronuous redo log parse request;
- add a new debug sync point to row_merge_rename_tables();
- use all of the above to add a testcase to
  percona_changed_page_bmp_debug test.

[Alexey Kopytov (akopytov)]

review: Approve

=== modified file 'Percona-Server/mysql-test/r/percona_server_variables_debug.result'
--- Percona-Server/mysql-test/r/percona_server_variables_debug.result	2013-06-03 03:53:55 +0000
+++ Percona-Server/mysql-test/r/percona_server_variables_debug.result	2013-09-09 16:35:56 +0000
@@ -127,6 +127,7 @@
 INNODB_LOCK_WAIT_TIMEOUT
 INNODB_LOG_BLOCK_SIZE
 INNODB_LOG_BUFFER_SIZE
+INNODB_LOG_CHECKPOINT_NOW
 INNODB_LOG_FILES_IN_GROUP
 INNODB_LOG_FILE_SIZE
 INNODB_LOG_GROUP_HOME_DIR
@@ -165,6 +166,7 @@
 INNODB_THREAD_CONCURRENCY_TIMER_BASED
 INNODB_THREAD_SLEEP_DELAY
 INNODB_TRACK_CHANGED_PAGES
+INNODB_TRACK_REDO_LOG_NOW
 INNODB_TRX_PURGE_VIEW_UPDATE_ONLY_DEBUG
 INNODB_TRX_RSEG_N_SLOTS_DEBUG
 INNODB_USE_PURGE_THREAD

=== modified file 'Percona-Server/mysql-test/suite/innodb_plugin/r/percona_changed_page_bmp_debug.result'
--- Percona-Server/mysql-test/suite/innodb_plugin/r/percona_changed_page_bmp_debug.result	2013-02-07 07:29:35 +0000
+++ Percona-Server/mysql-test/suite/innodb_plugin/r/percona_changed_page_bmp_debug.result	2013-09-09 16:35:56 +0000
@@ -21,3 +21,17 @@
 INSERT INTO t1 SELECT x FROM t1;
 3rd restart
 DROP TABLE t1;
+CREATE TABLE t1 (x INT NOT NULL UNIQUE KEY) ENGINE=InnoDB;
+INSERT INTO t1 VALUES(5);
+SET @@GLOBAL.innodb_track_changed_pages=FALSE;
+SET @@GLOBAL.innodb_log_checkpoint_now=TRUE;
+RENAME TABLE t1 TO t2;
+SET DEBUG_SYNC="row_merge_rename_tables_between_renames SIGNAL alter_table_ready WAIT_FOR finish_alter_table";
+ALTER TABLE t2 ADD PRIMARY KEY(x);
+SET DEBUG_SYNC="now WAIT_FOR alter_table_ready";
+SET @@GLOBAL.innodb_log_checkpoint_now=TRUE;
+SET @@GLOBAL.innodb_track_changed_pages=TRUE;
+SET @@GLOBAL.innodb_track_redo_log_now=TRUE;
+SET DEBUG_SYNC="now SIGNAL finish_alter_table";
+SET DEBUG_SYNC="RESET";
+DROP TABLE t2;

=== modified file 'Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp_debug-master.opt'
--- Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp_debug-master.opt	2013-02-07 07:29:35 +0000
+++ Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp_debug-master.opt	2013-09-09 16:35:56 +0000
@@ -1,1 +1,1 @@
---innodb_track_changed_pages=TRUE --innodb_log_file_size=1M
+--innodb_track_changed_pages=TRUE --innodb_log_file_size=1M --innodb-file-per-table

=== modified file 'Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp_debug.test'
--- Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp_debug.test	2013-02-07 07:29:35 +0000
+++ Percona-Server/mysql-test/suite/innodb_plugin/t/percona_changed_page_bmp_debug.test	2013-09-09 16:35:56 +0000
@@ -3,6 +3,7 @@
 #
 --source include/have_debug.inc
 --source include/have_innodb_plugin.inc
+--source include/count_sessions.inc
 
 --disable_warnings
 DROP TABLE IF EXISTS t1;
@@ -54,3 +55,48 @@
 --source include/restart_mysqld.inc
 
 DROP TABLE t1;
+
+#
+# Test for bug 1217002 (RENAME/DROP crashes with innodb_track_changed_pages)
+#
+CREATE TABLE t1 (x INT NOT NULL UNIQUE KEY) ENGINE=InnoDB;
+INSERT INTO t1 VALUES(5);
+
+# 1. Pause the log tracking thread
+SET @@GLOBAL.innodb_track_changed_pages=FALSE;
+SET @@GLOBAL.innodb_log_checkpoint_now=TRUE;
+
+# 2. Rename a table to log a MLOG_FILE_RENAME operation
+RENAME TABLE t1 TO t2;
+
+# 3. Start an ALTER TABLE and stop it after the table -> temp table rename
+--connect (con2,localhost,root,,)
+--connection default
+
+SET DEBUG_SYNC="row_merge_rename_tables_between_renames SIGNAL alter_table_ready WAIT_FOR finish_alter_table";
+
+send ALTER TABLE t2 ADD PRIMARY KEY(x);
+
+# 4. Force a checkpoint and resume the log tracker thread, so that it misapplies the t1 > t2 rename.
+--connection con2
+
+SET DEBUG_SYNC="now WAIT_FOR alter_table_ready";
+
+SET @@GLOBAL.innodb_log_checkpoint_now=TRUE;
+SET @@GLOBAL.innodb_track_changed_pages=TRUE;
+
+# 5. Force the log tracker to catch up.
+SET @@GLOBAL.innodb_track_redo_log_now=TRUE;
+
+# 6. Finish the ALTER TABLE, which then crashes if the bug is present.
+SET DEBUG_SYNC="now SIGNAL finish_alter_table";
+
+--connection default
+reap;
+SET DEBUG_SYNC="RESET";
+
+disconnect con2;
+
+DROP TABLE t2;
+
+--source include/wait_until_count_sessions.inc

=== modified file 'Percona-Server/storage/innodb_plugin/fil/fil0fil.c'
--- Percona-Server/storage/innodb_plugin/fil/fil0fil.c	2013-08-05 13:11:52 +0000
+++ Percona-Server/storage/innodb_plugin/fil/fil0fil.c	2013-09-09 16:35:56 +0000
@@ -2114,6 +2114,11 @@
 	if (!space_id) {
 
 		return(ptr);
+	} else {
+		/* Only replay file ops during recovery.  This is a
+		release-build assert to minimize any data loss risk by a
+		misapplied file operation.  */
+		ut_a(recv_recovery_is_on());
 	}
 
 	/* Let us try to perform the file operation, if sensible. Note that

=== modified file 'Percona-Server/storage/innodb_plugin/handler/ha_innodb.cc'
--- Percona-Server/storage/innodb_plugin/handler/ha_innodb.cc	2013-08-23 07:34:57 +0000
+++ Percona-Server/storage/innodb_plugin/handler/ha_innodb.cc	2013-09-09 16:35:56 +0000
@@ -11897,6 +11897,63 @@
 #endif
 }
 
+#ifdef UNIV_DEBUG
+static my_bool	innodb_log_checkpoint_now = TRUE;
+
+/****************************************************************//**
+Force innodb to checkpoint. */
+static
+void
+checkpoint_now_set(
+/*===============*/
+	THD*				thd	/*!< in: thread handle */
+	__attribute__((unused)),
+	struct st_mysql_sys_var*	var	/*!< in: pointer to system
+						variable */
+	__attribute__((unused)),
+	void*				var_ptr	/*!< out: where the formal
+						string goes */
+	__attribute__((unused)),
+	const void*			save)	/*!< in: immediate result from
+						check function */
+{
+	if (*(my_bool*) save) {
+		while (log_sys->last_checkpoint_lsn < log_sys->lsn) {
+			log_make_checkpoint_at(IB_ULONGLONG_MAX, TRUE);
+			fil_flush_file_spaces(FIL_LOG);
+		}
+		fil_write_flushed_lsn_to_data_files(log_sys->lsn, 0);
+		fil_flush_file_spaces(FIL_TABLESPACE);
+	}
+}
+
+static my_bool	innodb_track_redo_log_now = TRUE;
+
+/****************************************************************//**
+Force log tracker to track the log synchronously.  */
+static
+void
+track_redo_log_now_set(
+/*===================*/
+	THD*				thd	/*!< in: thread handle */
+	__attribute__((unused)),
+	struct st_mysql_sys_var*	var	/*!< in: pointer to system
+						variable */
+	__attribute__((unused)),
+	void*				var_ptr	/*!< out: where the formal
+						string goes */
+	__attribute__((unused)),
+	const void*			save)	/*!< in: immediate result from
+						check function */
+{
+	if (*(my_bool*) save && srv_track_changed_pages) {
+
+		log_online_follow_redo_log();
+	}
+}
+
+
+#endif /* UNIV_DEBUG */
 
 static SHOW_VAR innodb_status_variables_export[]= {
   {"Innodb",                   (char*) &show_innodb_vars, SHOW_FUNC},
@@ -12306,9 +12363,15 @@
    NULL, NULL, SRV_STATS_NULLS_EQUAL, &innodb_stats_method_typelib);
 
 static MYSQL_SYSVAR_BOOL(track_changed_pages, srv_track_changed_pages,
-    PLUGIN_VAR_NOCMDARG | PLUGIN_VAR_READONLY,
-    "Track the redo log for changed pages and output a changed page bitmap",
-    NULL, NULL, FALSE);
+  PLUGIN_VAR_NOCMDARG
+#ifndef UNIV_DEBUG
+  /* Make this variable dynamic for debug builds to
+  provide a testcase sync facility */
+  | PLUGIN_VAR_READONLY
+#endif
+  ,
+  "Track the redo log for changed pages and output a changed page bitmap",
+  NULL, NULL, FALSE);
 
 static MYSQL_SYSVAR_ULONGLONG(max_bitmap_file_size, srv_max_bitmap_file_size,
     PLUGIN_VAR_RQCMDARG,
@@ -12494,6 +12557,18 @@
   "It is to create artificially the situation the purge view have been updated "
   "but the each purges were not done yet.",
   NULL, NULL, FALSE);
+
+static MYSQL_SYSVAR_BOOL(log_checkpoint_now, innodb_log_checkpoint_now,
+  PLUGIN_VAR_OPCMDARG,
+  "Force checkpoint now",
+  NULL, checkpoint_now_set, FALSE);
+
+static MYSQL_SYSVAR_BOOL(track_redo_log_now,
+  innodb_track_redo_log_now,
+  PLUGIN_VAR_OPCMDARG,
+  "Force log tracker to catch up with checkpoint now",
+  NULL, track_redo_log_now_set, FALSE);
+
 #endif /* UNIV_DEBUG */
 
 static MYSQL_SYSVAR_BOOL(locking_fake_changes, srv_fake_changes_locks,
@@ -12613,6 +12688,8 @@
   MYSQL_SYSVAR(trx_rseg_n_slots_debug),
   MYSQL_SYSVAR(limit_optimistic_insert_debug),
   MYSQL_SYSVAR(trx_purge_view_update_only_debug),
+  MYSQL_SYSVAR(log_checkpoint_now),
+  MYSQL_SYSVAR(track_redo_log_now),
 #endif /* UNIV_DEBUG */
   NULL
 };

=== modified file 'Percona-Server/storage/innodb_plugin/log/log0recv.c'
--- Percona-Server/storage/innodb_plugin/log/log0recv.c	2013-08-05 13:11:52 +0000
+++ Percona-Server/storage/innodb_plugin/log/log0recv.c	2013-09-09 16:35:56 +0000
@@ -1256,7 +1256,8 @@
 		break;
 	case MLOG_FILE_RENAME:
 		ptr = fil_op_log_parse_or_replay(ptr, end_ptr, type,
-						 space_id, 0);
+						 (recv_recovery_is_on()
+						  ? space_id : 0), 0);
 		break;
 	case MLOG_FILE_CREATE:
 	case MLOG_FILE_DELETE:

=== modified file 'Percona-Server/storage/innodb_plugin/row/row0merge.c'
--- Percona-Server/storage/innodb_plugin/row/row0merge.c	2013-08-05 13:11:52 +0000
+++ Percona-Server/storage/innodb_plugin/row/row0merge.c	2013-09-09 16:35:56 +0000
@@ -58,6 +58,14 @@
 #include "handler0alter.h"
 #include "ha_prototypes.h"
 
+#ifdef __WIN__
+/* error LNK2001: unresolved external symbol _debug_sync_C_callback_ptr */
+# define DEBUG_SYNC_C(dummy) ((void) 0)
+#else
+# include "m_string.h" /* for my_sys.h */
+# include "my_sys.h" /* DEBUG_SYNC_C */
+#endif
+
 #ifdef UNIV_DEBUG
 /** Set these in order ot enable debug printout. */
 /* @{ */
@@ -2465,8 +2473,15 @@
 	/* The following calls will also rename the .ibd data files if
 	the tables are stored in a single-table tablespace */
 
-	if (!dict_table_rename_in_cache(old_table, tmp_name, FALSE)
-	    || !dict_table_rename_in_cache(new_table, old_name, FALSE)) {
+	if (!dict_table_rename_in_cache(old_table, tmp_name, FALSE)) {
+
+		err = DB_ERROR;
+		goto err_exit;
+	}
+
+	DEBUG_SYNC_C("row_merge_rename_tables_between_renames");
+
+	if (!dict_table_rename_in_cache(new_table, old_name, FALSE)) {
 
 		err = DB_ERROR;
 		goto err_exit;

=== modified file 'Percona-Server/storage/innodb_plugin/srv/srv0srv.c'
--- Percona-Server/storage/innodb_plugin/srv/srv0srv.c	2013-08-05 13:11:52 +0000
+++ Percona-Server/storage/innodb_plugin/srv/srv0srv.c	2013-09-09 16:35:56 +0000
@@ -2759,6 +2759,12 @@
 		os_event_wait(srv_checkpoint_completed_event);
 		os_event_reset(srv_checkpoint_completed_event);
 
+#ifdef UNIV_DEBUG
+		if (!srv_track_changed_pages) {
+			continue;
+		}
+#endif
+
 		if (!log_online_follow_redo_log()) {
 			/* TODO: sync with I_S log tracking status? */
 			fprintf(stderr,