List:Commits« Previous MessageNext Message »
From:Luis Soares Date:November 15 2011 1:05pm
Subject:bzr push into mysql-5.5 branch (luis.soares:3608 to 3609) Bug#11760927
View as plain text  
 3609 Luis Soares	2011-11-15 [merge]
      BUG#11760927
      
      Automerged approved bzr bundle in latest mysql-5.5.

    added:
      mysql-test/suite/rpl/r/rpl_row_find_row_debug.result
      mysql-test/suite/rpl/t/rpl_row_find_row_debug.test
    modified:
      sql/log_event.cc
      sql/log_event.h
      sql/rpl_rli.cc
      sql/rpl_rli.h
 3608 Nirbhay Choubey	2011-11-15
      Bug#11827359 60223: MYSQL_UPGRADE PROBLEM WITH
                          OPTION SKIP-WRITE-BINLOG
      
      System tables were not getting upgraded when
      mysql_upgrade was run with --skip-write-binlog
      option. (Same for --write-binlog.) Also, with
      this option, mysql_upgrade_info file was not
      getting created after the upgrade.
      
      mysql_upgrade makes use of mysql client tool in
      order to run upgrade scripts, while doing so it
      passes some of the command line options (used to
      start mysql_upgrade) directly to mysql client.
      The reason behind this bug being, some options
      like skip-write-binlog and upgrade-system-tables
      were being passed to mysql tool along with other
      options, and hence mysql execution failed due
      presence of these invalid options.
      
      Fixed this issue by filtering out the above mentioned
      options from the list of options that will be passed to
      mysql and mysqlcheck tools. However, since --write-binlog
      is supported by mysqlcheck, this option would be used
      explicitly while running mysqlcheck. (not part of patch,
      already there)
      
      Checking the contents of general log after the upgrade
      is not doable via an mtr test. So performed manual test.
      Added a test to verify the creation of mysql_upgrade_info.
     @ client/mysql_upgrade.c
        Bug#11827359 60223: MYSQL_UPGRADE PROBLEM WITH
                            OPTION SKIP-WRITE-BINLOG
        
        With this patch, --upgrade-system-tables and
        --write-binlog options will not be added to the
        list of options, used to start mysql and mysqlcheck
        tools.
     @ mysql-test/r/mysql_upgrade.result
        Added a testcase for Bug#11827359.
     @ mysql-test/t/mysql_upgrade.test
        Added a testcase for Bug#11827359.

    modified:
      client/mysql_upgrade.c
      mysql-test/r/mysql_upgrade.result
      mysql-test/t/mysql_upgrade.test
=== added file 'mysql-test/suite/rpl/r/rpl_row_find_row_debug.result'
--- a/mysql-test/suite/rpl/r/rpl_row_find_row_debug.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/r/rpl_row_find_row_debug.result	2011-11-11 17:26:56 +0000
@@ -0,0 +1,18 @@
+include/master-slave.inc
+[connection master]
+include/stop_slave.inc
+SET GLOBAL log_warnings = 2;
+SET GLOBAL debug="d,inject_long_find_row_note";
+include/start_slave.inc
+CREATE TABLE t1 (c1 INT);
+INSERT INTO t1 VALUES (1), (2);
+UPDATE t1 SET c1= 1000 WHERE c1=2;
+DELETE FROM t1;
+DROP TABLE t1;
+# Check if any note related to long DELETE_ROWS and UPDATE_ROWS appears in the error log
+Occurrences: update=1, delete=1
+include/stop_slave.inc
+SET GLOBAL debug = '';
+SET GLOBAL log_warnings = 1;
+include/start_slave.inc
+include/rpl_end.inc

