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()

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 */

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);
 }
 

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;

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
   {

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;

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 @@ uint _ma_apply_redo_index_free_page(MARIA_HA *info,
    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;

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,

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
 };
 
 

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,

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)
   {
     /*