Merge lp:~laurynas-biveinis/percona-server/bug1193332-5.5 into lp:percona-server/5.5

[Laurynas Biveinis]

Fix bug 1193332 ([Warning] InnoDB: changed page bitmap file
'./ib_modified_log_11_951286349.xdb' does not contain a complete run
at the end.)

The problem is bitmap writer thread working in parallel with bitmap
reader that processes an INFORMATION_SCHEMA.INNODB_CHANGED_PAGES
query, causing the latter to see partial data in the middle of the
write. The fix is, if the log tracker is running, to limit any
maximum LSN value for a query with an actual tracked LSN value.

Add a testcase to percona_changed_page_bmp_debug.

    http://jenkins.percona.com/job/percona-server-5.5-param/1009/

[Sergei Glushchenko (sergei.glushchenko)]

Approve

[Sergei Glushchenko (sergei.glushchenko)]

review: Approve (g2)

=== modified file 'mysql-test/suite/innodb/r/percona_changed_page_bmp_debug.result'
--- mysql-test/suite/innodb/r/percona_changed_page_bmp_debug.result	2013-09-25 05:52:09 +0000
+++ mysql-test/suite/innodb/r/percona_changed_page_bmp_debug.result	2014-06-11 13:20:55 +0000
@@ -42,3 +42,19 @@
 ERROR HY000: Can't read record in system table
 SET DEBUG_SYNC="RESET";
 DROP TABLE t2;
+RESET CHANGED_PAGE_BITMAPS;
+4th restart
+SET DEBUG_SYNC="i_s_innodb_changed_pages_range_ready SIGNAL ready WAIT_FOR finish";
+SELECT COUNT(*) FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES;
+SET DEBUG_SYNC="now WAIT_FOR ready";
+SET @@GLOBAL.innodb_track_changed_pages=FALSE;
+SET @@GLOBAL.innodb_log_checkpoint_now=TRUE;
+CREATE TABLE t1 (a INT)ENGINE=InnoDB;
+INSERT INTO t1 VALUES (1);
+CREATE TABLE t2 (a INT) ENGINE=InnoDB;
+INSERT INTO t2 VALUES (2);
+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";
+DROP TABLE t1, t2;

=== modified file 'mysql-test/suite/innodb/t/percona_changed_page_bmp_debug.test'
--- mysql-test/suite/innodb/t/percona_changed_page_bmp_debug.test	2013-09-25 05:52:09 +0000
+++ mysql-test/suite/innodb/t/percona_changed_page_bmp_debug.test	2014-06-11 13:20:55 +0000
@@ -130,5 +130,61 @@
 disconnect con2;
 
 DROP TABLE t2;
+RESET CHANGED_PAGE_BITMAPS;
+
+--source include/wait_until_count_sessions.inc
+
+#
+# Test for bug 1193332 ([Warning] InnoDB: changed page bitmap file
+# './ib_modified_log_11_951286349.xdb' does not contain a complete run at the end.)
+#
+
+# Setup an error on the 2nd bitmap page write, so that bitmap contains an incomplete run
+--echo 4th restart
+--exec echo "wait" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+--shutdown_server 10
+--source include/wait_until_disconnected.inc
+--enable_reconnect
+--exec echo "restart:-#d,bitmap_page_2_write_error" > $MYSQLTEST_VARDIR/tmp/mysqld.1.expect
+--source include/wait_until_connected_again.inc
+
+--source include/count_sessions.inc
+
+--connect(con2,localhost,root,,)
+
+SET DEBUG_SYNC="i_s_innodb_changed_pages_range_ready SIGNAL ready WAIT_FOR finish";
+send SELECT COUNT(*) FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES;
+
+--connection default
+
+SET DEBUG_SYNC="now WAIT_FOR ready";
+
+# Pause the log tracker
+SET @@GLOBAL.innodb_track_changed_pages=FALSE;
+SET @@GLOBAL.innodb_log_checkpoint_now=TRUE;
+
+# Prepare two pages of bitmap data
+CREATE TABLE t1 (a INT)ENGINE=InnoDB;
+INSERT INTO t1 VALUES (1);
+CREATE TABLE t2 (a INT) ENGINE=InnoDB;
+INSERT INTO t2 VALUES (2);
+
+# Resume the log tracker so it crashes after writing one page
+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";
+
+--connection con2
+# With the bug present the query will fail with ER_CANT_FIND_SYSTEM_REC
+--disable_result_log
+reap;
+--enable_result_log
+
+--disconnect con2
+--connection default
+
+DROP TABLE t1, t2;
 
 --source include/wait_until_count_sessions.inc

=== modified file 'storage/innobase/handler/i_s.cc'
--- storage/innobase/handler/i_s.cc	2013-10-31 11:50:31 +0000
+++ storage/innobase/handler/i_s.cc	2014-06-11 13:20:55 +0000
@@ -42,6 +42,7 @@
 #include "i_s.h"
 #include <sql_plugin.h>
 #include <mysql/innodb_priv.h>
