Bug #73978 slow_log table doesn't store fractional time part

• Submitted: 19 Sep 2014 10:14
• Modified: 19 Nov 2014 8:15
• Reporter: Eduardo Cortes
• Status: Closed
• Category: MySQL Server: Logging
• Severity: S3 (Non-critical)
• Version: 5.6.15, 5.6.20
• OS: Any
• CPU Architecture: Any

[19 Sep 2014 10:14] Eduardo Cortes

Description:
When log_output='TABLE', slow_log table use time type, which can store fractional part since 5.6.4, but it discards the data instead of inserting it

This information is already logged when using log_output='FILE', it is expected to get the same information in the file and the table nevertheless the table option is discarding the fractional time part.

From http://dev.mysql.com/doc/refman/5.6/en/time.html

"In particular, as of MySQL 5.6.4, any fractional part in a value inserted into a TIME column is stored rather than discarded. With the fractional part included, the range for TIME values is '-838:59:59.000000' to '838:59:59.000000'."

mysql> select time_format(query_time, '%s.%f') from mysql.slow_log;
+----------------------------------+
| time_format(query_time, '%s.%f') |
+----------------------------------+
| 05.000000                        |
| 31.000000                        |
+----------------------------------+
2 rows in set (0.00 sec)

From slow-log file:
# Query_time: 5.180930 
# Query_time: 31.803881

How to repeat:
mysql> set global log_output='TABLE';
mysql> set global slow_query_log=ON;
mysql> set global long_query_time=1;

launch some query that will take more than 1 second.

mysql> select time_format(query_time, '%s.%f') from mysql.slow_log;

Suggested fix:
Change the log function to store the time fractional part, it is logged when settings are configured to log to a file (log_ouput='FILE')

[19 Sep 2014 11:23] MySQL Verification Team

Hello Eduardo,

Thank you for the report.

Thanks,
Umesh

[19 Sep 2014 11:23] MySQL Verification Team

// with 5.6.20

set global log_output='FILE';
set global slow_query_log=ON;
set global long_query_time=0;

show global variables like 'log_output';

create database if not exists test;
use test;
drop table if exists t1;
create table t1(id int not null auto_increment primary key,name varchar(100));
insert into t1(name) values('A'),('A'),('A');
insert into t1(name) select name from t1;
select sleep(1) from dual;

mysql> select sleep(1) from dual;
+----------+
| sleep(1) |
+----------+
|        0 |
+----------+
1 row in set (1.00 sec)

mysql> \! more /tmp/master/cluster-repo-slow.log

# Time: 140921  7:44:19
# User@Host: root[root] @ localhost []  Id:   452
# Query_time: 1.000276  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1411265659;
select sleep(1) from dual;

mysql> select sleep(2) from dual;
+----------+
| sleep(2) |
+----------+
|        0 |
+----------+
1 row in set (2.00 sec)

mysql> \! more /tmp/master/cluster-repo-slow.log

# Time: 140921  7:45:33
# User@Host: root[root] @ localhost []  Id:   452
# Query_time: 2.000278  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1411265733;
select sleep(2) from dual;

set global log_output='TABLE';
set global slow_query_log=ON;
set global long_query_time=0;

show global variables like 'log_output';

select sleep(1) from dual;
select sleep(2) from dual;

select time_format(query_time, '%s.%f') from mysql.slow_log;
select query_time from mysql.slow_log;

mysql> select sleep(1) from dual;
+----------+
| sleep(1) |
+----------+
|        0 |
+----------+
1 row in set (1.00 sec)

mysql> select sleep(2) from dual;
+----------+
| sleep(2) |
+----------+
|        0 |
+----------+
1 row in set (2.00 sec)

mysql> select time_format(query_time, '%s.%f') from mysql.slow_log;
+----------------------------------+
| time_format(query_time, '%s.%f') |
+----------------------------------+
| 01.000000                        |
| 02.000000                        |
+----------------------------------+
8 rows in set (0.00 sec)

mysql> select query_time from mysql.slow_log;
+------------+
| query_time |
+------------+
| 00:00:01   |
| 00:00:02   |
+------------+

[19 Nov 2014 8:13] Ståle Deraas

Fixed in 5.7 by WL#6661:

mysql>  select time_format(query_time, '%s.%f') from mysql.slow_log;
+----------------------------------+
| time_format(query_time, '%s.%f') |
+----------------------------------+
| 00.000411                        |
| 02.000664                        |
| 00.001046                        |
+----------------------------------+
3 rows in set (0,00 sec)

mysql> select version();
+---------------------+
| version()           |
+---------------------+
| 5.7.6-m16-debug-log |
+---------------------+
1 row in set (0,00 sec)

[19 Nov 2014 8:15] Ståle Deraas

Fixed in 5.7.2

[1 Dec 2014 7:23] jia liu

Can this feature backport to 5.6?