MySQL Bugs: #12831: long_query_time is flawed because it is an integer

Bug #12831	long_query_time is flawed because it is an integer
Submitted:	26 Aug 2005 13:21	Modified:	2 Apr 2008 13:50
Reporter:	Peter van Dijk	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	4.1.13/BK 4.1 source	OS:	Any (5.4)
Assigned to:		CPU Architecture:	Any

Description:
Query time as noted in the slow query log can flap between neighbouring second counts for the same measured query, because it is measured as the difference between two integer second timestamps. This means that a query that (in my experiments) took 0.39 seconds will sometimes be considered a 0-second query and sometimes a 1-second query.

On a sidenote, specifying '1' as long_query_time in my.cnf will only log queries that take -2- or more seconds, by the metric given above. I suggest changing >= to > in the relevant if() in sql_parse.cc. That would also open up a way to log -every- query to the slow query log (which has more detail like rows_examined than the normal log), by specifying '0' as a lower bound.

How to repeat:
Set long_query_time to some boundary, for example 3. Repeatedly execute a query that takes between 3 and 4 seconds, and observe how it will sometimes end up in the slow query log, and sometimes won't.

# The MySQL server
[mysqld]
port            = 3306

<cut>

log-slow-queries=/home/miguel/dbs/4.1/test.log
long_query_time = 14

<cut>                                                            

miguel@hegel:~/dbs/4.1> bin/mysql -uroot db1
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 4.1.15-debug-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> select * from tb1 where name like "BCD";

16 rows in set (13.80 sec)

mysql> select * from tb1 where name like "BCD";

16 rows in set (14.73 sec)

miguel@hegel:~/dbs/4.1> cat test.log 
libexec/mysqld, Version: 4.1.15-debug-log. started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument

16 rows in set (14.73 sec) wasn't logged

mysql> select * from tb1 where name like "BCD";

16 rows in set (14.61 sec)

the above was logged as showed below:

miguel@hegel:~/dbs/4.1> cat test.log 
libexec/mysqld, Version: 4.1.15-debug-log. started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 050829 18:08:14
# User@Host: root[root] @ localhost []
# Query_time: 15  Lock_time: 0  Rows_sent: 16  Rows_examined: 1572896
use db1;
select * from tb1 where name like "BCD";

Will be fixed in 5.1 most probably where the slow log will have microseconds resolution.

Unfortunately not in the 5.1 feature list, will be fixed in further version.

> Will be fixed in 5.1 most probably where the slow log will have microseconds resolution.

> Unfortunately not in the 5.1 feature list, will be fixed in further version.

Argh, please?

Thank you for your bug report. This issue has already been fixed in the latest released version of that product, which you can download at

  http://www.mysql.com/downloads/

See http://dev.mysql.com/doc/refman/5.1/en/slow-query-log.html
"
Prior to MySQL 5.1.21, the minimum value [of long_query_time] is 1, and the value for this variable must be an integer. Beginning with MySQL 5.1.21, the minimum is 0, and a resolution of microseconds is supported
"