MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:Luis Soares Date:February 5 2010 5:48pm
Subject:bzr commit into mysql-5.1-bugteam branch (luis.soares:3368) Bug#50620
View as plain text  
#At file:///home/lsoares/Workspace/bzr/work/bugfixing/48632/mysql-5.1-bugteam-push/ based on revid:luis.soares@stripped

 3368 Luis Soares	2010-02-05
      BUG#50620: Adding an index to a table prevents slave from logging
      into slow log
            
      While processing a statement, down the mysql_parse execution
      stack, the thd->enable_slow_log can be assigned to
      opt_log_slow_admin_statements, depending whether one is executing
      administrative statements, such as ALTER TABLE, OPTIMIZE,
      ANALYZE, etc, or not. This can have an impact on slow logging for
      statements that are executed after an administrative statement
      execution is completed.
            
      When executing statements directly from the user this is fine
      because, the thd->enable_slow_log is reset right at the beginning
      of the dispatch_command function, ie, everytime a new statement
      is set is set to execute.
            
      On the other hand, for slave SQL thread (sql_thd) the story is a
      bit different. When in SBR the sql_thd applies statements by
      calling mysql_parse. Right after, it calls log_slow_statement
      function to log them if they take too long. Calling mysql_parse
      directly is fine, but also means that dispatch_command function
      is bypassed. As a consequence, thd->enable_slow_log does not get
      a chance to be reset before the next statement to be executed by
      the sql_thd. If the statement just executed by the sql_thd was an
      administrative statement and logging of admin statements was
      disabled, this means that sql_thd->enable_slow_log will be set to
      0 (disabled) from that moment on. End result: sql_thd stops
      logging slow statements.
            
      We fix this by resetting the value of sql_thd->enable_slow_log to
      the value of opt_log_slow_slave_statements right after
      log_slow_stement is called by the sql_thd.

    modified:
      mysql-test/suite/rpl/r/rpl_slow_query_log.result
      mysql-test/suite/rpl/t/rpl_slow_query_log.test
      sql/log_event.cc
=== modified file 'mysql-test/suite/rpl/r/rpl_slow_query_log.result'
--- a/mysql-test/suite/rpl/r/rpl_slow_query_log.result	2010-02-05 17:01:09 +0000
+++ b/mysql-test/suite/rpl/r/rpl_slow_query_log.result	2010-02-05 17:48:01 +0000
@@ -46,3 +46,46 @@ include/stop_slave.inc
 SET GLOBAL long_query_time= @old_long_query_time;
 SET GLOBAL log_output= @old_log_output;
 include/start_slave.inc
+stop slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+reset master;
+reset slave;
+drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
+start slave;
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET GLOBAL long_query_time= 2;
+SET @old_long_query_time= @@long_query_time;
+SET SESSION long_query_time= 2;
+TRUNCATE mysql.slow_log;
+include/stop_slave.inc
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET @old_long_query_time= @@long_query_time;
+SET GLOBAL long_query_time= 2;
+TRUNCATE mysql.slow_log;
+include/start_slave.inc
+CREATE TABLE t1 (a int, b int);
+********************************************************************
+**** INSERT one row that exceeds long_query_time
+**** Outcome: query ends up in both master and slave slow log
+********************************************************************
+INSERT INTO t1 values(1, sleep(3));
+### Assertion is good. Both Master and Slave exhibit the 
+### same number of queries in slow log: 1
+TRUNCATE mysql.slow_log;
+TRUNCATE mysql.slow_log;
+********************************************************************
+**** Now do inserts again, but first add an index to the table.
+**** Outcome: Note that the slave contains the same one entry (as 
+****          the master does)  whereas before the patch it did not.
+********************************************************************
+ALTER TABLE t1 ADD INDEX id1(a);
+INSERT INTO t1 values(1, sleep(3));
+### Assertion is good. Both Master and Slave exhibit the 
+### same number of queries in slow log: 1
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;
+DROP TABLE t1;
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;

=== modified file 'mysql-test/suite/rpl/t/rpl_slow_query_log.test'
--- a/mysql-test/suite/rpl/t/rpl_slow_query_log.test	2010-02-05 17:01:09 +0000
+++ b/mysql-test/suite/rpl/t/rpl_slow_query_log.test	2010-02-05 17:48:01 +0000
@@ -175,7 +175,6 @@ TRUNCATE mysql.slow_log;
 # clean up: drop tables, reset the variables back to the previous value,
 #           disconnect extra connections
 connection extra2;
