List:Commits« Previous MessageNext Message »
From:Alfranio Correia Date:February 4 2009 4:11pm
Subject:bzr commit into mysql-6.0-rpl branch (alfranio.correia:2810) Bug#40337
View as plain text  
#At file:///home/acorreia/workspace.sun/repository.mysql/bzrwork/bug-40337/mysql-6.0-rpl/ based on revid:luis.soares@stripped

 2810 Alfranio Correia	2009-02-04
      BUG#40337  Fsyncing master and relay log to disk after every event is too slow
      
      The fix proposed in BUG#35542 and BUG#31665 introduces a performance issue
      when fsyncing the master.info, relay.info and relay-log.bin* after #th events.
      Although such solution has been proposed to reduce the probability of corrupted
      files due to a slave-crash, the performance penalty introduced by it has
      made the approach impractical for highly intensive workloads.
      
      In a nutshell, the option --syn-relay-log proposed in BUG#35542 and BUG#31665
      simultaneously fsyncs master.info, relay-log.info and relay-log.bin* and
      this is the main source of performance issues.
      
      This patch introduces new options that give more control to the user on
      what should be fsynced and how often:
            1) (--sync-master-info, integer) which syncs the master.info after #th event;
            2) (--sync-relay-log, integer) which syncs the relay-log.bin* after #th events.
            3) (--sync-relay-log-info, integer) which syncs the relay.info after #th
            transactions.
      
      To provide both performance and increased reliability, we recommend the following
      setup:
            1) --sync-master-info = 0 eventually the operating system will fsync it;
            2) --sync-relay-log = 0 eventually the operating system will fsync it;
            3) --sync-relay-log-info = 1 fsyncs it after every transaction;
      
      Notice, however, that the previous setup does not reduce the probability of corrupted
      master.info and relay-log.bin*. To overcome the issue, this patch also introduces
      a recovery mechanism that right after restart throws away relay-log.bin* retrieved
      from a master and updates the master.info based on the relay.info:
            4) (--relay-log-recovery, boolean) which enables a recovery mechanism that
            throws away relay-log.bin* after a crash.
      
      So, it is advisable to setup:
            4) --syn-relay-log-info = 1.
modified:
  mysql-test/suite/rpl/r/rpl_flushlog_loop.result
  sql/mysql_priv.h
  sql/mysqld.cc
  sql/rpl_mi.cc
  sql/rpl_mi.h
  sql/rpl_rli.cc
  sql/rpl_rli.h
  sql/slave.cc
  sql/sql_repl.cc

per-file messages:
  mysql-test/suite/rpl/r/rpl_flushlog_loop.result
    Fixed result as "show variables like 'relay_log%'" produces a new record:
    relay_log_recovery OFF
  sql/mysql_priv.h
    Introduces the new options: sync_relayloginfo_period, sync_masterinfo_period and relay_log_recovery.
  sql/mysqld.cc
    Introduces the new options: sync_relayloginfo_period, sync_masterinfo_period and relay_log_recovery.
  sql/rpl_mi.cc
    This patch does three distinct things:
          1) Initializes the counter that keeps track of the number of events before fsyncing.
          2) Removes an unnecessary synchronization point that was causing two fsyncs on the relay-log.bin*.
          3) Introduces the fsync for the master.info.
  sql/rpl_mi.h
    Creates a counter that keeps track of the number of events before fsyncing the master.info.
  sql/rpl_rli.cc
    This patch does two distinct things:
          1) Initializes the counter that keeps track of the number of events before fsyncing.
          2) Avoids reading the current relay-log.bin* after restarting because it may be
          corrupted.
  sql/rpl_rli.h
    Creates a counter that keeps track of the number of events before fsyncing the master.info and
    a flag that indentifies that the server is recoverying. This is important to avoid reading a
    possilbe corrupted relay-log.bin*
  sql/slave.cc
    This patch does two distinct things:
          1) Introduces a recovery mechanism that right after restart throws away relay-log.bin* retrieved
          from a master and updates the master.info based on the relay.info
          2) Introduces the fsync for the relay-log.info.
