mirror of
https://github.com/MariaDB/server.git
synced 2025-08-27 13:04:36 +03:00
09c80e12c5
Major replication test framework cleanup. This does the following:
- Ensure that all tests clean up the replication state when they
finish, by making check-testcase check the output of SHOW SLAVE STATUS.
This implies:
- Slave must not be running after test finished. This is good
because it removes the risk for sporadic errors in subsequent
tests when a test forgets to sync correctly.
- Slave SQL and IO errors must be cleared when test ends. This is
good because we will notice if a test gets an unexpected error in
the slave threads near the end.
- We no longer have to clean up before a test starts.
- Ensure that all tests that wait for an error in one of the slave
threads waits for a specific error. It is no longer possible to
source wait_for_slave_[sql|io]_to_stop.inc when there is an error
in one of the slave threads. This is good because:
- If a test expects an error but there is a bug that causes
another error to happen, or if it stops the slave thread without
an error, then we will notice.
- When developing tests, wait_for_*_to_[start|stop].inc will fail
immediately if there is an error in the relevant slave thread.
Before this patch, we had to wait for the timeout.
- Remove duplicated and repeated code for setting up unusual replication
topologies. Now, there is a single file that is capable of setting
up arbitrary topologies (include/rpl_init.inc, but
include/master-slave.inc is still available for the most common
topology). Tests can now end with include/rpl_end.inc, which will clean
up correctly no matter what topology is used. The topology can be
changed with include/rpl_change_topology.inc.
- Improved debug information when tests fail. This includes:
- debug info is printed on all servers configured by include/rpl_init.inc
- User can set $rpl_debug=1, which makes auxiliary replication files
print relevant debug info.
- Improved documentation for all auxiliary replication files. Now they
describe purpose, usage, parameters, and side effects.
- Many small code cleanups:
- Made have_innodb.inc output a sensible error message.
- Moved contents of rpl000017-slave.sh into rpl000017.test
- Added mysqltest variables that expose the current state of
disable_warnings/enable_warnings and friends.
- Too many to list here: see per-file comments for details.
310 lines
9.5 KiB
Plaintext
310 lines
9.5 KiB
Plaintext
#
|
|
# 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 binlogging format because on row format
|
|
# slow queries do not get slow query logged.
|
|
# Note that due to the sleep() command the insert is written to the binary
|
|
# log in row format.
|
|
|
|
source include/master-slave.inc;
|
|
source include/have_binlog_format_statement.inc;
|
|
|
|
CALL mtr.add_suppression("Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT");
|
|
|
|
|
|
# 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;
|
|
--disable_warnings
|
|
eval $slow_query;
|
|
--enable_warnings
|
|
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;
|
|
|
|
#
|
|
# BUG#50620: Adding an index to a table prevents slave from logging into slow log
|
|
#
|
|
|
|
--source include/rpl_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;
|
|
--source include/rpl_end.inc
|