=== added file 'mysql-test/suite/rpl/t/rpl_row_find_row_debug.test'
--- a/mysql-test/suite/rpl/t/rpl_row_find_row_debug.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_row_find_row_debug.test	2011-11-11 17:26:56 +0000
@@ -0,0 +1,62 @@
+#
+# Bug#11760927: 53375: RBR + NO PK => HIGH LOAD ON SLAVE (TABLE SCAN/CPU) => SLAVE FAILURE
+#
+--source include/master-slave.inc
+--source include/have_binlog_format_row.inc
+--source include/have_debug.inc
+
+# SETUP
+# - setup log_warnings and debug 
+--connection slave
+--source include/stop_slave.inc
+--let $debug_save= `SELECT @@GLOBAL.debug`
+--let $log_warnings_save= `SELECT @@GLOBAL.log_warnings`
+
+SET GLOBAL log_warnings = 2;
+
+let $log_error_= `SELECT @@GLOBAL.log_error`;
+if(!$log_error_)
+{
+    # MySQL Server on windows is started with --console and thus
+    # does not know the location of its .err log, use default location
+    let $log_error_ = $MYSQLTEST_VARDIR/log/mysqld.2.err;
+}
+
+# Assign env variable LOG_ERROR
+let LOG_ERROR=$log_error_;
+
+# force printing the notes to the error log
+SET GLOBAL debug="d,inject_long_find_row_note";
+--source include/start_slave.inc
+
+# test
+--connection master
+CREATE TABLE t1 (c1 INT);
+--sync_slave_with_master
+--connection master
+
+INSERT INTO t1 VALUES (1), (2);
+UPDATE t1 SET c1= 1000 WHERE c1=2;
+DELETE FROM t1;
+DROP TABLE t1;
+--sync_slave_with_master
+
+--echo # Check if any note related to long DELETE_ROWS and UPDATE_ROWS appears in the error log
+perl;
+  use strict;
+  my $log_error= $ENV{'LOG_ERROR'} or die "LOG_ERROR not set";
+  open(FILE, "$log_error") or die("Unable to open $log_error: $!\n");
+  my $upd_count = () = grep(/The slave is applying a ROW event on behalf of an UPDATE statement on table t1 and is currently taking a considerable amount/g,<FILE>);
+  seek(FILE, 0, 0) or die "Can't seek to beginning of file: $!";
+  my $del_count = () = grep(/The slave is applying a ROW event on behalf of a DELETE statement on table t1 and is currently taking a considerable amount/g,<FILE>);
+  print "Occurrences: update=$upd_count, delete=$del_count\n";
+  close(FILE);
+EOF
+
+# cleanup
+--source include/stop_slave.inc
+--eval SET GLOBAL debug = '$debug_save'
+--eval SET GLOBAL log_warnings = $log_warnings_save
+--source include/start_slave.inc
+
+--source include/rpl_end.inc

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2011-07-15 11:43:38 +0000
+++ b/sql/log_event.cc	2011-11-11 17:26:56 +0000
@@ -7761,6 +7761,12 @@ int Rows_log_event::do_apply_event(Relay
 
     // row processing loop
 
+    /* 
+      set the initial time of this ROWS statement if it was not done
+      before in some other ROWS event. 
+     */
+    const_cast<Relay_log_info*>(rli)->set_row_stmt_start_timestamp();
+
     while (error == 0 && m_curr_row < m_rows_end)
     {
       /* in_use can have been set to NULL in close_tables_for_reopen */
@@ -9252,6 +9258,51 @@ record_compare_exit:
   return result;
 }
 
+/* 
+  Check if we are already spending too much time on this statement.
+  if we are, warn user that it might be because table does not have
+  a PK, but only if the warning was not printed before for this STMT.
+
+  @param type          The event type code.
+  @param table_name    The name of the table that the slave is 
+                       operating.
+  @param is_index_scan States whether the slave is doing an index scan 
+                       or not.
+  @param rli           The relay metadata info.
+*/
+static inline 
+void issue_long_find_row_warning(Log_event_type type, 
+                                 const char *table_name,
+                                 bool is_index_scan,
+                                 const Relay_log_info *rli)
+{
+  if ((global_system_variables.log_warnings > 1 && 
+      !const_cast<Relay_log_info*>(rli)->is_long_find_row_note_printed()))
+  {
+    time_t now= my_time(0);
+    time_t stmt_ts= const_cast<Relay_log_info*>(rli)->get_row_stmt_start_timestamp();
+    
+    DBUG_EXECUTE_IF("inject_long_find_row_note", 
+                    stmt_ts-=(LONG_FIND_ROW_THRESHOLD*2););
+
+    time_t delta= (now - stmt_ts);
+
+    if (delta > LONG_FIND_ROW_THRESHOLD)
+    {
+      const_cast<Relay_log_info*>(rli)->set_long_find_row_note_printed();
+      const char* evt_type= type == DELETE_ROWS_EVENT ? " DELETE" : "n UPDATE";
+      const char* scan_type= is_index_scan ? "scanning an index" : "scanning the table";
+
+      sql_print_information("The slave is applying a ROW event on behalf of a%s statement "
+                            "on table %s and is currently taking a considerable amount "
+                            "of time (%lu seconds). This is due to the fact that it is %s "
+                            "while looking up records to be processed. Consider adding a "
+                            "primary key (or unique key) to the table to improve "
+                            "performance.", evt_type, table_name, delta, scan_type);
+    }
+  }
+}
+
 /**
   Locate the current row in event's table.
 
@@ -9287,6 +9338,7 @@ int Rows_log_event::find_row(const Relay
 
   TABLE *table= m_table;
   int error= 0;
+  bool is_table_scan= false, is_index_scan= false;
 
   /*
     rpl_row_tabledefs.test specifies that
@@ -9452,6 +9504,8 @@ int Rows_log_event::find_row(const Relay
       }
     }
 
+    is_index_scan=true;
+
     /*
       In case key is not unique, we still have to iterate over records found
       and find the one which is identical to the row given. A copy of the 
@@ -9508,6 +9562,8 @@ int Rows_log_event::find_row(const Relay
       goto err;
     }
 
+    is_table_scan= true;
+
     /* Continue until we find the right record or have made a full loop */
     do
     {
@@ -9561,10 +9617,18 @@ int Rows_log_event::find_row(const Relay
     goto err;
   }
 ok:
+  if (is_table_scan || is_index_scan)
+    issue_long_find_row_warning(get_type_code(), m_table->alias, 
+                                is_index_scan, rli);
+
   table->default_column_bitmaps();
   DBUG_RETURN(0);
 
 err:
+  if (is_table_scan || is_index_scan)
+    issue_long_find_row_warning(get_type_code(), m_table->alias, 
+                                is_index_scan, rli);
+
   table->default_column_bitmaps();
   DBUG_RETURN(error);
 }

=== modified file 'sql/log_event.h'
--- a/sql/log_event.h	2011-06-30 15:46:53 +0000
+++ b/sql/log_event.h	2011-11-11 17:26:56 +0000
@@ -53,6 +53,7 @@
 class String;
 
 #define PREFIX_SQL_LOAD "SQL_LOAD-"
+#define LONG_FIND_ROW_THRESHOLD 60 /* seconds */
 
 /**
    Either assert or return an error.

=== modified file 'sql/rpl_rli.cc'
--- a/sql/rpl_rli.cc	2011-06-30 15:46:53 +0000
+++ b/sql/rpl_rli.cc	2011-11-11 17:26:56 +0000
@@ -1245,6 +1245,15 @@ void Relay_log_info::cleanup_context(THD
   */
   thd->variables.option_bits&= ~OPTION_NO_FOREIGN_KEY_CHECKS;
   thd->variables.option_bits&= ~OPTION_RELAXED_UNIQUE_CHECKS;
+
+  /*
+    Reset state related to long_find_row notes in the error log:
+    - timestamp
+    - flag that decides whether the slave prints or not
+  */
+  reset_row_stmt_start_timestamp();
+  unset_long_find_row_note_printed();
+
   DBUG_VOID_RETURN;
 }
 

