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

[Luís Soares]

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

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