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

[Luís Soares]

Hi Andrei,

  just a correction in one of the comments. Find it in-line.

On Fri, 2009-02-13 at 01:02 +0100, Luís Soares wrote:
> Hi Andrei,
> 
>  I have some comments inline. Please have a look.
> 
> On Wed, 2009-02-11 at 16:44 +0200, Andrei Elkin wrote:
> > Luis, hello.
> > 
> > 
> > 
> > > #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.
> > 
> > and this is a specified behavior, is not it? 
> > I would say that explicitly to avoid possible ambiguity.
> 
> Ok. I renamed the --slow-query-log to --log-slow-slave-statements.
> 
> > 
> > Another rather minor point, I think there is no need to separate the
> > above and the following paragraphs with the empty line. It makes me
> > think that the above paragraph stands to me as a problem description.
> 
> And it was my intention to make it as a short problem description.
> 
> > >       
> > >       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.
> > 
> > ok
> > 
> > > 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).
> > > +#
> > > +#   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;
> > > +
> > > +SET @old_long_query_time= @@long_query_time;
> > > +SET GLOBAL long_query_time= 2;
> > > +
> > > +START SLAVE;
> > > +
> > > +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;
> > > +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!"
> > 
> > Although correct, I'd suggest to use SELECT from the slow log table :-)
> > (see 5.2 MySQL Server Logs).
> 
> Good point. Improved the test by using slow log tables. I have also
> extended it for some other cases.
> 
> > 
> > > +
> > > +# reset the variables back to the previous value
> > > +STOP SLAVE;
> > > +SET GLOBAL long_query_time= @old_long_query_time;
> > > +START SLAVE;
> > >
> > > === 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.
> > 
> > ok
> > 
> > > +    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))
> > 
> > I suggest to stay without so verbose comments.
> > Mentioning opt_log_slow_slave_statements makes sql_thd->enable_slow_log is
> enough.
> 
> Ok. Removed from source.
> 
> > > +
> > > +      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.
> > > +
> > 
> > This comment paragraph looks redundant. thd->user_time won't be there
> > anymore.
> > I suggest to move the comment lines  into the per-file's for bzr.
> 
> Moved into 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();
> > >
> > 
> > There is one more place in the code
> > bool LOGGER::slow_log_print() referring to `opt_log_slow_slave_statements'
> > 
> >     if (thd->slave_thread && !opt_log_slow_slave_statements)
> >       return 0;
> > 
> > rather than to `enable_slow_log'. That piece of code is actually
> > completely extraneous because the caller of the function is to check
> `enable_slow_log'
> > before to call the func.
> > 
> > I suggest to remove the referred snippet.
> 
> Hmm... I opted to keep this one. The opt_log_slow_slave_statements may
> be used to enable disable from a regular connnection the slow query
> logging for replication thread (as one seems to be able to do with
> regular connections). Nevertheless, there seems to be some lack of
> support for this in the opt_log_slow_slave_statements (as there is for
> opt_slow_log).

I mean, opt_slow_slave_statements is not dynamic.

> 
> > >
> > > -- 
> > > MySQL Code Commits Mailing List
> > > For list archives: http://lists.mysql.com/commits
> > > To unsubscribe:    http://lists.mysql.com/commits?unsub=1
> > >
> > 
> > Your fixes must be correct as neither `user_time' nor
> > `start_time' are referred directly or indirectly (incl possible earlier
> > participating in assigning some other variables) in the stack headed
> > by slow_log_print().
> > This would give us a credit to eliminate `user_time' from THD
> > class altogether if `start_time' was not referred for `exec_time'
> > calculation in log_event.cc \footnote{correctness of the latter
> > feature might be challenged but I don't recommend it for the current
> > framework}
> > 
> > 
> > cheers,
> > 
> > Andrei
> > 
> > 
> > 
> -- 
> Luís
> 
> 
-- 
Luís