long_query_time not respected when slow_query_log_use_global_control = all
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
Medium
|
George Ormond Lorch III | ||
5.1 |
Invalid
|
Undecided
|
Unassigned | ||
5.5 |
Fix Released
|
Medium
|
George Ormond Lorch III | ||
5.6 |
Fix Released
|
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.
OS: CentOS 6.2
# The my.cnf
%> cat /etc/my.cnf
[mysqld]
innodb_
innodb_
userstat = 0
slow_query_log = 1
slow_query_
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',
while true do
result = client.
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_
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=
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=
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=
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=
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=
show global variables like 'long_query_time';
# Time: 120623 17:04:56
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:04:57
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:04:58
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:04:59
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:00
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:01
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:02
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:03
# User@Host: query_test[
# 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=
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=
select unix_timestamp();
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:05
# User@Host: query_test[
# 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=
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=
set global long_query_
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:07
# User@Host: query_test[
# 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=
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=
select unix_timestamp();
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:09
# User@Host: query_test[
# 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=
SELECT SLEEP(1);
# Time: 120623 17:05:10
# User@Host: query_test[
# 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=
......
Related branches
- Alexey Kopytov (community): Approve
- Sergei Glushchenko (community): Approve (g2)
-
Diff: 64 lines (+37/-2)4 files modifiedmysql-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)
- Alexey Kopytov (community): Approve
- Sergei Glushchenko (community): Approve (g2)
-
Diff: 64 lines (+37/-2)4 files modifiedmysql-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)
Changed in percona-server: | |
importance: | Undecided → Medium |
tags: | added: contribution |
Changed in percona-server: | |
status: | New → Triaged |
tags: | added: slow-extended |
tags: | added: i36448 |
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}; slow_query_ log_use_ global_ control( sys_var */*self*/, THD */*thd*/,
enum_ var_type /*type*/) slow_query_ log_use_ global_ control & (ULL(1) << SLOG_UG_ALL)) slow_query_ log_use_ global_ control= UG_LOG_ SLOW_FILTER | SLOG_UG_ LOG_SLOW_ RATE_LIMIT | SLOG_UG_ LOG_SLOW_ VERBOSITY | UG_LONG_ QUERY_TIME | SLOG_UG_ MIN_EXAMINED_ ROW_LIMIT;
static bool update_
{
if(opt_
{
opt_
SLOG_
SLOG_
}
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:
======= ======= ======= ======= ======= ======= ======= ==== LOG_SLOW_ FILTER | SLOG_UG_ LOG_SLOW_ RATE_LIMIT | SLOG_UG_ LOG_SLOW_ VERBOSITY | LONG_QUERY_ TIME | SLOG_UG_ MIN_EXAMINED_ ROW_LIMIT; LOG_SLOW_ FILTER) | (1 << SLOG_UG_ LOG_SLOW_ RATE_LIMIT) | (1 << SLOG_UG_ LOG_SLOW_ VERBOSITY) | LONG_QUERY_ TIME) | (1 << SLOG_UG_ MIN_EXAMINED_ ROW_LIMIT) ;
3168,3169c3168,3169
< SLOG_UG_
< SLOG_UG_
---
> (1 << SLOG_UG_
> (1 << SLOG_UG_
======= ======= ======= ======= ======= ======= ======= ======= ==