Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
N/A
-
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.
Attachments
Issue Links
Activity
Description |
{code:sql} MariaDB [test]> set global slow_query_log = 1, log_output = 'TABLE'; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> set slow_query_log = 1; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> truncate table mysql.slow_log; Query OK, 0 rows affected (0.13 sec) MariaDB [test]> set statement long_query_time = 0.000001 for select sleep(0.1); +------------+ | sleep(0.1) | +------------+ | 0 | +------------+ 1 row in set (0.10 sec) MariaDB [test]> set long_query_time = 0.000001; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> select sleep(0.05); +-------------+ | sleep(0.05) | +-------------+ | 0 | +-------------+ 1 row in set (0.05 sec) {code} {code:sql} MariaDB [test]> select * from mysql.slow_log; +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ | start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ | 2014-11-02 01:04:47.662235 | root[root] @ localhost [::1] | 00:00:00.000258 | 00:00:00.000000 | 0 | 0 | test | 0 | 0 | 1 | set long_query_time = 0.000001 | 9 | | 2014-11-02 01:04:57.086062 | root[root] @ localhost [::1] | 00:00:00.050704 | 00:00:00.000000 | 1 | 0 | test | 0 | 0 | 1 | select sleep(0.05) | 9 | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ 2 rows in set (0.01 sec) {code} Percona server does not seem to be affected. |
{code:sql} MariaDB [test]> set global slow_query_log = 1, log_output = 'TABLE'; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> set slow_query_log = 1; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> truncate table mysql.slow_log; Query OK, 0 rows affected (0.13 sec) MariaDB [test]> set statement long_query_time = 0.000001 for select sleep(0.1); +------------+ | sleep(0.1) | +------------+ | 0 | +------------+ 1 row in set (0.10 sec) MariaDB [test]> set long_query_time = 0.000001; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> select sleep(0.05); +-------------+ | sleep(0.05) | +-------------+ | 0 | +-------------+ 1 row in set (0.05 sec) {code} {code:sql} MariaDB [test]> select * from mysql.slow_log; +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ | start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ | 2014-11-02 01:04:47.662235 | root[root] @ localhost [::1] | 00:00:00.000258 | 00:00:00.000000 | 0 | 0 | test | 0 | 0 | 1 | set long_query_time = 0.000001 | 9 | | 2014-11-02 01:04:57.086062 | root[root] @ localhost [::1] | 00:00:00.050704 | 00:00:00.000000 | 1 | 0 | test | 0 | 0 | 1 | select sleep(0.05) | 9 | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ 2 rows in set (0.01 sec) {code} All the same in Percona server. |
Summary | SET STATEMENT long_query_time has no effect | SET STATEMENT does not work with slow log tuning (long_query_time, log_slow_filter, log_slow_verbosity, log_slow_rate_limit) |
Description |
{code:sql} MariaDB [test]> set global slow_query_log = 1, log_output = 'TABLE'; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> set slow_query_log = 1; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> truncate table mysql.slow_log; Query OK, 0 rows affected (0.13 sec) MariaDB [test]> set statement long_query_time = 0.000001 for select sleep(0.1); +------------+ | sleep(0.1) | +------------+ | 0 | +------------+ 1 row in set (0.10 sec) MariaDB [test]> set long_query_time = 0.000001; Query OK, 0 rows affected (0.00 sec) MariaDB [test]> select sleep(0.05); +-------------+ | sleep(0.05) | +-------------+ | 0 | +-------------+ 1 row in set (0.05 sec) {code} {code:sql} MariaDB [test]> select * from mysql.slow_log; +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ | start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ | 2014-11-02 01:04:47.662235 | root[root] @ localhost [::1] | 00:00:00.000258 | 00:00:00.000000 | 0 | 0 | test | 0 | 0 | 1 | set long_query_time = 0.000001 | 9 | | 2014-11-02 01:04:57.086062 | root[root] @ localhost [::1] | 00:00:00.050704 | 00:00:00.000000 | 1 | 0 | test | 0 | 0 | 1 | select sleep(0.05) | 9 | +----------------------------+------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+--------------------------------+-----------+ 2 rows in set (0.01 sec) {code} All the same in Percona server. |
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. {code:sql|title=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; {code} {code:sql|title=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; {code} {noformat:title=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); {noformat} {noformat:title=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'; {noformat} All the same in Percona server. |
Remote Link | This issue links to "Bug#1388632 - SET STATEMENT does not work with slow log tuning (long_query_time, log_slow_filter, log_slow_verbosity, log_slow_rate_limit) (Web Link)" [ 21204 ] |
Status | Open [ 1 ] | In Progress [ 3 ] |
Assignee | Oleksandr Byelkin [ sanja ] | Sergei Golubchik [ serg ] |
Status | In Progress [ 3 ] | In Review [ 10002 ] |
Assignee | Sergei Golubchik [ serg ] | Oleksandr Byelkin [ sanja ] |
Status | In Review [ 10002 ] | Stalled [ 10000 ] |
Status | Stalled [ 10000 ] | In Progress [ 3 ] |
Status | In Progress [ 3 ] | Stalled [ 10000 ] |
Status | Stalled [ 10000 ] | In Progress [ 3 ] |
Assignee | Oleksandr Byelkin [ sanja ] | Sergei Golubchik [ serg ] |
Status | In Progress [ 3 ] | In Review [ 10002 ] |
Assignee | Sergei Golubchik [ serg ] | Oleksandr Byelkin [ sanja ] |
Status | In Review [ 10002 ] | Stalled [ 10000 ] |
Status | Stalled [ 10000 ] | In Progress [ 3 ] |
Status | In Progress [ 3 ] | In Review [ 10002 ] |
Status | In Review [ 10002 ] | Stalled [ 10000 ] |
Assignee | Oleksandr Byelkin [ sanja ] | Sergei Golubchik [ serg ] |
Status | Stalled [ 10000 ] | In Review [ 10002 ] |
Assignee | Sergei Golubchik [ serg ] | Oleksandr Byelkin [ sanja ] |
Status | In Review [ 10002 ] | Stalled [ 10000 ] |
Status | Stalled [ 10000 ] | In Progress [ 3 ] |
Fix Version/s | 10.1.4 [ 18400 ] | |
Fix Version/s | 10.1 [ 16100 ] | |
Resolution | Fixed [ 1 ] | |
Status | In Progress [ 3 ] | Closed [ 6 ] |
Component/s | Admin statements [ 11400 ] | |
Component/s | OTHER [ 10125 ] |
Workflow | MariaDB v2 [ 58109 ] | MariaDB v3 [ 67169 ] |
Workflow | MariaDB v3 [ 67169 ] | MariaDB v4 [ 148396 ] |
The variables prohibited as a workaround.