=== modified file 'mysql-test/suite/rpl/r/rpl_flushlog_loop.result'
--- a/mysql-test/suite/rpl/r/rpl_flushlog_loop.result	2009-01-08 09:49:02 +0000
+++ b/mysql-test/suite/rpl/r/rpl_flushlog_loop.result	2009-02-04 16:11:20 +0000
@@ -10,6 +10,7 @@ relay_log	MYSQLD_DATADIR/relay-log
 relay_log_index	
 relay_log_info_file	relay-log.info
 relay_log_purge	ON
+relay_log_recovery	OFF
 relay_log_space_limit	0
 stop slave;
 change master to master_host='127.0.0.1',master_user='root',

=== modified file 'sql/mysql_priv.h'
--- a/sql/mysql_priv.h	2009-01-26 16:03:39 +0000
+++ b/sql/mysql_priv.h	2009-02-04 16:11:20 +0000
@@ -1969,10 +1969,12 @@ extern ulong specialflag;
 #ifdef MYSQL_SERVER
 extern ulong current_pid;
 extern ulong expire_logs_days;
-extern uint sync_binlog_period, sync_relaylog_period;
+extern uint sync_binlog_period, sync_relaylog_period, 
+            sync_relayloginfo_period, sync_masterinfo_period;
 extern ulong opt_tc_log_size, tc_log_max_pages_used, tc_log_page_size;
 extern ulong tc_log_page_waits;
 extern my_bool relay_log_purge, opt_innodb_safe_binlog, opt_innodb;
+extern my_bool relay_log_recovery;
 extern uint test_flags,select_errors,ha_open_options;
 extern uint protocol_version, mysqld_port, dropping_tables;
 extern uint delay_key_write_options;

=== modified file 'sql/mysqld.cc'
--- a/sql/mysqld.cc	2009-01-26 16:03:39 +0000
+++ b/sql/mysqld.cc	2009-02-04 16:11:20 +0000
@@ -499,6 +499,7 @@ extern const char *opt_ndb_distribution;
 extern enum ndb_distribution opt_ndb_distribution_id;
 #endif
 my_bool opt_readonly, use_temp_pool, relay_log_purge;
+my_bool relay_log_recovery;
 my_bool opt_sync_frm, opt_allow_suspicious_udfs;
 my_bool opt_secure_auth= 0;
 char* opt_secure_file_priv= 0;
@@ -580,7 +581,8 @@ ulong max_prepared_stmt_count;
 ulong prepared_stmt_count=0;
 ulong thread_id=1L,current_pid;
 ulong slow_launch_threads = 0;
-uint sync_binlog_period= 0, sync_relaylog_period= 0;
+uint sync_binlog_period= 0, sync_relaylog_period= 0,
+     sync_relayloginfo_period= 0, sync_masterinfo_period= 0;
 ulong expire_logs_days = 0;
 ulong rpl_recovery_rank=0;
 const char *log_output_str= "FILE";
@@ -5841,6 +5843,7 @@ enum options_mysqld
   OPT_QUERY_CACHE_TYPE, OPT_QUERY_CACHE_WLOCK_INVALIDATE, OPT_RECORD_BUFFER,
   OPT_RECORD_RND_BUFFER, OPT_DIV_PRECINCREMENT, OPT_RELAY_LOG_SPACE_LIMIT,
   OPT_RELAY_LOG_PURGE,
+  OPT_RELAY_LOG_RECOVERY,
   OPT_SLAVE_NET_TIMEOUT, OPT_SLAVE_COMPRESSED_PROTOCOL, OPT_SLOW_LAUNCH_TIME,
   OPT_SLAVE_TRANS_RETRIES, OPT_READONLY, OPT_DEBUGGING,
   OPT_SORT_BUFFER, OPT_TABLE_OPEN_CACHE, OPT_TABLE_DEF_CACHE,
@@ -5918,6 +5921,8 @@ enum options_mysqld
   OPT_GENERAL_LOG_FILE,
   OPT_SLOW_QUERY_LOG_FILE,
   OPT_SYNC_RELAY_LOG,