=== modified file 'sql/rpl_rli.h'
--- a/sql/rpl_rli.h	2011-08-29 07:40:06 +0000
+++ b/sql/rpl_rli.h	2011-11-11 17:26:56 +0000
@@ -452,8 +452,49 @@ public:
       (m_flags & (1UL << IN_STMT));
   }
 
+  time_t get_row_stmt_start_timestamp()
+  {
+    return row_stmt_start_timestamp;
+  }
+
+  time_t set_row_stmt_start_timestamp()
+  {
+    if (row_stmt_start_timestamp == 0)
+      row_stmt_start_timestamp= my_time(0);
+
+    return row_stmt_start_timestamp;
+  }
+
+  void reset_row_stmt_start_timestamp()
+  {
+    row_stmt_start_timestamp= 0;
+  }
+
+  void set_long_find_row_note_printed()
+  {
+    long_find_row_note_printed= true;
+  }
+
+  void unset_long_find_row_note_printed()
+  {
+    long_find_row_note_printed= false;
+  }
+
+  bool is_long_find_row_note_printed()
+  {
+    return long_find_row_note_printed;
+  }
+
 private:
+
   uint32 m_flags;
+
+  /*
+    Runtime state for printing a note when slave is taking
+    too long while processing a row event.
+   */
+  time_t row_stmt_start_timestamp;
+  bool long_find_row_note_printed;
 };
 
 

No bundle (reason: useless for push emails).
Thread
bzr push into mysql-5.5 branch (luis.soares:3608 to 3609) Bug#11760927Luis Soares16 Nov