[MDEV-7006] SET STATEMENT does not work with slow log tuning (long_query_time, log_slow_filter, log_slow_verbosity, log_slow_rate_limit) Created: 2014-11-01  Updated: 2015-04-12  Resolved: 2015-03-12

Status: Closed
Project: MariaDB Server
Component/s: Admin statements
Affects Version/s: N/A
Fix Version/s: 10.1.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-7007 SET STATEMENT slow_query_log has no e... Closed
relates to MDEV-7009 SET STATEMENT min_examined_row_limit ... Closed
relates to MDEV-5231 Per query variables from Percona Serv... Closed
relates to MDEV-6923 Testing for SET STATEMENT .. FOR (MDE... Closed

 Description   

The first test case is for 4 options each set via SET STATEMENT var FOR query. Every part of the test fails – whatever is expected does not happen.
To make sure that the test itself is valid, the second test case is provided. It does exactly the same, but via old-fashioned SET var; query; unset var. It works as expected.

Test case 1

 
--let $slowlog = `select @@slow_query_log_file`
 
 
 
set @log_output.saved = @@global.log_output;
 
set @slow_query_log.saved = @@global.slow_query_log;
 
 
 
set global log_output = 'FILE', global slow_query_log = 1;
 
set slow_query_log = 1;
 
set long_query_time = 10;
 
 
 
set LONG_QUERY_TIME = 0.01;
 
select sleep(0.11);
 
set LONG_QUERY_TIME = DEFAULT;
 
--echo #--------------------------------------------------------------------
 
--echo # The last select statement is expected to be in the log
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
set long_query_time = 0.01;
 
 
 
set LOG_SLOW_FILTER = 'full_scan';
 
select sleep(0.14);
 
set LOG_SLOW_FILTER = DEFAULT;
 
--echo #--------------------------------------------------------------------
 
--echo # The last select statement is NOT expected to be in the log
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
set LOG_SLOW_VERBOSITY = 'explain';
 
select host, sleep(0.15) from mysql.user where user = 'root';
 
set LOG_SLOW_VERBOSITY = DEFAULT;
 
--echo #--------------------------------------------------------------------
 
--echo # The last select statement should have EXPLAIN
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
set LOG_SLOW_RATE_LIMIT = 4;
 
select sleep(0.16);
 
set LOG_SLOW_RATE_LIMIT = DEFAULT;
 
--echo #--------------------------------------------------------------------
 
--echo # The last select statement is NOT expected to be in the log
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
--connection default
 
set global log_output = @log_output.saved;
 
set global slow_query_log = @slow_query_log.saved;

Test case 2 (sanity check)

 
--let $slowlog = `select @@slow_query_log_file`
 
 
 
set @log_output.saved = @@global.log_output;
 
set @slow_query_log.saved = @@global.slow_query_log;
 
 
 
set global log_output = 'FILE', global slow_query_log = 1;
 
set slow_query_log = 1;
 
set long_query_time = 10;
 
 
 
set statement LONG_QUERY_TIME = 0.01 for select sleep(0.11);
 
--echo #--------------------------------------------------------------------
 
--echo # The last set statement is expected to be in the log
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
set long_query_time = 0.01;
 
 
 
set statement LOG_SLOW_FILTER = 'full_scan' for select sleep(0.14);
 
--echo #--------------------------------------------------------------------
 
--echo # The last set statement is NOT expected to be in the log
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
set statement LOG_SLOW_VERBOSITY = 'explain' for select host, sleep(0.15) from mysql.user where user = 'root';
 
--echo #--------------------------------------------------------------------
 
--echo # The last set statement should have EXPLAIN
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
set statement LOG_SLOW_RATE_LIMIT = 4 for select sleep(0.16);
 
--echo #--------------------------------------------------------------------
 
--echo # The last set statement is NOT expected to be in the log
 
--echo #------
 
cat_file $slowlog;
 
--echo #--------------------------------------------------------------------
 
 
 
--connection default
 
set global log_output = @log_output.saved;
 
set global slow_query_log = @slow_query_log.saved;

Final log from test case 1

 
/data/repo/git/bb-10.1-set-statement/sql/mysqld, Version: 10.1.1-MariaDB-wsrep-debug-log (Source distribution, wsrep_25.10.r4123). started with:
 
Tcp port: 16000  Unix socket: /data/repo/git/bb-10.1-set-statement/mysql-test/var/tmp/mysqld.1.sock
 
Time                 Id Command    Argument
 
# Time: 141103  1:06:12
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 4  Schema: test  QC_hit: No
 
# Query_time: 0.140494  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
 
use test;
 
SET timestamp=1414962372;
 
set statement LOG_SLOW_FILTER = 'full_scan' for select sleep(0.14);
 
# Time: 141103  1:06:13
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 4  Schema: test  QC_hit: No
 
# Query_time: 0.602010  Lock_time: 0.000315  Rows_sent: 4  Rows_examined: 4
 
SET timestamp=1414962373;
 
set statement LOG_SLOW_VERBOSITY = 'explain' for select host, sleep(0.15) from mysql.user where user = 'root';
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 4  Schema: test  QC_hit: No
 
# Query_time: 0.160619  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
 
SET timestamp=1414962373;
 
set statement LOG_SLOW_RATE_LIMIT = 4 for select sleep(0.16);

Final log from test case 2

 
/data/repo/git/bb-10.1-set-statement/sql/mysqld, Version: 10.1.1-MariaDB-wsrep-debug-log (Source distribution, wsrep_25.10.r4123). started with:
 
Tcp port: 16000  Unix socket: /data/repo/git/bb-10.1-set-statement/mysql-test/var/tmp/mysqld.1.sock
 
Time                 Id Command    Argument
 
# Time: 141103  1:07:34
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 3  Schema: test  QC_hit: No
 
# Query_time: 0.111444  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
 
use test;
 
SET timestamp=1414962454;
 
select sleep(0.11);
 
# Time: 141103  1:07:35
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 3  Schema: test  QC_hit: No
 
# Query_time: 0.602077  Lock_time: 0.000219  Rows_sent: 4  Rows_examined: 4
 
#
 
# explain: id	select_type	table	type	possible_keys	key	key_len	ref	rows	r_rows	filtered	r_filtered	Extra
 
# explain: 1	SIMPLE	user	index	NULL	PRIMARY	420	NULL	4	4	100.00	100.00	Using where; Using index
 
#
 
SET timestamp=1414962455;
 
select host, sleep(0.15) from mysql.user where user = 'root';

All the same in Percona server.

 Comments   
Comment by Oleksandr Byelkin [ 2014-11-05 ]

The variables prohibited as a workaround.

Comment by Oleksandr Byelkin [ 2014-11-11 ]

Here (as well as all bugs connected to slow log) cause is that we write slow log after restoring variables values.

Comment by Oleksandr Byelkin [ 2015-02-17 ]

Hopefully I fixed everything except finding a function to put variables reset (there is no such function and I can't move the calls because they are at the end of statements execution loop.

commit to check is:
revision-id: 83659a68642da2eb6e9327f17a0ef730f512aa96
parent(s): 3e2849d2a01b06a61407b00989c3f981e62dd183
committer: Oleksandr Byelkin
branch nick: server
timestamp: 2015-02-17 12:54:51 +0100

Comment by Oleksandr Byelkin [ 2015-03-10 ]

The review mail is answered, fix according to the review commited

Comment by Oleksandr Byelkin [ 2015-03-10 ]

evision-id: 966158a1d718e49fc8c0bbbed8b3078f247f8a33
parent(s): 3e2849d2a01b06a61407b00989c3f981e62dd183
committer: Oleksandr Byelkin
branch nick: server
timestamp: 2015-03-10 16:19:31 +0100
message:

MDEV-7006 MDEV-7007: SET STATEMENT and slow log
fixed embedded server tests
MDEV-7009: SET STATEMENT min_examined_row_limit has no effect
MDEV-6948:SET STATEMENT gtid_domain_id = ... FOR has no effect (same for gtid_seq_no and server_id)

old values of SET STATENENT variables now saved in its own Query_arena and restored later

Comment by Sergei Golubchik [ 2015-03-11 ]

ok to push

Comment by Daniel Black [ 2015-04-12 ]

ref: https://github.com/MariaDB/server/commit/a71e2d23bd08ca041a953df44f2235a8ef20bfcc

Generated at Thu Feb 08 07:16:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.