+  OPT_SYNC_RELAY_LOG_INFO,
+  OPT_SYNC_MASTER_INFO,
   OPT_BACKUP_HISTORY_LOG_FILE,
   OPT_BACKUP_PROGRESS_LOG_FILE
 };
@@ -7176,6 +7181,13 @@ The minimum value for this variable is 4
    (uchar**) &relay_log_purge,
    (uchar**) &relay_log_purge, 0, GET_BOOL, NO_ARG,
    1, 0, 1, 0, 1, 0},
+  {"relay_log_recovery", OPT_RELAY_LOG_RECOVERY,
+   "Enables automatic relay log recovery right after the database startup, "
+   "which means that the IO Thread starts re-fetching from the master " 
+   "right after the last transaction processed.",
+   (uchar**) &relay_log_recovery,
+   (uchar**) &relay_log_recovery, 0, GET_BOOL, NO_ARG,
+   0, 0, 1, 0, 1, 0},
   {"relay_log_space_limit", OPT_RELAY_LOG_SPACE_LIMIT,
    "Maximum space to use for all relay logs.",
    (uchar**) &relay_log_space_limit,
@@ -7221,6 +7233,16 @@ The minimum value for this variable is 4
    "Use 0 (default) to disable synchronous flushing.",
    (uchar**) &sync_relaylog_period, (uchar**) &sync_relaylog_period, 0, GET_UINT,
    REQUIRED_ARG, 0, 0, (longlong) UINT_MAX, 0, 1, 0},
+  {"sync-relay-log-info", OPT_SYNC_RELAY_LOG_INFO,
+   "Synchronously flush relay log info to disk after #th transaction. "
+   "Use 0 (default) to disable synchronous flushing.",
+   (uchar**) &sync_relayloginfo_period, (uchar**) &sync_relayloginfo_period, 0, GET_UINT,
+   REQUIRED_ARG, 0, 0, (longlong) UINT_MAX, 0, 1, 0},
+  {"sync-master-info", OPT_SYNC_MASTER_INFO,
+   "Synchronously flush master info to disk after every #th event. "
+   "Use 0 (default) to disable synchronous flushing.",
+   (uchar**) &sync_masterinfo_period, (uchar**) &sync_masterinfo_period, 0, GET_UINT,
+   REQUIRED_ARG, 0, 0, (longlong) UINT_MAX, 0, 1, 0},
   {"sync-frm", OPT_SYNC_FRM, "Sync .frm to disk on create. Enabled by default.",
    (uchar**) &opt_sync_frm, (uchar**) &opt_sync_frm, 0, GET_BOOL, NO_ARG, 1, 0,
    0, 0, 0, 0},

=== modified file 'sql/rpl_mi.cc'
--- a/sql/rpl_mi.cc	2008-12-24 10:48:24 +0000
+++ b/sql/rpl_mi.cc	2009-02-04 16:11:20 +0000
@@ -35,7 +35,8 @@ Master_info::Master_info()
    ssl(0), ssl_verify_server_cert(0), fd(-1),  io_thd(0), port(MYSQL_PORT),
    connect_retry(DEFAULT_CONNECT_RETRY), heartbeat_period(0),
    received_heartbeats(0), inited(0), master_id(0),
