List:Commits« Previous MessageNext Message »
From:Luis Soares Date:November 15 2011 1:05pm
Subject:bzr push into mysql-trunk branch (luis.soares:3611 to 3612) Bug#11760927
View as plain text  
 3612 Luis Soares	2011-11-15 [merge]
      BUG#11760927
            
      Manual merge from mysql-5.5 into latest mysql-trunk.
            
      Conflicts
      ---------
      Text conflict in sql/log_event.cc
      Text conflict in sql/rpl_rli.h
            
      Disabled warnings in test case when including master-slave.inc .

    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
 3611 Nirbhay Choubey	2011-11-15 [merge]
      Merge of fix for bug#11827359 from mysql-5.5.

    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-15 13:04:11 +0000
@@ -0,0 +1,64 @@
+#
+# Bug#11760927: 53375: RBR + NO PK => HIGH LOAD ON SLAVE (TABLE SCAN/CPU) => SLAVE FAILURE
+#
+--disable_warnings
+--source include/master-slave.inc
+--enable_warnings
+--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-11-10 06:53:27 +0000
+++ b/sql/log_event.cc	2011-11-15 13:04:11 +0000
@@ -8872,6 +8872,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();
+
     const uchar *saved_m_curr_row= m_curr_row;
     while (error == 0)
     {
@@ -10610,6 +10616,50 @@ search_key_in_table(TABLE *table, MY_BIT
   return res;
 }
 
+/* 
+  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 ((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.
@@ -10649,6 +10699,7 @@ int Rows_log_event::find_row(const Relay
   int error= 0;
   KEY *keyinfo;
   uint key;
+  bool is_table_scan= false, is_index_scan= false;
 
   /*
     rpl_row_tabledefs.test specifies that
@@ -10838,6 +10889,8 @@ INDEX_SCAN:
       }
     }
 
+    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 
@@ -10898,6 +10951,8 @@ TABLE_SCAN:
       goto err;
     }
 
+    is_table_scan= true;
+
     /* Continue until we find the right record or have made a full loop */
     do
     {
@@ -10951,10 +11006,18 @@ TABLE_SCAN:
     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-08-29 12:08:58 +0000
+++ b/sql/log_event.h	2011-11-15 13:04:11 +0000
@@ -51,6 +51,7 @@ typedef ulonglong sql_mode_t;
 typedef struct st_db_worker_hash_entry db_worker_hash_entry;
 
 #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-10-28 12:45:35 +0000
+++ b/sql/rpl_rli.cc	2011-11-15 13:04:11 +0000
@@ -1142,6 +1142,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-10-13 14:01:50 +0000
+++ b/sql/rpl_rli.h	2011-11-15 13:04:11 +0000
@@ -758,6 +758,40 @@ public:
     with several warning messages.
   */
   bool reported_unsafe_warning;
+
+  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:
   /**
     Delay slave SQL thread by this amount, compared to master (in
@@ -799,6 +833,13 @@ private:
 
   Relay_log_info(const Relay_log_info& info);
   Relay_log_info& operator=(const Relay_log_info& info);
+
+  /*
+    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;
 };
 
 bool mysql_show_relaylog_events(THD* thd);

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