long_query_time not respected when slow_query_log_use_global_control = all

Bug #1016991 reported by Ryan Lowe on 2012-06-23
64
This bug affects 11 people
Affects Status Importance Assigned to Milestone
Percona Server
Status tracked in 5.6
5.1
Undecided
Unassigned
5.5
Medium
George Ormond Lorch III
5.6
Medium
George Ormond Lorch III

Bug Description

Queries that no longer exceed long_query_time continue to be written to the slow query log if they matched the previous long_query_time value.

Percona-Server version: 55-5.5.24-rel26.0.256.rhel6.x86_64
OS: CentOS 6.2

# The my.cnf
%> cat /etc/my.cnf
[mysqld]
innodb_file_per_table
innodb_buffer_pool_size = 16G
userstat = 0
slow_query_log = 1
slow_query_log_use_global_control = all
long_query_time = 0

# The script used to test
%> cat select_sleep.rb
#!/usr/bin/ruby

require 'rubygems'
require 'mysql2'

client = Mysql2::Client.new( :host => 'localhost',
                             :username => 'query_test',
                             :password => 'password');

while true do
  result = client.query("SELECT SLEEP(1)")
end

# The test
screen1 %> ruby select_sleep.rb
mysql> select unix_timestamp();
+------------------+
| unix_timestamp() |
+------------------+
| 1340471088 |
+------------------+
1 row in set (0.00 sec)

mysql> show global variables like 'long_query_time';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 0.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

mysql> select unix_timestamp();
+------------------+
| unix_timestamp() |
+------------------+
| 1340471104 |
+------------------+
1 row in set (0.00 sec)

mysql> set global long_query_time=2000000;
Query OK, 0 rows affected (0.00 sec)

mysql> select unix_timestamp();
+------------------+
| unix_timestamp() |
+------------------+
| 1340471108 |
+------------------+
1 row in set (0.00 sec)

mysql> show global variables like 'long_query_time';
+-----------------+----------------+
| Variable_name | Value |
+-----------------+----------------+
| long_query_time | 2000000.000000 |
+-----------------+----------------+
1 row in set (0.00 sec)

# Meanwhile, here are the contents of the slow log (note the timestamps):

/usr/sbin/mysqld, Version: 5.5.24-55-log (Percona Server (GPL), Release rel26.0, Revision 256). start
ed with:
Tcp port: 0 Unix socket: (null)
Time Id Command Argument
# Time: 120623 17:04:22
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000270 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 122 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471062;
select @@version_comment limit 1;
# Time: 120623 17:04:33
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000995 Lock_time: 0.000207 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 221 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471073;
show global variables like 'long_query_time';
# Time: 120623 17:04:46
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 1054 Killed: 0
# Query_time: 0.000116 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 60 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471086;
select unix_timestamp;
# Time: 120623 17:04:48
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000097 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 80 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471088;
select unix_timestamp();
# Time: 120623 17:04:52
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000714 Lock_time: 0.000102 Rows_sent: 1 Rows_examined: 1 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 221 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471092;
show global variables like 'long_query_time';
# Time: 120623 17:04:56
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000289 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471096;
SELECT SLEEP(1);
# Time: 120623 17:04:57
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000167 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471097;
SELECT SLEEP(1);
# Time: 120623 17:04:58
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000172 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471098;
SELECT SLEEP(1);
# Time: 120623 17:04:59
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000164 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471099;
SELECT SLEEP(1);
# Time: 120623 17:05:00
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000177 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471100;
SELECT SLEEP(1);
# Time: 120623 17:05:01
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000173 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471101;
SELECT SLEEP(1);
# Time: 120623 17:05:02
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000178 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471102;
SELECT SLEEP(1);
# Time: 120623 17:05:03
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000177 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471103;
SELECT SLEEP(1);
# Time: 120623 17:05:04
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000114 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 80 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471104;
select unix_timestamp();
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000178 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471104;
SELECT SLEEP(1);
# Time: 120623 17:05:05
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000175 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471105;
SELECT SLEEP(1);
# Time: 120623 17:05:06
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000123 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0
# Bytes_sent: 11 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471106;
set global long_query_time=2000000;
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000184 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471106;
SELECT SLEEP(1);
# Time: 120623 17:05:07
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000171 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471107;
SELECT SLEEP(1);
# Time: 120623 17:05:08
# User@Host: root[root] @ localhost []
# Thread_id: 1 Schema: Last_errno: 0 Killed: 0
# Query_time: 0.000080 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 80 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471108;
select unix_timestamp();
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000180 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471108;
SELECT SLEEP(1);
# Time: 120623 17:05:09
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000172 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471109;
SELECT SLEEP(1);
# Time: 120623 17:05:10
# User@Host: query_test[query_test] @ localhost []
# Thread_id: 2 Schema: Last_errno: 0 Killed: 0
# Query_time: 1.000172 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 Rows_read: 1
# Bytes_sent: 63 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
SET timestamp=1340471110;
......

