List:Commits« Previous MessageNext Message »
From:Luis Soares Date:January 23 2010 3:17am
Subject:bzr commit into mysql-5.1-bugteam branch (luis.soares:3333) Bug#23300
Bug#48632
View as plain text  
#At file:///home/lsoares/Workspace/bzr/work/bugfixing/48632/mysql-5.1-bugteam/ based on revid:svoj@stripped

 3333 Luis Soares	2010-01-23
      BUG#48632: Fix for Bug #23300 Has Not Been Backported 
      To 5.x Release
      
      Notes
      =====
      
      This is a backport of BUG#23300 into 5.1 GA.
      
      Original cset revid:
      luis.soares@stripped
      
      Description
      ===========
      
      When using replication, the slave will not log any slow query
      logs queries replicated from the master, even if the
      option "--log-slow-slave-statements" is set and these take more
      than "log_query_time" to execute.
                    
      In order to log slow queries in replicated thread one needs to
      set the --log-slow-slave-statements, so that the SQL thread is
      initialized with the correct switch. Although setting this flag
      correctly configures the slave thread option to log slow queries,
      there is an issue with the condition that is used to check
      whether to log the slow query or not. When replaying binlog
      events the statement contains the SET TIMESTAMP clause which will
      force the slow logging condition check to fail. Consequently, the
      slow query logging will not take place.
                    
      This patch addresses this issue by removing the second condition
      from the log_slow_statements as it prevents slow queries to be
      binlogged and seems to be deprecated.

    added:
      mysql-test/suite/rpl/r/rpl_slow_query_log.result
      mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt
      mysql-test/suite/rpl/t/rpl_slow_query_log.test
    modified:
      sql/log.cc
      sql/sql_parse.cc
=== added file 'mysql-test/suite/rpl/r/rpl_slow_query_log.result'
--- a/mysql-test/suite/rpl/r/rpl_slow_query_log.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/r/rpl_slow_query_log.result	2010-01-23 03:17:15 +0000
@@ -0,0 +1,48 @@
+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;
+CALL mtr.add_suppression("Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT");
+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 INTO t1 values(1, 1);
+INSERT INTO t1 values(1, sleep(3));
+TRUNCATE mysql.slow_log;
+SELECT 1, sleep(3);
+1	sleep(3)
+1	0
+SELECT 1;
+1
+1
+TRUNCATE mysql.slow_log;
+SET TIMESTAMP= 1;
+SELECT 2, sleep(3);
+2	sleep(3)
+2	0
+SELECT 2;
+2
+2
+TRUNCATE mysql.slow_log;
+SET @old_slow_query_log= @@slow_query_log;
+SET GLOBAL slow_query_log= 'OFF';
+SELECT 3, sleep(3);
+3	sleep(3)
+3	0
+SELECT 3;
+3
+3
+TRUNCATE mysql.slow_log;
+SET GLOBAL slow_query_log= @old_slow_query_log;
+DROP TABLE t1;
+include/stop_slave.inc
+SET GLOBAL long_query_time= @old_long_query_time;
+SET GLOBAL log_output= @old_log_output;
+include/start_slave.inc

=== added file 'mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt'
--- a/mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt	2010-01-23 03:17:15 +0000
@@ -0,0 +1 @@
+--force-restart --log-slow-slave-statements --log-slow-queries