-   abort_slave(0), slave_running(0), slave_run_id(0)
+   abort_slave(0), slave_running(0), slave_run_id(0),
+   sync_counter(0)
 {
   host[0] = 0; user[0] = 0; password[0] = 0;
   ssl_ca[0]= 0; ssl_capath[0]= 0; ssl_cert[0]= 0;
@@ -432,11 +433,6 @@ int flush_master_info(Master_info* mi, b
     IO_CACHE *log_file= mi->rli.relay_log.get_log_file();
     if (flush_io_cache(log_file))
       DBUG_RETURN(2);
-
-    /* Sync to disk if --sync-relay-log is set */
-    if (sync_relaylog_period &&
-        my_sync(log_file->file, MY_WME))
-      DBUG_RETURN(2);
   }
 
   /*
@@ -492,8 +488,12 @@ int flush_master_info(Master_info* mi, b
               ignore_server_ids_buf);
   my_free(ignore_server_ids_buf, MYF(0));
   err= flush_io_cache(file);
-  if (sync_relaylog_period && !err)
+  if (sync_masterinfo_period && !err && 
+      ++(mi->sync_counter) >= sync_masterinfo_period)
+  {
     err= my_sync(mi->fd, MYF(MY_WME));
+    mi->sync_counter= 0;
+  }
   DBUG_RETURN(-err);
 }
 

=== modified file 'sql/rpl_mi.h'
--- a/sql/rpl_mi.h	2008-07-17 19:11:37 +0000
+++ b/sql/rpl_mi.h	2009-02-04 16:11:20 +0000
@@ -106,6 +106,13 @@ class Master_info : public Slave_reporti
 
   */
   long clock_diff_with_master;
+
+  /*
+   * Keeps track of the number of events before fsyncing.
+   * The option --sync-master-info determines how many
+   * events should happen before fsyncing.
+   */
+  uint sync_counter;
 };
 
 void init_master_log_pos(Master_info* mi);

=== modified file 'sql/rpl_rli.cc'
--- a/sql/rpl_rli.cc	2008-12-24 10:48:24 +0000
+++ b/sql/rpl_rli.cc	2009-02-04 16:11:20 +0000
@@ -33,7 +33,8 @@ int init_strvar_from_file(char *var, int
 Relay_log_info::Relay_log_info()
   :Slave_reporting_capability("SQL"),
    no_storage(FALSE), replicate_same_server_id(::replicate_same_server_id),
-   info_fd(-1), cur_log_fd(-1), relay_log(&sync_relaylog_period),
+   info_fd(-1), cur_log_fd(-1), 
+   relay_log(&sync_relaylog_period), sync_counter(0),
    save_temporary_tables(0),
    cur_log_old_open_count(0), group_relay_log_pos(0), event_relay_log_pos(0),
 #if HAVE_purify
@@ -248,7 +249,8 @@ Failed to open the existing relay log in
     rli->group_relay_log_pos= rli->event_relay_log_pos= relay_log_pos;
     rli->group_master_log_pos= master_log_pos;
 
-    if (init_relay_log_pos(rli,
+    if (!rli->is_relay_log_recovery &&
+        init_relay_log_pos(rli,
                            rli->group_relay_log_name,
                            rli->group_relay_log_pos,
                            0 /* no data lock*/,
@@ -269,7 +271,8 @@ Failed to open the existing relay log in
                         llstr(my_b_tell(rli->cur_log),llbuf1),
                         llstr(rli->event_relay_log_pos,llbuf2)));
     DBUG_ASSERT(rli->event_relay_log_pos >= BIN_LOG_HEADER_SIZE);
-    DBUG_ASSERT(my_b_tell(rli->cur_log) == rli->event_relay_log_pos);
+    DBUG_ASSERT(rli->is_relay_log_recovery || 
+                (my_b_tell(rli->cur_log) == rli->event_relay_log_pos));
   }
 #endif
 

=== modified file 'sql/rpl_rli.h'
--- a/sql/rpl_rli.h	2008-08-18 05:43:50 +0000
+++ b/sql/rpl_rli.h	2009-02-04 16:11:20 +0000
@@ -96,6 +96,19 @@ public:
   LOG_INFO linfo;
   IO_CACHE cache_buf,*cur_log;
 
+  /*
+   * Keeps track of the number of transactions that commits
+   * before fsyncing. The option --sync-relay-log-info determines 
+   * how many transactions should commit before fsyncing.
+   */ 
+  uint sync_counter;
+
+  /*
+   * Identifies when the recovery process is going on.
+   * See sql/slave.cc:init_recovery for further details.
+   */ 
+  bool is_relay_log_recovery;
+
   /* The following variables are safe to read any time */
 
   /* IO_CACHE of the info file - set only during init or end */

=== modified file 'sql/slave.cc'
--- a/sql/slave.cc	2009-01-26 16:03:39 +0000
+++ b/sql/slave.cc	2009-02-04 16:11:20 +0000
@@ -132,6 +132,7 @@ static bool wait_for_relay_log_space(Rel
 static inline bool io_slave_killed(THD* thd,Master_info* mi);
 static inline bool sql_slave_killed(THD* thd,Relay_log_info* rli);
 static int init_slave_thread(THD* thd, SLAVE_THD_TYPE thd_type);
+static int init_recovery(Master_info* mi);
 static int safe_connect(THD* thd, MYSQL* mysql, Master_info* mi);
 static int safe_reconnect(THD* thd, MYSQL* mysql, Master_info* mi,
                           bool suppress_warnings);
@@ -254,6 +255,10 @@ int init_slave()
     goto err;
   }
 
+  active_mi->rli.is_relay_log_recovery= relay_log_recovery;
+  if (active_mi->rli.is_relay_log_recovery && init_recovery(active_mi))
+    goto err;
+
   /* If server id is not set, start_slave_thread() will say it */
 
   if (active_mi->host[0] && !opt_skip_slave_start)
@@ -269,15 +274,86 @@ int init_slave()
       goto err;
     }
   }