+#include <debug_sync.h>
 
 extern "C" {
 #include "btr0pcur.h"	/* for file sys_tables related info. */
@@ -7511,12 +7512,23 @@
 		limit_lsn_range_from_condition(table, cond, &min_lsn,
 					       &max_lsn);
 	}
+	
+	/* If the log tracker is running and our max_lsn > current tracked LSN,
+	cap the max lsn so that we don't try to read any partial runs as the
+	tracked LSN advances. */
+	if (srv_track_changed_pages) {
+		ib_uint64_t		tracked_lsn = log_get_tracked_lsn();
+		if (max_lsn > tracked_lsn)
+			max_lsn = tracked_lsn;
+	}
 
 	if (!log_online_bitmap_iterator_init(&i, min_lsn, max_lsn)) {
 		my_error(ER_CANT_FIND_SYSTEM_REC, MYF(0));
 		DBUG_RETURN(1);
 	}
 
+	DEBUG_SYNC(thd, "i_s_innodb_changed_pages_range_ready");
+
 	while(log_online_bitmap_iterator_next(&i) &&
 	      (!srv_max_changed_pages ||
 	       output_rows_num < srv_max_changed_pages) &&

=== modified file 'storage/innobase/include/log0log.h'
--- storage/innobase/include/log0log.h	2013-12-05 08:07:26 +0000
+++ storage/innobase/include/log0log.h	2014-06-11 13:20:55 +0000
@@ -581,6 +581,18 @@
 log_mem_free(void);
 /*==============*/
 
+/****************************************************************//**
+Safely reads the log_sys->tracked_lsn value.  Uses atomic operations
+if available, otherwise this field is protected with the log system
+mutex.  The writer counterpart function is log_set_tracked_lsn() in
+log0online.c.
+
+@return log_sys->tracked_lsn value. */
+UNIV_INLINE
+ib_uint64_t
+log_get_tracked_lsn(void);
+/*=====================*/
+
 extern log_t*	log_sys;
 
 /* Values used as flags */

=== modified file 'storage/innobase/include/log0log.ic'
--- storage/innobase/include/log0log.ic	2013-08-02 09:40:55 +0000
+++ storage/innobase/include/log0log.ic	2014-06-11 13:20:55 +0000
@@ -459,3 +459,24 @@
 	}
 }
 #endif /* !UNIV_HOTBACKUP */
+
+/****************************************************************//**
+Safely reads the log_sys->tracked_lsn value.  Uses atomic operations
+if available, otherwise this field is protected with the log system
+mutex.  The writer counterpart function is log_set_tracked_lsn() in
+log0online.c.
+
+@return log_sys->tracked_lsn value. */
+UNIV_INLINE
+ib_uint64_t
+log_get_tracked_lsn(void)
+/*=====================*/
+{
+#ifdef HAVE_ATOMIC_BUILTINS_64
+	return os_atomic_increment_uint64(&log_sys->tracked_lsn, 0);
+#else
+	ut_ad(mutex_own(&(log_sys->mutex)));
+	return log_sys->tracked_lsn;
+#endif
+}
+

=== modified file 'storage/innobase/log/log0log.c'
--- storage/innobase/log/log0log.c	2013-12-05 08:07:26 +0000
+++ storage/innobase/log/log0log.c	2014-06-11 13:20:55 +0000
@@ -215,25 +215,6 @@
 }
 
 /****************************************************************//**
-Safely reads the log_sys->tracked_lsn value.  Uses atomic operations
-if available, otherwise this field is protected with the log system
-mutex.  The writer counterpart function is log_set_tracked_lsn() in
-log0online.c.
-
-@return log_sys->tracked_lsn value. */
-UNIV_INLINE
-ib_uint64_t
-log_get_tracked_lsn()
-{
-#ifdef HAVE_ATOMIC_BUILTINS_64
-	return os_atomic_increment_uint64(&log_sys->tracked_lsn, 0);
-#else
-	ut_ad(mutex_own(&(log_sys->mutex)));
-	return log_sys->tracked_lsn;
-#endif
-}
-
-/****************************************************************//**
 Checks if the log groups have a big enough margin of free space in
 so that a new log entry can be written without overwriting log data
 that is not read by the changed page bitmap thread.

=== modified file 'storage/innobase/log/log0online.c'
--- storage/innobase/log/log0online.c	2014-02-14 07:44:36 +0000
+++ storage/innobase/log/log0online.c	2014-06-11 13:20:55 +0000
@@ -1202,6 +1202,9 @@
 
 		bmp_tree_node = (ib_rbt_node_t*)
 			rbt_next(log_bmp_sys->modified_pages, bmp_tree_node);
+
+		DBUG_EXECUTE_IF("bitmap_page_2_write_error",
+				DBUG_SET("+d,bitmap_page_write_error"););
 	}
 
 	rbt_reset(log_bmp_sys->modified_pages);