=== added file 'mysql-test/suite/rpl/t/rpl_slow_query_log.test'
--- a/mysql-test/suite/rpl/t/rpl_slow_query_log.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_slow_query_log.test	2010-01-23 03:17:15 +0000
@@ -0,0 +1,193 @@
+#
+# BUG#23300: Slow query log on slave does not log slow replicated statements
+#
+# Description:
+#   The slave should log slow queries replicated from master when
+#   --log-slow-slave-statements is used.
+#
+#   Test is implemented as follows:
+#      i) stop slave
+#     ii) On slave, set long_query_time to a small value.
+#     ii) start slave so that long_query_time variable is picked by sql thread
+#    iii) On master, do one short time query and one long time query, on slave
+#         and check that slow query is logged to slow query log but fast query 
+#         is not.
+#     iv) On slave, check that slow queries go into the slow log and fast dont,
+#         when issued through a regular client connection
+#      v) On slave, check that slow queries go into the slow log and fast dont
+#         when we use SET TIMESTAMP= 1 on a regular client connection.
+#     vi) check that when setting slow_query_log= OFF in a connection 'extra2'
+#         prevents logging slow queries in a connection 'extra'
+#
+# OBS: 
+#   This test only runs for statement binlogging format because on row format
+#   slow queries do not get slow query logged. 
+#   Note that due to the sleep() command the insert is written to the binary
+#   log in row format.
+
+source include/master-slave.inc;
+source include/have_binlog_format_statement.inc;
+
+CALL mtr.add_suppression("Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT");
+
+
+# Prepare slave for different long_query_time we need to stop the slave 
+# and restart it as long_query_time variable is dynamic and, after 
+# setting it, it only takes effect on new connections. 
+#
+# Reference: 
+#   http://dev.mysql.com/doc/refman/6.0/en/set-option.html
+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;
+
+connection master;
+CREATE TABLE t1 (a int, b int); 
+
+# test:
+#   check that slave logs the slow query to the slow log, but not the fast one.
+
+let $slow_query= INSERT INTO t1 values(1, sleep(3));
+let $fast_query= INSERT INTO t1 values(1, 1);
+
+eval $fast_query;
+--disable_warnings
+eval $slow_query;
+--enable_warnings
+sync_slave_with_master;
+
+let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
+let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if ($found_fast_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Fast query FOUND in slow query log. Bailing out!";
+}
+
+if (!$found_slow_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!";
+}
+TRUNCATE mysql.slow_log;
+
+# regular checks for slow query log (using a new connection - 'extra' - to slave)
+
+# test: 
+#   when using direct connections to the slave, check that slow query is logged 
+#   but not the fast one.
+
+connect(extra,127.0.0.1,root,,test,$SLAVE_MYPORT);
+connection extra;
+
+let $fast_query= SELECT 1;
+let $slow_query= SELECT 1, sleep(3);
+
+eval $slow_query;
+eval $fast_query;
+
+let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
+let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if ($found_fast_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Fast query FOUND in slow query log. Bailing out!";
+}
+
+if (!$found_slow_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!";
+}
+TRUNCATE mysql.slow_log;
+
+# test:
+#   when using direct connections to the slave, check that when setting timestamp to 1 the 
+#   slow query is logged but the fast one is not.
+
+let $fast_query= SELECT 2;
+let $slow_query= SELECT 2, sleep(3);
+
+SET TIMESTAMP= 1;
+eval $slow_query;
+eval $fast_query;
+
+let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
+let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if ($found_fast_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Fast query FOUND in slow query log. Bailing out!";
+}
+
+if (!$found_slow_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!";
+}
+TRUNCATE mysql.slow_log;
+
+# test: 
+#   check that when setting the slow_query_log= OFF on connection 'extra2'
+#   prevents connection 'extra' from logging to slow query log.
+
+let $fast_query= SELECT 3;
+let $slow_query= SELECT 3, sleep(3);
+
+connect(extra2,127.0.0.1,root,,test,$SLAVE_MYPORT);
+connection extra2;
+
+SET @old_slow_query_log= @@slow_query_log;
+SET GLOBAL slow_query_log= 'OFF';
+
+connection extra;
+
+eval $slow_query;
+eval $fast_query;
+
+let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
+let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
+
+if ($found_fast_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Fast query FOUND in slow query log when slow_query_log= OFF. Bailing out!";
+}
+
+if ($found_slow_query)
+{
+  SELECT * FROM mysql.slow_log;
+  die "Assertion failed! Slow query FOUND in slow query log when slow_query_log= OFF. Bailing out!";
+}
+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;
+DROP TABLE t1;
+sync_slave_with_master;
+
+source include/stop_slave.inc;
+
+SET GLOBAL long_query_time= @old_long_query_time;
+SET GLOBAL log_output= @old_log_output;
+
+source include/start_slave.inc;
+
+disconnect extra;
+disconnect extra2;

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2010-01-20 19:08:16 +0000
+++ b/sql/log.cc	2010-01-23 03:17:15 +0000
@@ -964,6 +964,7 @@ bool LOGGER::slow_log_print(THD *thd, co
   uint user_host_len= 0;
   ulonglong query_utime, lock_utime;
 
+  DBUG_ASSERT(thd->enable_slow_log);
   /*
     Print the message to the buffer if we have slow log enabled
   */

=== modified file 'sql/sql_parse.cc'
--- a/sql/sql_parse.cc	2010-01-22 10:58:21 +0000
+++ b/sql/sql_parse.cc	2010-01-23 03:17:15 +0000
@@ -1656,9 +1656,9 @@ void log_slow_statement(THD *thd)
 
   /*
     Do not log administrative statements unless the appropriate option is
-    set; do not log into slow log if reading from backup.
+    set.
   */
-  if (thd->enable_slow_log && !thd->user_time)
+  if (thd->enable_slow_log)
   {
     ulonglong end_utime_of_query= thd->current_utime();
     thd_proc_info(thd, "logging slow query");


Attachment: [text/bzr-bundle] bzr/luis.soares@sun.com-20100123031715-jobv9mg2bmn1an35.bundle
Thread
bzr commit into mysql-5.1-bugteam branch (luis.soares:3333) Bug#23300Bug#48632Luis Soares23 Jan