diff --git a/mysql-test/suite/rpl/r/rpl_slow_query_log.result b/mysql-test/suite/rpl/r/rpl_slow_query_log.result index fd6a2c5d7c4..a4479f0c544 100644 --- a/mysql-test/suite/rpl/r/rpl_slow_query_log.result +++ b/mysql-test/suite/rpl/r/rpl_slow_query_log.result @@ -46,3 +46,46 @@ include/stop_slave.inc SET GLOBAL long_query_time= @old_long_query_time; SET GLOBAL log_output= @old_log_output; include/start_slave.inc +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; +SET @old_log_output= @@log_output; +SET GLOBAL log_output= 'TABLE'; +SET GLOBAL long_query_time= 2; +SET @old_long_query_time= @@long_query_time; +SET SESSION long_query_time= 2; +TRUNCATE mysql.slow_log; +include/stop_slave.inc +SET @old_log_output= @@log_output; +SET GLOBAL log_output= 'TABLE'; +SET @old_long_query_time= @@long_query_time; +SET GLOBAL long_query_time= 2; +TRUNCATE mysql.slow_log; +include/start_slave.inc +CREATE TABLE t1 (a int, b int); +******************************************************************** +**** INSERT one row that exceeds long_query_time +**** Outcome: query ends up in both master and slave slow log +******************************************************************** +INSERT INTO t1 values(1, sleep(3)); +### Assertion is good. Both Master and Slave exhibit the +### same number of queries in slow log: 1 +TRUNCATE mysql.slow_log; +TRUNCATE mysql.slow_log; +******************************************************************** +**** Now do inserts again, but first add an index to the table. +**** Outcome: Note that the slave contains the same one entry (as +**** the master does) whereas before the patch it did not. +******************************************************************** +ALTER TABLE t1 ADD INDEX id1(a); +INSERT INTO t1 values(1, sleep(3)); +### Assertion is good. Both Master and Slave exhibit the +### same number of queries in slow log: 1 +SET @@global.log_output= @old_log_output; +SET @@global.long_query_time= @old_long_query_time; +DROP TABLE t1; +SET @@global.log_output= @old_log_output; +SET @@global.long_query_time= @old_long_query_time; diff --git a/mysql-test/suite/rpl/t/rpl_slow_query_log.test b/mysql-test/suite/rpl/t/rpl_slow_query_log.test index c310d6a8a4f..ced4859ebe7 100644 --- a/mysql-test/suite/rpl/t/rpl_slow_query_log.test +++ b/mysql-test/suite/rpl/t/rpl_slow_query_log.test @@ -175,7 +175,6 @@ TRUNCATE mysql.slow_log; # clean up: drop tables, reset the variables back to the previous value, # disconnect extra connections connection extra2; - SET GLOBAL slow_query_log= @old_slow_query_log; connection master; @@ -191,3 +190,119 @@ source include/start_slave.inc; disconnect extra; disconnect extra2; + +# +# BUG#50620: Adding an index to a table prevents slave from logging into slow log +# + +-- source include/master-slave-reset.inc + +-- connection master +SET @old_log_output= @@log_output; +SET GLOBAL log_output= 'TABLE'; +SET GLOBAL long_query_time= 2; +SET @old_long_query_time= @@long_query_time; +SET SESSION long_query_time= 2; +TRUNCATE mysql.slow_log; +-- connection slave + +-- source include/stop_slave.inc +SET @old_log_output= @@log_output; +SET GLOBAL log_output= 'TABLE'; +SET @old_long_query_time= @@long_query_time; +SET GLOBAL long_query_time= 2; +TRUNCATE mysql.slow_log; +-- source include/start_slave.inc + +let $slow_query= INSERT INTO t1 values(1, sleep(3)); + +-- connection master +CREATE TABLE t1 (a int, b int); + +-- echo ******************************************************************** +-- echo **** INSERT one row that exceeds long_query_time +-- echo **** Outcome: query ends up in both master and slave slow log +-- echo ******************************************************************** + +-- disable_warnings +-- eval $slow_query +-- enable_warnings + +let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; +-- sync_slave_with_master +let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; + +if (`SELECT $master_slow_query != $slave_slow_query`) +{ + -- connection master + -- echo *********************************************** + -- echo ** DUMPING MASTER SLOW LOG CONTENTS + -- echo *********************************************** + SELECT * FROM mysql.slow_log; + + -- connection slave + -- echo *********************************************** + -- echo ** DUMPING SLAVE SLOW LOG CONTENTS + -- echo *********************************************** + SELECT * FROM mysql.slow_log; + + -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!" +} + +if (`SELECT $master_slow_query = $slave_slow_query`) +{ + -- echo ### Assertion is good. Both Master and Slave exhibit the + -- echo ### same number of queries in slow log: $master_slow_query +} + +TRUNCATE mysql.slow_log; +-- connection master +TRUNCATE mysql.slow_log; + +-- echo ******************************************************************** +-- echo **** Now do inserts again, but first add an index to the table. +-- echo **** Outcome: Note that the slave contains the same one entry (as +-- echo **** the master does) whereas before the patch it did not. +-- echo ******************************************************************** + +ALTER TABLE t1 ADD INDEX id1(a); + +-- disable_warnings +-- eval $slow_query +-- enable_warnings + +let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; +-- sync_slave_with_master +let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; + +if (`SELECT $master_slow_query != $slave_slow_query`) +{ + -- connection master + -- echo *********************************************** + -- echo ** DUMPING MASTER SLOW LOG CONTENTS + -- echo *********************************************** + SELECT * FROM mysql.slow_log; + + -- connection slave + -- echo *********************************************** + -- echo ** DUMPING SLAVE SLOW LOG CONTENTS + -- echo *********************************************** + SELECT * FROM mysql.slow_log; + + -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!" +} + +if (`SELECT $master_slow_query = $slave_slow_query`) +{ + -- echo ### Assertion is good. Both Master and Slave exhibit the + -- echo ### same number of queries in slow log: $master_slow_query +} + +-- connection master +SET @@global.log_output= @old_log_output; +SET @@global.long_query_time= @old_long_query_time; +DROP TABLE t1; + +-- sync_slave_with_master +SET @@global.log_output= @old_log_output; +SET @@global.long_query_time= @old_long_query_time; diff --git a/sql/log_event.cc b/sql/log_event.cc index 2da825e63ce..de395f3d4c7 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -3170,6 +3170,18 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli, const char* found_semicolon= NULL; mysql_parse(thd, thd->query(), thd->query_length(), &found_semicolon); log_slow_statement(thd); + + /* + Resetting the enable_slow_log thd variable. + + We need to reset it back to the opt_log_slow_slave_statements + value after the statement execution (and slow logging + is done). It might have changed if the statement was an + admin statement (in which case, down in mysql_parse execution + thd->enable_slow_log is set to the value of + opt_log_slow_admin_statements). + */ + thd->enable_slow_log= opt_log_slow_slave_statements; } else {