Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-7006

SET STATEMENT does not work with slow log tuning (long_query_time, log_slow_filter, log_slow_verbosity, log_slow_rate_limit)

Details

    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

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-7007 SET STATEMENT slow_query_log has no effect

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-7009 SET STATEMENT min_examined_row_limit has no effect

          • Major - Major loss of function.
          • Closed

          Task - A task that needs to be done. MDEV-5231 Per query variables from Percona Server [patch]

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Technical task - A technical task. MDEV-6923 Testing for SET STATEMENT .. FOR (MDEV-5231, per-query variables)

          • Major - Major loss of function.
          • Closed
          links to

          Web Link Bug#1388632 - SET STATEMENT does not work with slow log tuning (long_query_time, log_slow_filter, log_slow_verbosity, log_slow_rate_limit)

          Activity

            Ascending order - Click to sort in descending order
            sanja Oleksandr Byelkin added a comment -

            The variables prohibited as a workaround.

            sanja Oleksandr Byelkin added a comment - The variables prohibited as a workaround.
            sanja Oleksandr Byelkin added a comment -

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

            sanja Oleksandr Byelkin added a comment - Here (as well as all bugs connected to slow log) cause is that we write slow log after restoring variables values.
            sanja Oleksandr Byelkin added a comment -

            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

            sanja Oleksandr Byelkin added a comment - 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
            sanja Oleksandr Byelkin added a comment -

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

            sanja Oleksandr Byelkin added a comment - The review mail is answered, fix according to the review commited
            sanja Oleksandr Byelkin added a comment -

            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

            sanja Oleksandr Byelkin added a comment - 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
            serg Sergei Golubchik added a comment -

            ok to push

            serg Sergei Golubchik added a comment - ok to push
            danblack Daniel Black added a comment -

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

            danblack Daniel Black added a comment - ref: https://github.com/MariaDB/server/commit/a71e2d23bd08ca041a953df44f2235a8ef20bfcc

            People

              sanja Oleksandr Byelkin
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.