diff options
| -rw-r--r-- | mysql-test/suite/rpl/r/rpl_slow_query_log.result | 47 | ||||
| -rw-r--r-- | mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt | 1 | ||||
| -rw-r--r-- | mysql-test/suite/rpl/t/rpl_slow_query_log.test | 187 | ||||
| -rw-r--r-- | sql/log.cc | 1 | ||||
| -rw-r--r-- | sql/sql_parse.cc | 4 |
5 files changed, 238 insertions, 2 deletions
diff --git a/mysql-test/suite/rpl/r/rpl_slow_query_log.result b/mysql-test/suite/rpl/r/rpl_slow_query_log.result new file mode 100644 index 00000000000..ced357b21e9 --- /dev/null +++ b/mysql-test/suite/rpl/r/rpl_slow_query_log.result @@ -0,0 +1,47 @@ +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; +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 INTO t1 values(1, 1); +INSERT INTO t1 values(1, sleep(3)); +TRUNCATE mysql.slow_log; +SELECT 1, sleep(3); +1 sleep(3) +1 0 +SELECT 1; +1 +1 +TRUNCATE mysql.slow_log; +SET TIMESTAMP= 1; +SELECT 2, sleep(3); +2 sleep(3) +2 0 +SELECT 2; +2 +2 +TRUNCATE mysql.slow_log; +SET @old_slow_query_log= @@slow_query_log; +SET GLOBAL slow_query_log= 'OFF'; +SELECT 3, sleep(3); +3 sleep(3) +3 0 +SELECT 3; +3 +3 +TRUNCATE mysql.slow_log; +SET GLOBAL slow_query_log= @old_slow_query_log; +DROP TABLE t1; +include/stop_slave.inc +SET GLOBAL long_query_time= @old_long_query_time; +SET GLOBAL log_output= @old_log_output; +include/start_slave.inc diff --git a/mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt b/mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt new file mode 100644 index 00000000000..a27d3a0f5a7 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt @@ -0,0 +1 @@ +--force-restart --log-slow-slave-statements --log-slow-queries diff --git a/mysql-test/suite/rpl/t/rpl_slow_query_log.test b/mysql-test/suite/rpl/t/rpl_slow_query_log.test new file mode 100644 index 00000000000..1d5fcf950f2 --- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_slow_query_log.test @@ -0,0 +1,187 @@ +# +# BUG#23300: Slow query log on slave does not log slow replicated statements +# +# Description: +# The slave should log slow queries replicated from master when +# --log-slow-slave-statements is used. +# +# 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, on slave +# and check that slow query is logged to slow query log but fast query +# is not. +# iv) On slave, check that slow queries go into the slow log and fast dont, +# when issued through a regular client connection +# v) On slave, check that slow queries go into the slow log and fast dont +# when we use SET TIMESTAMP= 1 on a regular client connection. +# vi) check that when setting slow_query_log= OFF in a connection 'extra2' +# prevents logging slow queries in a connection 'extra' +# +# 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; + +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; + +connection master; +CREATE TABLE t1 (a int, b int); + +# test: +# check that slave logs the slow query to the slow log, but not the fast one. + +let $slow_query= INSERT INTO t1 values(1, sleep(3)); +let $fast_query= INSERT INTO t1 values(1, 1); + +eval $fast_query; +eval $slow_query; +sync_slave_with_master; + +let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`; +let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; + +if ($found_fast_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Fast query FOUND in slow query log. Bailing out!"; +} + +if (!$found_slow_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!"; +} +TRUNCATE mysql.slow_log; + +# regular checks for slow query log (using a new connection - 'extra' - to slave) + +# test: +# when using direct connections to the slave, check that slow query is logged +# but not the fast one. + +connect(extra,127.0.0.1,root,,test,$SLAVE_MYPORT); +connection extra; + +let $fast_query= SELECT 1; +let $slow_query= SELECT 1, sleep(3); + +eval $slow_query; +eval $fast_query; + +let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`; +let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; + +if ($found_fast_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Fast query FOUND in slow query log. Bailing out!"; +} + +if (!$found_slow_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!"; +} +TRUNCATE mysql.slow_log; + +# test: +# when using direct connections to the slave, check that when setting timestamp to 1 the +# slow query is logged but the fast one is not. + +let $fast_query= SELECT 2; +let $slow_query= SELECT 2, sleep(3); + +SET TIMESTAMP= 1; +eval $slow_query; +eval $fast_query; + +let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`; +let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; + +if ($found_fast_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Fast query FOUND in slow query log. Bailing out!"; +} + +if (!$found_slow_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!"; +} +TRUNCATE mysql.slow_log; + +# test: +# check that when setting the slow_query_log= OFF on connection 'extra2' +# prevents connection 'extra' from logging to slow query log. + +let $fast_query= SELECT 3; +let $slow_query= SELECT 3, sleep(3); + +connect(extra2,127.0.0.1,root,,test,$SLAVE_MYPORT); +connection extra2; + +SET @old_slow_query_log= @@slow_query_log; +SET GLOBAL slow_query_log= 'OFF'; + +connection extra; + +eval $slow_query; +eval $fast_query; + +let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`; +let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`; + +if ($found_fast_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Fast query FOUND in slow query log when slow_query_log= OFF. Bailing out!"; +} + +if ($found_slow_query) +{ + SELECT * FROM mysql.slow_log; + die "Assertion failed! Slow query FOUND in slow query log when slow_query_log= OFF. Bailing out!"; +} +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; +DROP TABLE t1; +sync_slave_with_master; + +source include/stop_slave.inc; + +SET GLOBAL long_query_time= @old_long_query_time; +SET GLOBAL log_output= @old_log_output; + +source include/start_slave.inc; + +disconnect extra; +disconnect extra2; diff --git a/sql/log.cc b/sql/log.cc index 1af2f3a4ddc..5c25d30bad0 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -961,6 +961,7 @@ bool LOGGER::slow_log_print(THD *thd, const char *query, uint query_length, uint user_host_len= 0; ulonglong query_utime, lock_utime; + DBUG_ASSERT(thd->enable_slow_log); /* Print the message to the buffer if we have slow log enabled */ diff --git a/sql/sql_parse.cc b/sql/sql_parse.cc index 513b9230c37..d0897646cec 100644 --- a/sql/sql_parse.cc +++ b/sql/sql_parse.cc @@ -1615,9 +1615,9 @@ 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. */ - if (thd->enable_slow_log && !thd->user_time) + if (thd->enable_slow_log) { ulonglong end_utime_of_query= thd->current_utime(); thd_proc_info(thd, "logging slow query"); |