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

[Andrei Elkin]

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.

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.

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


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

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


>    */
> -  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.

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