mirror of
https://github.com/MariaDB/server.git
synced 2025-01-21 06:22:28 +01:00
a0e19f6816
into slow log
While processing a statement, down the mysql_parse execution
stack, the thd->enable_slow_log can be assigned to
opt_log_slow_admin_statements, depending whether one is executing
administrative statements, such as ALTER TABLE, OPTIMIZE,
ANALYZE, etc, or not. This can have an impact on slow logging for
statements that are executed after an administrative statement
execution is completed.
When executing statements directly from the user this is fine
because, the thd->enable_slow_log is reset right at the beginning
of the dispatch_command function, ie, everytime a new statement
is set is set to execute.
On the other hand, for slave SQL thread (sql_thd) the story is a
bit different. When in SBR the sql_thd applies statements by
calling mysql_parse. Right after, it calls log_slow_statement
function to log them if they take too long. Calling mysql_parse
directly is fine, but also means that dispatch_command function
is bypassed. As a consequence, thd->enable_slow_log does not get
a chance to be reset before the next statement to be executed by
the sql_thd. If the statement just executed by the sql_thd was an
administrative statement and logging of admin statements was
disabled, this means that sql_thd->enable_slow_log will be set to
0 (disabled) from that moment on. End result: sql_thd stops
logging slow statements.
We fix this by resetting the value of sql_thd->enable_slow_log to
the value of opt_log_slow_slave_statements right after
log_slow_stement is called by the sql_thd.
91 lines
2.8 KiB
Text
91 lines
2.8 KiB
Text
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;
|
|
CALL mtr.add_suppression("Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT");
|
|
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
|
|
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;
|