Added --sync-sys=0 option for mysqld to skip sync() calls for faster testing

Fixed LP#613418 (M)aria recovery failure: ma_key_recover.c:981: _ma_apply_redo_index: Assertion `check_page_length == page_length' failed

include/my_sys.h:
  Added my_disable_sync
mysql-test/mysql-test-run.pl:
  Added --sync-sys=0 to run test suite faster
mysys/my_static.c:
  Added my_disable_sync
mysys/my_sync.c:
  Added my_disable_sync
sql/mysqld.cc:
  Added -sync-sys=0 option for mysqld to skip sync() calls for faster testing
storage/maria/ma_key_recover.c:
  More DBUG_ASSERT()
  Added logging of KEY_OP_DEBUG to make examening of logs easier
  Fixed testing of page length in recovery to ensure we don't overwrite checksum (previous tests was too relaxed)
  Fixed bug in recovery logging of split pages which caused failure during recovery:
  - Length was not adjusted properly for pages to be split
  - Added KEY_OP_MAX_PAGELENGTH to tell recovery that page is now full length
  - This fixed LP#613418
storage/maria/ma_key_recover.h:
  Changed prototype for ma_log_change() for KEY_OP_DEBUG
storage/maria/ma_loghandler.h:
  Added new enums for better debugging of recovery logs
storage/maria/ma_rt_index.c:
  Added debugging information to calls to ma_log_change()
storage/maria/ma_write.c:
  Added debugging information to calls to ma_log_change() and ma_log_split()

10 files changed, 93 insertions, 22 deletions

diff --git a/include/my_sys.h b/include/my_sys.h
index c5b3008e8bc..2f8a44fedc0 100644
--- a/include/my_sys.h
+++ b/include/my_sys.h
@@ -266,6 +266,7 @@ extern size_t sf_malloc_cur_memory, sf_malloc_max_memory;
 extern ulong	my_default_record_cache_size;
 extern my_bool NEAR my_disable_locking,NEAR my_disable_async_io,
                NEAR my_disable_flush_key_blocks, NEAR my_disable_symlinks;
+extern my_bool my_disable_sync;
 extern char	wild_many,wild_one,wild_prefix;
 extern const char *charsets_dir;
 /* from default.c */
diff --git a/mysql-test/mysql-test-run.pl b/mysql-test/mysql-test-run.pl
index e409bab32f7..eb51d385f77 100755
--- a/mysql-test/mysql-test-run.pl
+++ b/mysql-test/mysql-test-run.pl
@@ -1802,6 +1802,7 @@ sub mysql_fix_arguments () {
   mtr_add_arg($args, "--basedir=%s", $basedir);
   mtr_add_arg($args, "--bindir=%s", $path_client_bindir);
   mtr_add_arg($args, "--verbose");
+  mtr_add_arg($args, "--sync-sys=0"); # Speed up test suite
   return mtr_args2str($exe, @$args);
 }
 
diff --git a/mysys/my_static.c b/mysys/my_static.c
index 0ef5656b76f..08653d03d21 100644
--- a/mysys/my_static.c
+++ b/mysys/my_static.c
@@ -119,6 +119,7 @@ ulonglong query_performance_frequency, query_performance_offset;
 
 	/* How to disable options */
 my_bool NEAR my_disable_locking=0;
+my_bool NEAR my_disable_sync=0;
 my_bool NEAR my_disable_async_io=0;
 my_bool NEAR my_disable_flush_key_blocks=0;
 my_bool NEAR my_disable_symlinks=0;
diff --git a/mysys/my_sync.c b/mysys/my_sync.c
index 967a6ae6c78..9f6c55f4fb6 100644
--- a/mysys/my_sync.c
+++ b/mysys/my_sync.c
@@ -48,6 +48,9 @@ int my_sync(File fd, myf my_flags)
   DBUG_ENTER("my_sync");
   DBUG_PRINT("my",("fd: %d  my_flags: %d", fd, my_flags));
 