+  active_mi->rli.is_relay_log_recovery= 0;
   pthread_mutex_unlock(&LOCK_active_mi);
   DBUG_RETURN(0);
 
 err:
+  active_mi->rli.is_relay_log_recovery= 0;
   pthread_mutex_unlock(&LOCK_active_mi);
   DBUG_RETURN(1);
 }
 
-
+/*
+ * Updates the master info based on the information stored in the
+ * relay info and ignores relay logs previously retrieved by the IO 
+ * thread, which thus starts fetching again based on to the  
+ * group_master_log_pos and group_master_log_name. Eventually, the old
+ * relay logs will be purged by the normal purge mechanism.
+ * 
+ * In the feature, we can improve this routine in order to avoid throwing
+ * away logs that are safely stored in the disk.
+ * 
+ * There is no need for a mutex as the caller (i.e. init_slave) already 
+ * has one acquired.
+ * 
+ * Specifically, the following structures are updated:
+ * 
+ * 1 - mi->master_log_pos  <-- rli->group_master_log_pos
+ * 2 - mi->master_log_name <-- rli->group_master_log_name
+ * 3 - It moves the relay log to the new relay log file, by
+ *     rli->group_relay_log_pos  <-- BIN_LOG_HEADER_SIZE;
+ *     rli->event_relay_log_pos  <-- BIN_LOG_HEADER_SIZE;
+ *     rli->group_relay_log_name <-- rli->relay_log.get_log_fname();
+ *     rli->event_relay_log_name <-- rli->relay_log.get_log_fname();
+ * 
+ *  If there is an error, it returns (1), otherwise returns (0).
+ */
+static int init_recovery(Master_info* mi)
+{
+  const char *errmsg= 0;
+  DBUG_ENTER("init_recovery");
+ 
+  Relay_log_info *rli= &mi->rli;
+  if (rli->group_master_log_name[0])
+  {
+    mi->master_log_pos= max(BIN_LOG_HEADER_SIZE,
+                             rli->group_master_log_pos);
+    strmake(mi->master_log_name, rli->group_master_log_name,
+            sizeof(mi->master_log_name)-1);
+ 
+    sql_print_warning("Recovery from master pos %ld and file %s.",
+                      (ulong) mi->master_log_pos, mi->master_log_name);
+ 
+    strmake(rli->group_relay_log_name, rli->relay_log.get_log_fname(),
+            sizeof(rli->group_relay_log_name)-1);
+    strmake(rli->event_relay_log_name, rli->relay_log.get_log_fname(),
+            sizeof(mi->rli.event_relay_log_name)-1);
+ 
+    rli->group_relay_log_pos= rli->event_relay_log_pos= BIN_LOG_HEADER_SIZE;
+ 
+    if (init_relay_log_pos(rli,
+                           rli->group_relay_log_name,
+                           rli->group_relay_log_pos,
+                           0 /*no data lock*/,
+                            &errmsg, 0))
+      DBUG_RETURN(1);
+ 
+    if (flush_master_info(mi, 0))
+    {
+      sql_print_error("Failed to flush master info file");
+      DBUG_RETURN(1);
+    }
+    if (flush_relay_log_info(rli))
+    {
+       sql_print_error("Failed to flush relay info file");
+       DBUG_RETURN(1);
+    }
+  }
+ 
+  DBUG_RETURN(0);
+}
+ 
 /**
   Convert slave skip errors bitmap into a printable string.
 */
