Re: bzr commit into mysql-6.0-bugteam branch (luis.soares:3010) Bug#23300

[Luís Soares]

Hi Zhenxing,

  

On Wed, 2009-02-11 at 17:30 +0800, He Zhenxing wrote:
> 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.'

Ok, changed.

> > +#
> > +#   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.

Yes, I agree. Changed.

> > +
> > +SET @old_long_query_time= @@long_query_time;
> > +SET GLOBAL long_query_time= 2;
> > +
> > +START SLAVE;
> 
> use  start_slave.inc

Again, agree.

> 
> > +
> > +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.

Not really necessary, but probably makes things more structured. Agree
and changed.

> 
> > +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

Again, agree.
> 
> > +SET GLOBAL long_query_time= @old_long_query_time;
> > +START SLAVE;
> > 
> 
> use  start_slave.inc

Again, agree.
> 
> > === 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.

Removed from source. Moved part of it to the commit message.

> 
> >    */
> > -  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();
> > 
> > 
> 
> 

Regards,
Luís
-- 
Luís