+  if (my_disable_sync)
+    DBUG_RETURN(0);
+
   statistic_increment(my_sync_count,&THR_LOCK_open);
   do
   {
diff --git a/sql/mysqld.cc b/sql/mysqld.cc
index eb46ba14f19..4f8cfd70615 100644
--- a/sql/mysqld.cc
+++ b/sql/mysqld.cc
@@ -418,6 +418,7 @@ static bool volatile ready_to_exit;
 static my_bool opt_debugging= 0, opt_external_locking= 0, opt_console= 0;
 static my_bool opt_short_log_format= 0;
 static my_bool opt_ignore_wrong_options= 0, opt_expect_abort= 0;
+static my_bool opt_sync= 0;
 static uint kill_cached_threads, wake_thread;
 ulong thread_created;
 static ulong max_used_connections;
@@ -5897,7 +5898,7 @@ enum options_mysqld
   OPT_RANGE_ALLOC_BLOCK_SIZE, OPT_ALLOW_SUSPICIOUS_UDFS,
   OPT_QUERY_ALLOC_BLOCK_SIZE, OPT_QUERY_PREALLOC_SIZE,
   OPT_TRANS_ALLOC_BLOCK_SIZE, OPT_TRANS_PREALLOC_SIZE,
-  OPT_SYNC_FRM, OPT_SYNC_BINLOG,
+  OPT_SYNC_FRM, OPT_SYNC_BINLOG, OPT_SYNC,
   OPT_SYNC_REPLICATION,
   OPT_SYNC_REPLICATION_SLAVE_ID,
   OPT_SYNC_REPLICATION_TIMEOUT,
@@ -7417,6 +7418,10 @@ thread is in the relay logs.",
   {"sync-frm", OPT_SYNC_FRM, "Sync .frm to disk on create. Enabled by default.",
    &opt_sync_frm, &opt_sync_frm, 0, GET_BOOL, NO_ARG, 1, 0,
    0, 0, 0, 0},
+  {"sync-sys", OPT_SYNC,
+   "Enable/disable system sync calls. Should only be turned off when running "
+   "tests or debugging!!",
+   &opt_sync, &opt_sync, 0, GET_BOOL, NO_ARG, 1, 0, 0, 0, 0, 0},
   {"table_cache", OPT_TABLE_OPEN_CACHE,
    "Deprecated; use --table_open_cache instead.",
    &table_cache_size, &table_cache_size, 0, GET_ULONG,
@@ -9158,6 +9163,7 @@ static int get_options(int *argc,char **argv)
     In most cases the global variables will not be used
   */
   my_disable_locking= myisam_single_user= test(opt_external_locking == 0);
+  my_disable_sync= opt_sync == 0;
   my_default_record_cache_size=global_system_variables.read_buff_size;
   myisam_max_temp_length=
     (my_off_t) global_system_variables.myisam_max_sort_file_size;
diff --git a/storage/maria/ma_key_recover.c b/storage/maria/ma_key_recover.c
index 38317cd61db..4dc902f9418 100644
--- a/storage/maria/ma_key_recover.c
+++ b/storage/maria/ma_key_recover.c
@@ -494,7 +494,8 @@ my_bool _ma_log_add(MARIA_PAGE *ma_page,
                     my_bool handle_overflow __attribute__ ((unused)))
 {
   LSN lsn;
-  uchar log_data[FILEID_STORE_SIZE + PAGE_STORE_SIZE + 3 + 3 + 3 + 3 + 7 + 2];
+  uchar log_data[FILEID_STORE_SIZE + PAGE_STORE_SIZE + 2 + 3 + 3 + 3 + 3 + 7 +
+                 2];
   uchar *log_pos;
   uchar *buff= ma_page->buff;
   LEX_CUSTRING log_array[TRANSLOG_INTERNAL_PARTS + 3];
@@ -509,6 +510,7 @@ my_bool _ma_log_add(MARIA_PAGE *ma_page,
                        (ulong) ma_page->pos, org_page_length, changed_length,
                        move_length));
   DBUG_ASSERT(info->s->now_transactional);
+  DBUG_ASSERT(move_length <= (int) changed_length);
 
   /*
     Write REDO entry that contains the logical operations we need
@@ -519,6 +521,11 @@ my_bool _ma_log_add(MARIA_PAGE *ma_page,
   page_store(log_pos, page_pos);
   log_pos+= PAGE_STORE_SIZE;
 
+#ifdef EXTRA_DEBUG_KEY_CHANGES
+  *log_pos++= KEY_OP_DEBUG;
+  *log_pos++= KEY_OP_DEBUG_LOG_ADD;
+#endif
+
   /* Store keypage_flag */
   *log_pos++= KEY_OP_SET_PAGEFLAG;
   *log_pos++= buff[KEYPAGE_TRANSFLAG_OFFSET];
@@ -533,21 +540,31 @@ my_bool _ma_log_add(MARIA_PAGE *ma_page,
     DBUG_ASSERT(handle_overflow);
     if (offset + changed_length > page_length)
     {
+      /* Log that data changed to end of page */
       changed_length= page_length - offset;
       move_length= 0;
+      /* Set page to max length */
+      org_page_length= page_length;
+      *log_pos++= KEY_OP_MAX_PAGELENGTH;
     }
     else
     {
+      /* They key will not be part of the page ; Don't log it */
       uint diff= org_page_length + move_length - page_length;
       log_pos[0]= KEY_OP_DEL_SUFFIX;
       int2store(log_pos+1, diff);
       log_pos+= 3;
-      org_page_length= page_length - move_length;
+      org_page_length-= diff;
+      DBUG_ASSERT(org_page_length == page_length - move_length);
     }
+    DBUG_ASSERT(offset != org_page_length);
   }
 
   if (offset == org_page_length)
+  {
+    DBUG_ASSERT(move_length == (int) changed_length);
     log_pos[0]= KEY_OP_ADD_SUFFIX;
+  }
   else
   {
     log_pos[0]= KEY_OP_OFFSET;
@@ -832,6 +849,8 @@ err:
    KEY_OP_CHECK      6 page_length[2},CRC Used only when debugging
    KEY_OP_COMPACT_PAGE  6 transid
    KEY_OP_SET_PAGEFLAG  1 flag for page
+   KEY_OP_MAX_PAGELENGTH 0                Set page to max length
+   KEY_OP_DEBUG	     1                    Info where logging was done
 
    @return Operation status
      @retval 0      OK
@@ -850,6 +869,7 @@ uint _ma_apply_redo_index(MARIA_HA *info,
   const uchar *header_end= header + head_length;
   uint page_offset= 0, org_page_length;
   uint nod_flag, page_length, keypage_header, keynr;
+  uint max_page_length= share->block_size - KEYPAGE_CHECKSUM_SIZE;
   int result;
   MARIA_PAGE page;
   DBUG_ENTER("_ma_apply_redo_index");
@@ -898,7 +918,7 @@ uint _ma_apply_redo_index(MARIA_HA *info,
       header+= 2;
       DBUG_PRINT("redo", ("key_op_shift: %d", length));
       DBUG_ASSERT(page_offset != 0 && page_offset <= page_length &&
-                  page_length + length < share->block_size);
+                  page_length + length <= max_page_length);
 
       if (length < 0)
         bmove(buff + page_offset, buff + page_offset - length,
@@ -927,7 +947,7 @@ uint _ma_apply_redo_index(MARIA_HA *info,
                           insert_length, changed_length));
 
       DBUG_ASSERT(insert_length <= changed_length &&
-                  page_length + changed_length <= share->block_size);
+                  page_length + changed_length <= max_page_length);
 
       bmove_upp(buff + page_length + insert_length, buff + page_length,
                 page_length - keypage_header);
@@ -954,7 +974,7 @@ uint _ma_apply_redo_index(MARIA_HA *info,
     {
       uint insert_length= uint2korr(header);
       DBUG_PRINT("redo", ("key_op_add_prefix: %u", insert_length));
-      DBUG_ASSERT(page_length + insert_length <= share->block_size);
+      DBUG_ASSERT(page_length + insert_length <= max_page_length);
       memcpy(buff + page_length, header+2, insert_length);
 
       page_length+= insert_length;
@@ -983,7 +1003,7 @@ uint _ma_apply_redo_index(MARIA_HA *info,
                                       page_length - LSN_STORE_SIZE))
       {
         DBUG_PRINT("error", ("page_length %u",page_length));
-        DBUG_DUMP("KEY_OP_CHECK bad page", buff, share->block_size);
+        DBUG_DUMP("KEY_OP_CHECK bad page", buff, max_page_length);
         DBUG_ASSERT("crc" == "failure in REDO_INDEX");
       }
 #endif
@@ -991,6 +1011,14 @@ uint _ma_apply_redo_index(MARIA_HA *info,
       header+= 6;
       break;
     }
+    case KEY_OP_DEBUG:
+      DBUG_PRINT("redo", ("Debug: %u", (uint) header[0]));
+      header++;
+      break;
+    case KEY_OP_MAX_PAGELENGTH:
+      DBUG_PRINT("redo", ("key_op_max_page_length"));
+      page_length= max_page_length;
+      break;
     case KEY_OP_MULTI_COPY:                     /* 9 */
     {
       /*
@@ -1011,7 +1039,7 @@ uint _ma_apply_redo_index(MARIA_HA *info,
       log_memcpy_length= uint2korr(header);
       header+= 2;
       log_memcpy_end= header + log_memcpy_length;
-      DBUG_ASSERT(full_length < share->block_size);
+      DBUG_ASSERT(full_length <= max_page_length);
       while (header < log_memcpy_end)
       {
         uint to, from;
@@ -1020,7 +1048,7 @@ uint _ma_apply_redo_index(MARIA_HA *info,
         from= uint2korr(header);
         header+= 2;
         /* "from" is a place in the existing page */
-        DBUG_ASSERT(max(from, to) < share->block_size);
+        DBUG_ASSERT(max(from, to) < max_page_length);
         memcpy(buff + to, buff + from, full_length);
       }
       break;
diff --git a/storage/maria/ma_key_recover.h b/storage/maria/ma_key_recover.h
index b580433c99a..30830f7d82c 100644
--- a/storage/maria/ma_key_recover.h
+++ b/storage/maria/ma_key_recover.h
@@ -72,7 +72,8 @@ my_bool _ma_log_add(MARIA_PAGE *page, uint buff_length, uchar *key_pos,
                     my_bool handle_overflow);
 my_bool _ma_log_delete(MARIA_PAGE *page, const uchar *key_pos,
                        uint changed_length, uint move_length);
-my_bool _ma_log_change(MARIA_PAGE *page, const uchar *key_pos, uint length);
+my_bool _ma_log_change(MARIA_PAGE *page, const uchar *key_pos, uint length,
+                       enum en_key_debug debug_marker);
 my_bool _ma_log_new(MARIA_PAGE *page, my_bool root_page);
 
 uint _ma_apply_redo_index_new_page(MARIA_HA *info, LSN lsn,
diff --git a/storage/maria/ma_loghandler.h b/storage/maria/ma_loghandler.h
index dba6283e303..2ef082e38dc 100644
--- a/storage/maria/ma_loghandler.h
+++ b/storage/maria/ma_loghandler.h
@@ -165,7 +165,20 @@ enum en_key_op
   KEY_OP_CHECK,         /* For debugging; CRC of used part of page */
   KEY_OP_MULTI_COPY,    /* List of memcpy()s with fixed-len sources in page */
   KEY_OP_SET_PAGEFLAG,  /* Set pageflag from next byte */
-  KEY_OP_COMPACT_PAGE   /* Compact key page */
+  KEY_OP_COMPACT_PAGE,	/* Compact key page */
+  KEY_OP_MAX_PAGELENGTH, /* Set page to max page length */
+  KEY_OP_DEBUG		/* Entry for storing what triggered redo_index */
+};
+
+enum en_key_debug
+{
+  KEY_OP_DEBUG_RTREE_COMBINE,
+  KEY_OP_DEBUG_RTREE_SPLIT,
+  KEY_OP_DEBUG_RTREE_SET_KEY,
+  KEY_OP_DEBUG_FATHER_CHANGED_1,
+  KEY_OP_DEBUG_FATHER_CHANGED_2,
+  KEY_OP_DEBUG_LOG_SPLIT,
+  KEY_OP_DEBUG_LOG_ADD
 };
 
 
diff --git a/storage/maria/ma_rt_index.c b/storage/maria/ma_rt_index.c
index d50dd99e5cf..62474dbbad8 100644
--- a/storage/maria/ma_rt_index.c
+++ b/storage/maria/ma_rt_index.c
@@ -625,7 +625,8 @@ static int maria_rtree_insert_req(MARIA_HA *info, MARIA_KEY *key,
       {
         maria_rtree_combine_rect(keyinfo->seg, k, key->data, k, key_length);
         if (share->now_transactional &&
-            _ma_log_change(&page, k, key_length))
+            _ma_log_change(&page, k, key_length,
+                           KEY_OP_DEBUG_RTREE_COMBINE))
           goto err;
         page_mark_changed(info, &page);
         if (_ma_write_keypage(&page, PAGECACHE_LOCK_LEFT_WRITELOCKED,
@@ -652,7 +653,8 @@ static int maria_rtree_insert_req(MARIA_HA *info, MARIA_KEY *key,
         if (maria_rtree_set_key_mbr(info, &k_key, _ma_kpos(nod_flag, k)))
           goto err;
         if (share->now_transactional &&
-            _ma_log_change(&page, k, key_length))
+            _ma_log_change(&page, k, key_length,
+                           KEY_OP_DEBUG_RTREE_SPLIT))
           goto err;
         /* add new key for new page */
         _ma_kpointer(info, new_key_buff - nod_flag, *new_page);
@@ -964,7 +966,8 @@ static int maria_rtree_delete_req(MARIA_HA *info, const MARIA_KEY *key,
                                           _ma_kpos(nod_flag, k)))
                 goto err;
               if (share->now_transactional &&
-                  _ma_log_change(&page, k, key->data_length))
+                  _ma_log_change(&page, k, key->data_length,
+                                 KEY_OP_DEBUG_RTREE_SET_KEY))
                 goto err;
               page_mark_changed(info, &page)
               if (_ma_write_keypage(&page,
diff --git a/storage/maria/ma_write.c b/storage/maria/ma_write.c
index a552d15a650..2d13b223399 100644
--- a/storage/maria/ma_write.c
+++ b/storage/maria/ma_write.c
@@ -1416,7 +1416,8 @@ static int _ma_balance_page(MARIA_HA *info, MARIA_KEYDEF *keyinfo,
     /* Log changes to father (one level up) page */
 
     if (share->now_transactional &&
-        _ma_log_change(father_page, father_key_pos, k_length))
+        _ma_log_change(father_page, father_key_pos, k_length,
+                       KEY_OP_DEBUG_FATHER_CHANGED_1))
       goto err;
 
     /*
@@ -1583,7 +1584,8 @@ static int _ma_balance_page(MARIA_HA *info, MARIA_KEYDEF *keyinfo,
 
     /* Log changes to father (one level up) page */
     if (share->now_transactional &&
-        _ma_log_change(father_page, father_key_pos, k_length))
+        _ma_log_change(father_page, father_key_pos, k_length,
+                       KEY_OP_DEBUG_FATHER_CHANGED_2))
       goto err;
   }
 
@@ -1905,11 +1907,11 @@ my_bool _ma_log_new(MARIA_PAGE *ma_page, my_bool root_page)
    Log when some part of the key page changes
 */
 
-my_bool _ma_log_change(MARIA_PAGE *ma_page,
-                       const uchar *key_pos, uint length)
+my_bool _ma_log_change(MARIA_PAGE *ma_page, const uchar *key_pos, uint length,
+                       enum en_key_debug debug_marker __attribute__((unused)))
 {
   LSN lsn;
-  uchar log_data[FILEID_STORE_SIZE + PAGE_STORE_SIZE + 6 + 7], *log_pos;
+  uchar log_data[FILEID_STORE_SIZE + PAGE_STORE_SIZE + 2 + 6 + 7], *log_pos;
   LEX_CUSTRING log_array[TRANSLOG_INTERNAL_PARTS + 3];
   uint offset= (uint) (key_pos - ma_page->buff), translog_parts;
   uint extra_length= 0;
@@ -1919,18 +1921,26 @@ my_bool _ma_log_change(MARIA_PAGE *ma_page,
   DBUG_PRINT("enter", ("page: %lu length: %u", (ulong) ma_page->pos, length));
 
   DBUG_ASSERT(info->s->now_transactional);
+  DBUG_ASSERT(offset + length <= ma_page->size);
 
   /* Store address of new root page */
   page= ma_page->pos / info->s->block_size;
   page_store(log_data + FILEID_STORE_SIZE, page);
   log_pos= log_data+ FILEID_STORE_SIZE + PAGE_STORE_SIZE;
+
+#ifdef EXTRA_DEBUG_KEY_CHANGES
+  (*log_pos++)= KEY_OP_DEBUG;
+  (*log_pos++)= debug_marker;
+#endif
+
   log_pos[0]= KEY_OP_OFFSET;
   int2store(log_pos+1, offset);
   log_pos[3]= KEY_OP_CHANGE;
   int2store(log_pos+4, length);
+  log_pos+= 6;
 
   log_array[TRANSLOG_INTERNAL_PARTS + 0].str=    log_data;
-  log_array[TRANSLOG_INTERNAL_PARTS + 0].length= sizeof(log_data) - 7;
+  log_array[TRANSLOG_INTERNAL_PARTS + 0].length= (log_pos - log_data);
   log_array[TRANSLOG_INTERNAL_PARTS + 1].str=    key_pos;
   log_array[TRANSLOG_INTERNAL_PARTS + 1].length= length;
   translog_parts= 2;
@@ -1941,7 +1951,6 @@ my_bool _ma_log_change(MARIA_PAGE *ma_page,
     ha_checksum crc;
     crc= my_checksum(0, ma_page->buff + LSN_STORE_SIZE,
                      page_length - LSN_STORE_SIZE);
-    log_pos+= 6;
     log_pos[0]= KEY_OP_CHECK;
     int2store(log_pos+1, page_length);
     int4store(log_pos+3, crc);
@@ -1987,7 +1996,7 @@ static my_bool _ma_log_split(MARIA_PAGE *ma_page,
                              uint changed_length)
 {
   LSN lsn;
-  uchar log_data[FILEID_STORE_SIZE + PAGE_STORE_SIZE + 3+3+3+3+3+2 +7];
+  uchar log_data[FILEID_STORE_SIZE + PAGE_STORE_SIZE + 2 + 3+3+3+3+3+2 +7];
   uchar *log_pos;
   LEX_CUSTRING log_array[TRANSLOG_INTERNAL_PARTS + 4];
   uint offset= (uint) (key_pos - ma_page->buff);
@@ -2003,6 +2012,11 @@ static my_bool _ma_log_split(MARIA_PAGE *ma_page,
   page_store(log_pos, page);
   log_pos+= PAGE_STORE_SIZE;
 
+#ifdef EXTRA_DEBUG_KEY_CHANGES
+  (*log_pos++)= KEY_OP_DEBUG;
+  (*log_pos++)= KEY_OP_DEBUG_LOG_SPLIT;
+#endif
+
   if (new_length <= offset || !key_pos)
   {
     /*