@@ -3826,7 +3902,14 @@ bool flush_relay_log_info(Relay_log_info
     error=1;
   if (flush_io_cache(file))
     error=1;
-
+  if (sync_relayloginfo_period &&
+      !error &&
+      ++(rli->sync_counter) >= sync_relayloginfo_period)
+  {
+    if (my_sync(rli->info_fd, MYF(MY_WME)))
+      error=1;
+    rli->sync_counter= 0;
+  }
   /* Flushing the relay log is done by the slave I/O thread */
   DBUG_RETURN(error);
 }

=== modified file 'sql/sql_repl.cc'
--- a/sql/sql_repl.cc	2009-01-26 16:32:29 +0000
+++ b/sql/sql_repl.cc	2009-02-04 16:11:20 +0000
@@ -2036,6 +2036,16 @@ static sys_var_const    sys_relay_log_in
                                       (uchar*) &relay_log_info_file);
 static sys_var_bool_ptr	sys_relay_log_purge(&vars, "relay_log_purge",
 					    &relay_log_purge);
+static sys_var_bool_ptr sys_relay_log_recovery(&vars, "relay_log_recovery",
+                                               &relay_log_recovery);
+static sys_var_int_ptr sys_sync_binlog_period(&vars, "sync_binlog",
+                                              &sync_binlog_period);
+static sys_var_int_ptr sys_sync_relaylog_period(&vars, "sync_relay_log",
+                                                &sync_relaylog_period);
+static sys_var_int_ptr sys_sync_relayloginfo_period(&vars, "sync_relay_log_info",
+                                                    &sync_relayloginfo_period);
+static sys_var_int_ptr sys_sync_masterinfo_period(&vars, "sync_master_info",
+                                                  &sync_masterinfo_period);
 static sys_var_const    sys_relay_log_space_limit(&vars,
                                                   "relay_log_space_limit",
                                                   OPT_GLOBAL, SHOW_LONGLONG,
@@ -2052,8 +2062,6 @@ static sys_var_const    sys_slave_skip_e
                                               (uchar*) slave_skip_error_names);
 static sys_var_long_ptr	sys_slave_trans_retries(&vars, "slave_transaction_retries",
 						&slave_trans_retries);
-static sys_var_int_ptr sys_sync_binlog_period(&vars, "sync_binlog", &sync_binlog_period);
-static sys_var_int_ptr sys_sync_relaylog_period(&vars, "sync_relay_log", &sync_relaylog_period);
 static sys_var_slave_skip_counter sys_slave_skip_counter(&vars, "sql_slave_skip_counter");
 
 

Thread
bzr commit into mysql-6.0-rpl branch (alfranio.correia:2810) Bug#40337Alfranio Correia4 Feb
  • Re: bzr commit into mysql-6.0-rpl branch (alfranio.correia:2810)Bug#40337He Zhenxing5 Feb
  • Re: bzr commit into mysql-6.0-rpl branch (alfranio.correia:2810)Bug#40337Mats Kindahl9 Feb
    • Re: bzr commit into mysql-6.0-rpl branch (alfranio.correia:2810)Bug#40337Alfranio Correia10 Feb
      • Re: bzr commit into mysql-6.0-rpl branch (alfranio.correia:2810)Bug#40337Alfranio Correia10 Feb