Related branches

lp:~gl-az/percona-server/bug1016991-5.5
Merged into lp:percona-server/5.5 at revision 644
Alexey Kopytov: Approve on 2014-03-19
Sergei Glushchenko: Approve (g2) on 2014-03-18
lp:~gl-az/percona-server/bug1016991-5.6
Merged into lp:percona-server at revision 565
Alexey Kopytov: Approve on 2014-03-19
Sergei Glushchenko: Approve (g2) on 2014-03-18
Stewart Smith (stewart) on 2012-06-25
Changed in percona-server:
importance: Undecided → Medium

It is broken because the ON_UPDATE for slow_query_log_use_global_control is broken.

From sql/sys_vars.cc:

===============

const char *slow_query_log_use_global_control_name[]= { "log_slow_filter", "log_slow_rate_limit", "log_slow_verbosity", "long_query_time", "min_examined_row_limit", "all", 0};
static bool update_slow_query_log_use_global_control(sys_var */*self*/, THD */*thd*/,
                                               enum_var_type /*type*/)
{
  if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL))
  {
    opt_slow_query_log_use_global_control=
      SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
      SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
  }
  return false;
}

================

When set to all, opt_slow_query_log_use_global_control ends up with value of 7 (0 | 1 | 2 | 3 | 4) instead of the intended value of 32.

Following is the fix:

=====================================================
3168,3169c3168,3169
< SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
< SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
---
> (1 << SLOG_UG_LOG_SLOW_FILTER) | (1 << SLOG_UG_LOG_SLOW_RATE_LIMIT) | (1 << SLOG_UG_LOG_SLOW_VERBOSITY) |
> (1 << SLOG_UG_LONG_QUERY_TIME) | (1 << SLOG_UG_MIN_EXAMINED_ROW_LIMIT);

==========================================================

Correction: I meant intended value of 31 (not 32).

Patch in unified mode:

--- sql/sys_vars.cc 2012-07-17 22:27:15.000000000 +0530
+++ /tmp/sys_vars.cc 2012-08-07 01:30:33.254952431 +0530
@@ -3165,8 +3165,8 @@
   if(opt_slow_query_log_use_global_control & (ULL(1) << SLOG_UG_ALL))
   {
     opt_slow_query_log_use_global_control=
- SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY |
- SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT;
+ (1 << SLOG_UG_LOG_SLOW_FILTER) | (1 << SLOG_UG_LOG_SLOW_RATE_LIMIT) | (1 << SLOG_UG_LOG_SLOW_VERBOSITY) |
+ (1 << SLOG_UG_LONG_QUERY_TIME) | (1 << SLOG_UG_MIN_EXAMINED_ROW_LIMIT);
   }
   return false;
 }

tags: added: contribution

This doesn't affect 5.1 though.

It is defined correctly there (as in the patch above)

#define SLOG_UG_NONE (1UL << 0)
#define SLOG_UG_LOG_SLOW_FILTER (1UL << 1)
#define SLOG_UG_LOG_SLOW_RATE_LIMIT (1UL << 2)
#define SLOG_UG_LOG_SLOW_VERBOSITY (1UL << 3)
#define SLOG_UG_LONG_QUERY_TIME (1UL << 4)
#define SLOG_UG_MIN_EXAMINED_ROW_LIMIT (1UL << 5)
#define SLOG_UG_ALL SLOG_UG_LOG_SLOW_FILTER | SLOG_UG_LOG_SLOW_RATE_LIMIT | SLOG_UG_LOG_SLOW_VERBOSITY | SLOG_UG_LONG_QUERY_TIME | SLOG_UG_MIN_EXAMINED_ROW_LIMIT

Each of the SLOG* are enum in 5.5 and (0..) instead of (1UL << 0, ...).

Changed in percona-server:
status: New → Triaged
tags: added: slow-extended
Kenny Gryp (gryp) wrote :

It also affects 5.5.28-29.2 and 5.5.30-30.2.

Jervin R (revin) wrote :

Also on 5.5.33-31.1, for the record setting slow_query_log_use_global_control to 'log_slow_filter,log_slow_rate_limit,log_slow_verbosity,long_query_time,min_examined_row_limit' reduces the logging but I still see some < long_query_time queries being logged where server is not slave and those queries have indexes (PK lookups).

tags: added: i36448

Likewise min_examined_row_limit, see bug 1245559.

George Ormond Lorch III (gl-az) wrote :

On review I agree w/ Raghu, does not affect 5.1 and cause is the change over from define to enum in 5.5 without correcting the shifting.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers