Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: N/A
-
Fix Version/s: 10.1.4
-
Component/s: Admin statements
-
Labels:None
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.
Gliffy Diagrams
Attachments
Issue Links
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
Here (as well as all bugs connected to slow log) cause is that we write slow log after restoring variables values.
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
The review mail is answered, fix according to the review commited
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
ok to push
The variables prohibited as a workaround.