-
 SET GLOBAL slow_query_log= @old_slow_query_log;
 
 connection master;
@@ -191,3 +190,119 @@ source include/start_slave.inc;
 
 disconnect extra;
 disconnect extra2;
+
+#
+# BUG#50620: Adding an index to a table prevents slave from logging into slow log
+#
+
+-- source include/master-slave-reset.inc
+
+-- connection master
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET GLOBAL long_query_time= 2;
+SET @old_long_query_time= @@long_query_time;
+SET SESSION long_query_time= 2;
+TRUNCATE mysql.slow_log;
+-- connection slave
+
+-- source include/stop_slave.inc
+SET @old_log_output= @@log_output;
+SET GLOBAL log_output= 'TABLE';
+SET @old_long_query_time= @@long_query_time;
+SET GLOBAL long_query_time= 2;
+TRUNCATE mysql.slow_log;
+-- source include/start_slave.inc
+
+let $slow_query= INSERT INTO t1 values(1, sleep(3));
+
+-- connection master
+CREATE TABLE t1 (a int, b int); 
+
+-- echo ********************************************************************
+-- echo **** INSERT one row that exceeds long_query_time
+-- echo **** Outcome: query ends up in both master and slave slow log
+-- echo ********************************************************************
+
+-- disable_warnings
+-- eval $slow_query
+-- enable_warnings
+
+let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+-- sync_slave_with_master
+let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if (`SELECT $master_slow_query != $slave_slow_query`)
+{
+  -- connection master
+  -- echo ***********************************************
+  -- echo ** DUMPING MASTER SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- connection slave
+  -- echo ***********************************************
+  -- echo ** DUMPING SLAVE SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!"
+}
+
+if (`SELECT $master_slow_query = $slave_slow_query`)
+{
+  -- echo ### Assertion is good. Both Master and Slave exhibit the 
+  -- echo ### same number of queries in slow log: $master_slow_query
+}
+
+TRUNCATE mysql.slow_log;
+-- connection master
+TRUNCATE mysql.slow_log;
+
+-- echo ********************************************************************
+-- echo **** Now do inserts again, but first add an index to the table.
+-- echo **** Outcome: Note that the slave contains the same one entry (as 
+-- echo ****          the master does)  whereas before the patch it did not.
+-- echo ********************************************************************
+
+ALTER TABLE t1 ADD INDEX id1(a);
+
+-- disable_warnings
+-- eval $slow_query
+-- enable_warnings
+
+let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+-- sync_slave_with_master
+let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if (`SELECT $master_slow_query != $slave_slow_query`)
+{
+  -- connection master
+  -- echo ***********************************************
+  -- echo ** DUMPING MASTER SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- connection slave
+  -- echo ***********************************************
+  -- echo ** DUMPING SLAVE SLOW LOG CONTENTS 
+  -- echo ***********************************************
+  SELECT * FROM mysql.slow_log;
+
+  -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!"
+}
+
+if (`SELECT $master_slow_query = $slave_slow_query`)
+{
+  -- echo ### Assertion is good. Both Master and Slave exhibit the 
+  -- echo ### same number of queries in slow log: $master_slow_query
+}
+
+-- connection master
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;
+DROP TABLE t1;
+
+-- sync_slave_with_master
+SET @@global.log_output= @old_log_output;
+SET @@global.long_query_time= @old_long_query_time;

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2010-01-28 21:51:40 +0000
+++ b/sql/log_event.cc	2010-02-05 17:48:01 +0000
@@ -3170,6 +3170,18 @@ int Query_log_event::do_apply_event(Rela
       const char* found_semicolon= NULL;
       mysql_parse(thd, thd->query(), thd->query_length(), &found_semicolon);
       log_slow_statement(thd);
+
+      /*
+        Resetting the enable_slow_log thd variable.
+
+        We need to reset it back to the opt_log_slow_slave_statements
+        value after the statement execution (and slow logging
+        is done). It might have changed if the statement was an
+        admin statement (in which case, down in mysql_parse execution
+        thd->enable_slow_log is set to the value of
+        opt_log_slow_admin_statements).
+      */
+      thd->enable_slow_log= opt_log_slow_slave_statements;
     }
     else
     {


Attachment: [text/bzr-bundle] bzr/luis.soares@sun.com-20100205174801-8xmrfxodv4224pv2.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (luis.soares:3368) Bug#50620Luis Soares5 Feb