percona-discussion team mailing list archive

Thread
Date

[Bug 375494] [NEW] log_slow_rate_limit logs all connections after a query > 1s runs

To: percona-discussion@xxxxxxxxxxxxxxxxxxx
From: Morgan Tocker <tocker@xxxxxxxxx>
Date: Tue, 12 May 2009 15:07:45 -0000
Reply-to: Bug 375494 <375494@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx

Public bug reported:

The log_slow_rate_limit should not log queries from all connections, but
it seems that after a 1 second threshold is tripped, all slow queries
from that session can potentially be logged.

To reproduce, set a my.cnf file to have something like:

log_slow_rate_limit=4
log_slow_verbosity=innodb,query_plan
long_query_time=0
log-slow-queries=/tmp/slow-log.log
log_queries_not_using_indexes=1

Then connect to the server:

$ mysql test

mysql> create table my_test (a int); # not logged
Query OK, 0 rows affected (0.01 sec)

mysql> select 1; # not logged
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

mysql> insert into my_test VALUES (SLEEP(1)); # logged!
Query OK, 1 row affected (1.01 sec)

mysql> select 1; # logged!
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

It seems to be anything over that one second threshold.  Here was my
original testcase:

mysql> create table t1 (id int not null primary key auto_increment, b char(255));
Query OK, 0 rows affected (0.82 sec)

mysql> insert into t1 VALUES (NULL, REPEAT('a', 255));
Query OK, 1 row affected (0.00 sec)

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 1 row affected (0.00 sec)
Records: 1 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 2 rows affected (0.00 sec)
Records: 2 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 4 rows affected (0.00 sec)
Records: 4 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 8 rows affected (0.00 sec)
Records: 8 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 16 rows affected (0.00 sec)
Records: 16 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 32 rows affected (0.00 sec)
Records: 32 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 64 rows affected (0.00 sec)
Records: 64 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 128 rows affected (0.00 sec)
Records: 128 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 256 rows affected (0.00 sec)
Records: 256 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 512 rows affected (0.00 sec)
Records: 512 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 1024 rows affected (0.00 sec)
Records: 1024 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 2048 rows affected (0.01 sec)
Records: 2048 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 4096 rows affected (0.02 sec)
Records: 4096 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 8192 rows affected (0.05 sec)
Records: 8192 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 16384 rows affected (0.13 sec)
Records: 16384 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 32768 rows affected (0.23 sec)
Records: 32768 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 65536 rows affected (0.47 sec)
Records: 65536 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1; # logged
Query OK, 131072 rows affected (1.02 sec)
Records: 131072 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1; # logged
Query OK, 262144 rows affected (2.03 sec)
Records: 262144 Duplicates: 0 Warnings: 0

mysql> SELECT 1; # logged
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

** Affects: percona-patches
     Importance: Undecided
         Status: New

-- 
log_slow_rate_limit logs all connections after a query > 1s runs
https://bugs.launchpad.net/bugs/375494
You received this bug notification because you are a member of Percona
developers, which is the registrant for Percona patches.

Status in Patches for MySQL by Percona: New

Bug description:
The log_slow_rate_limit should not log queries from all connections, but it seems that after a 1 second threshold is tripped, all slow queries from that session can potentially be logged.

To reproduce, set a my.cnf file to have something like:

log_slow_rate_limit=4
log_slow_verbosity=innodb,query_plan
long_query_time=0
log-slow-queries=/tmp/slow-log.log
log_queries_not_using_indexes=1

Then connect to the server:

$ mysql test

mysql> create table my_test (a int); # not logged
Query OK, 0 rows affected (0.01 sec)

mysql> select 1; # not logged
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

mysql> insert into my_test VALUES (SLEEP(1)); # logged!
Query OK, 1 row affected (1.01 sec)

mysql> select 1; # logged!
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

It seems to be anything over that one second threshold.  Here was my original testcase:

mysql> create table t1 (id int not null primary key auto_increment, b char(255));
Query OK, 0 rows affected (0.82 sec)

mysql> insert into t1 VALUES (NULL, REPEAT('a', 255));
Query OK, 1 row affected (0.00 sec)

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 1 row affected (0.00 sec)
Records: 1 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 2 rows affected (0.00 sec)
Records: 2 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 4 rows affected (0.00 sec)
Records: 4 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 8 rows affected (0.00 sec)
Records: 8 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 16 rows affected (0.00 sec)
Records: 16 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 32 rows affected (0.00 sec)
Records: 32 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 64 rows affected (0.00 sec)
Records: 64 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 128 rows affected (0.00 sec)
Records: 128 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 256 rows affected (0.00 sec)
Records: 256 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 512 rows affected (0.00 sec)
Records: 512 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 1024 rows affected (0.00 sec)
Records: 1024 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 2048 rows affected (0.01 sec)
Records: 2048 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 4096 rows affected (0.02 sec)
Records: 4096 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 8192 rows affected (0.05 sec)
Records: 8192 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 16384 rows affected (0.13 sec)
Records: 16384 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 32768 rows affected (0.23 sec)
Records: 32768 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1;
Query OK, 65536 rows affected (0.47 sec)
Records: 65536 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1; # logged
Query OK, 131072 rows affected (1.02 sec)
Records: 131072 Duplicates: 0 Warnings: 0

mysql> insert into t1 SELECT NULL, REPEAT('a', 255) FROM t1; # logged
Query OK, 262144 rows affected (2.03 sec)
Records: 262144 Duplicates: 0 Warnings: 0

mysql> SELECT 1; # logged
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

Follow ups

[Bug 375494] Re: log_slow_rate_limit logs all queries on a connection after a >1s query
From: Launchpad Bug Tracker, 2009-05-28
[Bug 375494] Re: log_slow_rate_limit logs all queries on a connection after a >1s query
From: Yasufumi Kinoshita, 2009-05-27
[Bug 375494] Re: log_slow_rate_limit logs all queries on a connection after a >1s query
From: Vadim Tkachenko, 2009-05-27
[Bug 375494] Re: log_slow_rate_limit logs all queries on a connection after a >1s query
From: Vadim Tkachenko, 2009-05-19
[Bug 375494] Re: log_slow_rate_limit logs all queries on a connection after a >1s query
From: Morgan Tocker, 2009-05-14
[Bug 375494] [NEW] log_slow_rate_limit logs all connections after a query > 1s runs
From: Morgan Tocker, 2009-05-12

References

[Bug 375494] [NEW] log_slow_rate_limit logs all connections after a query > 1s runs
From: Morgan Tocker, 2009-05-12