Hi, Luis
Thank you for the work! Patch is good, approved after consideration of
the comments in line.
Luis Soares wrote:
> #At file:///home/lsoares/Workspace/mysql-server/bugfix/23300/6.0-bt/ based on
> revid:joro@stripped
>
> 3010 Luis Soares 2009-02-10
> BUG#23300: Slow query log on slave does not log slow replicated statements
>
> When using replication, the slave will not log any slow query logs queries
> replicated from the master, even if the option "--slow-query-log" 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
> does 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/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 2009-02-10 17:08:11 +0000
> @@ -0,0 +1,19 @@
> +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;
> +STOP SLAVE;
> +SET @old_long_query_time= @@long_query_time;
> +SET GLOBAL long_query_time= 2;
> +START SLAVE;
> +CREATE TABLE t1 (a int, b int);
> +INSERT INTO t1 values(1, 1);
> +INSERT INTO t1 values(1, sleep(3));
> +DROP TABLE t1;
> +Check absence of short query in mysqld-slow.log: Not found.
> +Check long query in mysqld-slow.log: INSERT INTO t1 values(1, sleep(3));
> +STOP SLAVE;
> +SET GLOBAL long_query_time= @old_long_query_time;
> +START SLAVE;
>
> === 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 2009-02-10 17:08:11 +0000
> @@ -0,0 +1 @@
> +--force-restart --log-slow-slave-statements
>
> === 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 2009-02-10 17:08:11 +0000
> @@ -0,0 +1,55 @@
> +#
> +# BUG#23300: Slow query log on slave does not log slow replicated statements
> +#
> +# Description:
> +# When using replication, the slave will not log any queries replicated from
> +# the master).
I think this should be '..., the slave should log slow queries
replicated from master.'
> +#
> +# 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
> +# iv) On slave, sync and check that short lived query is not on
> +# mysqld-slow.log and that long lived query is.
> +#
> +# OBS:
> +# This test only runs for statement and mixed binlogging firmat because on
> +# row format slow queries do not get slow query logged.
> +
> +source include/master-slave.inc;
> +source include/have_binlog_format_mixed_or_statement.inc;
> +
> +# 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;
> +
> +STOP SLAVE;
use
source include/stop_slave.inc;
to make sure it really stops.
> +
> +SET @old_long_query_time= @@long_query_time;
> +SET GLOBAL long_query_time= 2;
> +
> +START SLAVE;
use start_slave.inc
> +
> +connection master;
> +
> +# create table and insert with query time longer
> +# than long_query_time
> +CREATE TABLE t1 (a int, b int);
> +INSERT INTO t1 values(1, 1);
> +INSERT INTO t1 values(1, sleep(3));
> +DROP TABLE t1;
I'd suggest to move the clean up statement to the end of the test.
> +sync_slave_with_master;
> +
> +let $MYSQLD_DATADIR= `select @@datadir`;
> +--exec echo -n "Check absence of short query in mysqld-slow.log: " && grep
> "INSERT INTO t1 values(1, 1)" $MYSQLD_DATADIR/../mysqld-slow.log || echo "Not found."
> +--exec echo -n "Check long query in mysqld-slow.log: " && grep "INSERT INTO
> t1 values(1, sleep(3))" $MYSQLD_DATADIR/../mysqld-slow.log || echo "Not found!"
> +
> +# reset the variables back to the previous value
> +STOP SLAVE;
use stop_slave.inc
> +SET GLOBAL long_query_time= @old_long_query_time;
> +START SLAVE;
>
use start_slave.inc
> === modified file 'sql/sql_parse.cc'
> --- a/sql/sql_parse.cc 2009-02-03 09:16:53 +0000
> +++ b/sql/sql_parse.cc 2009-02-10 17:08:11 +0000
> @@ -1463,9 +1463,24 @@ 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.
> +
> + Note for log slow slave statements:
> +
> + when slave thread is initialized the thd->enable_slow_log is set according
> + the opt_log_slow_slave_statements. Thence there is only the need to check
> + if this is a slave_thread or not. The more intuitive, but also redundant
> + condition would be:
> +
> + thd->enable_slow_log &&
> + (!thd->user_time || (thd->slave_thread &&
> opt_log_slow_slave_statements))
> +
> + Furthermore, since we want to preserve the same behavior always, not only in
> + replication thread, but on all threads we disregard the thd->user_time and
> only
> + check if the slow query log is enabled.
> +
IMO, this comment is not necessary, it makes the code even harder to
understand. I think you can add some comment to explain why made this
change in the commit message of this file.
> */
> - if (thd->enable_slow_log && !thd->user_time)
> + if (thd->enable_slow_log)
> {
> thd_proc_info(thd, "logging slow query");
> ulonglong end_utime_of_query= thd->current_utime();
>
>
