Percona Server moved to https://jira.percona.com/projects/PS

long_query_time not respected when slow_query_log_use_global_control = all

Bug #1016991 reported by Ryan Lowe
64
This bug affects 11 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
George Ormond Lorch III
Percona Server moved to https://jira.percona.com/projects/PS 5.6.17-65.0
5.1
Invalid
Undecided
Unassigned
5.5
Fix Released
Medium
George Ormond Lorch III
Percona Server moved to https://jira.percona.com/projects/PS 5.5.37-35.0
5.6
Fix Released
Medium
George Ormond Lorch III
Percona Server moved to https://jira.percona.com/projects/PS 5.6.17-65.0

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
Alexey Kopytov (community): Approve
Sergei Glushchenko (community): Approve (g2)
Diff: 64 lines (+37/-2)
4 files modified
mysql-test/r/percona_bug1016991.result (+13/-0)
mysql-test/t/percona_bug1016991-master.opt (+1/-0)
mysql-test/t/percona_bug1016991.test (+20/-0)
sql/sys_vars.cc (+3/-2)
lp:~gl-az/percona-server/bug1016991-5.6
Alexey Kopytov (community): Approve
Sergei Glushchenko (community): Approve (g2)
Diff: 64 lines (+37/-2)
4 files modified
mysql-test/r/percona_bug1016991.result (+13/-0)
mysql-test/t/percona_bug1016991-master.opt (+1/-0)
mysql-test/t/percona_bug1016991.test (+20/-0)
sql/sys_vars.cc (+3/-2)
Stewart Smith (stewart)
Changed in percona-server:
importance: Undecided → Medium
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

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);

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

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

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

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

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;
 }

Laurynas Biveinis (laurynas-biveinis)
tags: added: contribution
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

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, ...).

Vadim Tkachenko (vadim-tk)
Changed in percona-server:
status: New → Triaged
Laurynas Biveinis (laurynas-biveinis)
tags: added: slow-extended
Revision history for this message
Kenny Gryp (gryp) wrote :

It also affects 5.5.28-29.2 and 5.5.30-30.2.

Revision history for this message
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).

Valerii Kravchuk (valerii-kravchuk)
tags: added: i36448
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Likewise min_examined_row_limit, see bug 1245559.

Revision history for this message
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.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-137

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

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.