[Commits] bzr commit into MariaDB 5.1, with Maria 1.5:maria branch (monty:2896)

9 Aug 2010

#At lp:maria based on revid:monty@askmonty.org-20100807160859-z3lau71kddwzaa2p

 2896 Michael Widenius	2010-08-09
      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
      modified:
        include/my_sys.h
        mysql-test/mysql-test-run.pl
        mysys/my_static.c
        mysys/my_sync.c
        sql/mysqld.cc
        storage/maria/ma_key_recover.c
        storage/maria/ma_key_recover.h
        storage/maria/ma_loghandler.h
        storage/maria/ma_rt_index.c
        storage/maria/ma_write.c

per-file messages:
  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()
=== modified file 'include/my_sys.h'

--- a/include/my_sys.h	2010-08-02 09:01:24 +0000
+++ b/include/my_sys.h	2010-08-09 17:05:42 +0000
@@ -266,6 +266,7 @@ extern size_t sf_malloc_cur_memory, sf_m
 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 */

=== modified file 'mysql-test/mysql-test-run.pl'
--- a/mysql-test/mysql-test-run.pl	2010-08-07 14:42:30 +0000
+++ b/mysql-test/mysql-test-run.pl	2010-08-09 17:05:42 +0000
@@ -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);
 }
 

=== modified file 'mysys/my_static.c'
--- a/mysys/my_static.c	2009-12-03 11:19:05 +0000
+++ b/mysys/my_static.c	2010-08-09 17:05:42 +0000
@@ -119,6 +119,7 @@ ulonglong query_performance_frequency, q
 
 	/* 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;

=== modified file 'mysys/my_sync.c'
--- a/mysys/my_sync.c	2010-03-09 19:22:24 +0000
+++ b/mysys/my_sync.c	2010-08-09 17:05:42 +0000
@@ -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
   {

=== modified file 'sql/mysqld.cc'
--- a/sql/mysqld.cc	2010-08-02 09:01:24 +0000
+++ b/sql/mysqld.cc	2010-08-09 17:05:42 +0000
@@ -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 **
     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;

=== modified file 'storage/maria/ma_key_recover.c'
--- a/storage/maria/ma_key_recover.c	2009-02-19 09:01:25 +0000
+++ b/storage/maria/ma_key_recover.c	2010-08-09 17:05:42 +0000
@@ -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;

=== modified file 'storage/maria/ma_key_recover.h'
--- a/storage/maria/ma_key_recover.h	2010-03-09 19:22:24 +0000
+++ b/storage/maria/ma_key_recover.h	2010-08-09 17:05:42 +0000
@@ -72,7 +72,8 @@ my_bool _ma_log_add(MARIA_PAGE *page, ui
                     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,

=== modified file 'storage/maria/ma_loghandler.h'
--- a/storage/maria/ma_loghandler.h	2009-01-15 22:25:53 +0000
+++ b/storage/maria/ma_loghandler.h	2010-08-09 17:05:42 +0000
@@ -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
 };
 
 

=== modified file 'storage/maria/ma_rt_index.c'
--- a/storage/maria/ma_rt_index.c	2009-09-15 11:22:39 +0000
+++ b/storage/maria/ma_rt_index.c	2010-08-09 17:05:42 +0000
@@ -625,7 +625,8 @@ static int maria_rtree_insert_req(MARIA_
       {
         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_
         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_
                                           _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,

=== modified file 'storage/maria/ma_write.c'
--- a/storage/maria/ma_write.c	2010-08-05 15:56:31 +0000
+++ b/storage/maria/ma_write.c	2010-08-09 17:05:42 +0000
@@ -1416,7 +1416,8 @@ static int _ma_balance_page(MARIA_HA *in
     /* 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 *in
 
     /* 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,
    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_pa
   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_pa
     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
                              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
   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)
   {
     /*

    