Percona Server with XtraDB

Time in slow query log displayed incorrectly when slow_query_log_microseconds_timestamp enabled

Reported by Aurimas Mikalauskas on 2011-11-09
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server
High
Laurynas Biveinis
5.1
High
Laurynas Biveinis
5.5
High
Laurynas Biveinis

Bug Description

When slow_query_log_microseconds_timestamp is enabled, I get four leading zeroes in what should be microseconds in the # Time line in slow query log:

# grep -B 2 '^# Thread_id: 1927989' /var/lib/mysql/slow-query.log | grep '^# Time'
# Time: 111109 1:35:45.0000519855
# Time: 111109 1:35:45.0000651195
# Time: 111109 1:35:45.0000780475
# Time: 111109 1:35:45.0000797051
# Time: 111109 1:35:45.0000812461
# Time: 111109 1:35:45.0000920200
# Time: 111109 1:35:46.0000050173
# Time: 111109 1:35:46.0000275315
# Time: 111109 1:35:46.0000435252

Server version: 5.1.59-rel13.0-log Percona Server (GPL), 13.0, Revision 325

$ cat /etc/redhat-release
CentOS release 5.7 (Final)

$ uname -a
Linux localhost 2.6.18-194.26.1.el5 #1 SMP Tue Nov 9 12:54:20 EST 2010 x86_64 x86_64 x86_64 GNU/Linux

mysql> show global variables like '%slow%';
+---------------------------------------+---------------------------------+
| Variable_name | Value |
+---------------------------------------+---------------------------------+
| log_slow_admin_statements | OFF |
| log_slow_filter | |
| log_slow_queries | OFF |
| log_slow_rate_limit | 1 |
| log_slow_slave_statements | OFF |
| log_slow_sp_statements | ON |
| log_slow_timestamp_every | ON |
| log_slow_verbosity | microtime,query_plan,innodb |
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/mysql/slow-query.log |
| slow_query_log_microseconds_timestamp | ON |
| use_global_log_slow_control | none |
+---------------------------------------+---------------------------------+
13 rows in set (0.00 sec)

Obviously slow query logging is set to off now and it was on before, but that's the only difference in the config.

As a workaround, I process the slow query log with sed to get it look right, but that's one more pass on the slow query log:

sed 's/^# Time: \([0-9]\{6\}\)\([ ]\+\)\([0-9]\+:[0-9]\+:[0-9]\+\)\(.0000\)/# Time: \1\2\3./g' < in > out

Oleg Tsarev (tsarev) on 2011-11-09
Changed in percona-server:
assignee: nobody → Oleg Tsarev (tsarev)
Stewart Smith (stewart) on 2012-02-07
Changed in percona-server:
importance: Undecided → Medium
Stewart Smith (stewart) on 2012-03-27
Changed in percona-server:
assignee: Oleg Tsarev (tsarev) → nobody

%010lld is used to print it, hence padding. It should be %06lld instead. (also ulonglong is used to store it which is probably not required)

Changed in percona-server:
status: New → Confirmed
Stewart Smith (stewart) on 2012-12-10
Changed in percona-server:
status: Confirmed → Triaged
importance: Medium → High
tags: added: low-hanging-fruit
tags: added: slow-extended

The testcase that was supposed to test this used too lax a regexp for microsecond check in the output. Also, there is no need to use query_exec_time and limit it to debug builds only.

no longer affects: percona-server/5.6
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers