Percona Server moved to https://jira.percona.com/projects/PS

Time in slow query log displayed incorrectly when slow_query_log_microseconds_timestamp enabled

Bug #887928 reported by Aurimas Mikalauskas
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.5.29-30.0
5.1
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.1.67-14.4
5.5
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.5.29-30.0

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

Related branches

lp:~laurynas-biveinis/percona-server/slow-log-fixes-5.1
Stewart Smith (community): Approve
Diff: 20056 lines (+9597/-9871)
52 files modified
Percona-Server/mysql-test/include/log_cleanup.inc (+1/-0)
Percona-Server/mysql-test/include/log_start.inc (+3/-8)
Percona-Server/mysql-test/include/log_stop.inc (+2/-2)
Percona-Server/mysql-test/include/percona_slow_extended_error_on_quit.inc (+0/-50)
Percona-Server/mysql-test/include/percona_slow_log_verbosity_grep.inc (+26/-0)
Percona-Server/mysql-test/r/percona_bug643149.result (+2/-2)
Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result (+15/-6)
Percona-Server/mysql-test/r/percona_log_slow_filter.result (+0/-15)
Percona-Server/mysql-test/r/percona_log_slow_innodb.result (+42/-0)
Percona-Server/mysql-test/r/percona_log_slow_query_plan.result (+202/-0)
Percona-Server/mysql-test/r/percona_log_slow_query_plan_qc.result (+35/-0)
Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result (+6/-1)
Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result (+16/-36)
Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result (+20/-19)
Percona-Server/mysql-test/r/percona_log_slow_timestamp_every.result (+13/-39)
Percona-Server/mysql-test/r/percona_log_slow_verbosity.result (+111/-16)
Percona-Server/mysql-test/r/percona_long_query_time.result (+2/-0)
Percona-Server/mysql-test/r/percona_mysqldumpslow.result (+8100/-9094)
Percona-Server/mysql-test/r/percona_slow_extended_error_on_quit.result (+20/-168)
Percona-Server/mysql-test/r/percona_slow_extended_log_error.result (+14/-0)
Percona-Server/mysql-test/r/percona_slow_query_log_microseconds_timestamp.result (+17/-17)
Percona-Server/mysql-test/r/percona_use_global_log_slow_control.result (+2/-0)
Percona-Server/mysql-test/r/percona_use_global_long_query_time.result (+2/-0)
Percona-Server/mysql-test/t/disabled.def (+1/-0)
Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test (+41/-2)
Percona-Server/mysql-test/t/percona_log_slow_filter.test (+0/-26)
Percona-Server/mysql-test/t/percona_log_slow_innodb.test (+82/-0)
Percona-Server/mysql-test/t/percona_log_slow_query_plan.test (+302/-0)
Percona-Server/mysql-test/t/percona_log_slow_query_plan_qc.test (+71/-0)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt (+0/-1)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test (+16/-16)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements-slave.opt (+0/-1)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test (+50/-101)
Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test (+34/-20)
Percona-Server/mysql-test/t/percona_log_slow_timestamp_every.test (+17/-29)
Percona-Server/mysql-test/t/percona_log_slow_verbosity.test (+75/-19)
Percona-Server/mysql-test/t/percona_long_query_time.test (+4/-0)
Percona-Server/mysql-test/t/percona_min_examined_row_limit.test (+1/-0)
Percona-Server/mysql-test/t/percona_mysqldumpslow.test (+59/-24)
Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test (+58/-74)
Percona-Server/mysql-test/t/percona_slow_extended_log_error.test (+31/-0)
Percona-Server/mysql-test/t/percona_slow_query_log_microseconds_timestamp.test (+36/-24)
Percona-Server/mysql-test/t/percona_use_global_log_slow_control.test (+4/-1)
Percona-Server/mysql-test/t/percona_use_global_long_query_time.test (+5/-0)
Percona-Server/scripts/mysqldumpslow.sh (+3/-3)
Percona-Server/sql/event_scheduler.cc (+0/-1)
Percona-Server/sql/log.cc (+48/-22)
Percona-Server/sql/log_event.cc (+5/-9)
Percona-Server/sql/slave.cc (+1/-2)
Percona-Server/sql/sql_class.h (+0/-13)
Percona-Server/sql/sql_connect.cc (+0/-9)
Percona-Server/sql/sql_parse.cc (+2/-1)
lp:~laurynas-biveinis/percona-server/slow-log-fixes-5.5
Stewart Smith (community): Approve
Diff: 3690 lines (+1002/-1194)
55 files modified
Percona-Server/mysql-test/include/log_cleanup.inc (+1/-0)
Percona-Server/mysql-test/include/log_start.inc (+0/-16)
Percona-Server/mysql-test/include/log_stop.inc (+0/-7)
Percona-Server/mysql-test/include/percona_slow_extended_error_on_quit.inc (+0/-50)
Percona-Server/mysql-test/include/percona_slow_log_verbosity_grep.inc (+26/-0)
Percona-Server/mysql-test/include/percona_slow_query_log_rate.inc (+5/-10)
Percona-Server/mysql-test/r/mysqld--help-notwin.result (+2/-2)
Percona-Server/mysql-test/r/percona_bug643149.result (+0/-21)
Percona-Server/mysql-test/r/percona_log_slow_admin_statements.result (+0/-35)
Percona-Server/mysql-test/r/percona_log_slow_filter.result (+0/-16)
Percona-Server/mysql-test/r/percona_log_slow_innodb.result (+42/-0)
Percona-Server/mysql-test/r/percona_log_slow_query_plan.result (+268/-0)
Percona-Server/mysql-test/r/percona_log_slow_query_plan_qc.result (+46/-0)
Percona-Server/mysql-test/r/percona_log_slow_slave_statements-innodb.result (+0/-19)
Percona-Server/mysql-test/r/percona_log_slow_slave_statements.result (+0/-45)
Percona-Server/mysql-test/r/percona_log_slow_sp_statements.result (+0/-25)
Percona-Server/mysql-test/r/percona_log_slow_verbosity.result (+0/-16)
Percona-Server/mysql-test/r/percona_long_query_time.result (+0/-33)
Percona-Server/mysql-test/r/percona_min_examined_row_limit.result (+1/-1)
Percona-Server/mysql-test/r/percona_slow_extended_error_on_quit.result (+23/-168)
Percona-Server/mysql-test/r/percona_slow_extended_log_error.result (+0/-10)
Percona-Server/mysql-test/r/percona_slow_query_log_rate.result (+45/-69)
Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_always.result (+0/-41)
Percona-Server/mysql-test/r/percona_slow_query_log_timestamp_precision.result (+0/-18)
Percona-Server/mysql-test/r/percona_slow_query_log_use_global_control.result (+0/-18)
Percona-Server/mysql-test/t/disabled.def (+1/-0)
Percona-Server/mysql-test/t/percona_log_slow_admin_statements.test (+0/-20)
Percona-Server/mysql-test/t/percona_log_slow_filter.test (+0/-26)
Percona-Server/mysql-test/t/percona_log_slow_innodb.test (+82/-0)
Percona-Server/mysql-test/t/percona_log_slow_query_plan.test (+302/-0)
Percona-Server/mysql-test/t/percona_log_slow_query_plan_qc.test (+71/-0)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb-slave.opt (+0/-1)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements-innodb.test (+0/-42)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements-slave.opt (+0/-1)
Percona-Server/mysql-test/t/percona_log_slow_slave_statements.test (+0/-117)
Percona-Server/mysql-test/t/percona_log_slow_sp_statements.test (+0/-29)
Percona-Server/mysql-test/t/percona_log_slow_verbosity.test (+0/-19)
Percona-Server/mysql-test/t/percona_long_query_time.test (+0/-25)
Percona-Server/mysql-test/t/percona_min_examined_row_limit.test (+0/-35)
Percona-Server/mysql-test/t/percona_slow_extended_error_on_quit.test (+0/-87)
Percona-Server/mysql-test/t/percona_slow_extended_log_error.test (+0/-15)
Percona-Server/mysql-test/t/percona_slow_query_log_rate.test (+10/-3)
Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_always.test (+0/-34)
Percona-Server/mysql-test/t/percona_slow_query_log_timestamp_precision.test (+0/-25)
Percona-Server/mysql-test/t/percona_slow_query_log_use_global_control.test (+0/-28)
Percona-Server/sql/event_scheduler.cc (+0/-1)
Percona-Server/sql/log.cc (+49/-23)
Percona-Server/sql/log_event.cc (+1/-1)
Percona-Server/sql/slave.cc (+1/-2)
Percona-Server/sql/sql_class.cc (+0/-5)
Percona-Server/sql/sql_class.h (+8/-20)
Percona-Server/sql/sql_connect.cc (+0/-8)
Percona-Server/sql/sql_parse.cc (+15/-5)
Percona-Server/sql/sys_vars.cc (+2/-1)
Percona-Server/storage/innobase/handler/ha_innodb.cc (+1/-1)
Oleg Tsarev (tsarev)
Changed in percona-server:
assignee: nobody → Oleg Tsarev (tsarev)
Stewart Smith (stewart)
Changed in percona-server:
importance: Undecided → Medium
Stewart Smith (stewart)
Changed in percona-server:
assignee: Oleg Tsarev (tsarev) → nobody
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

%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)
Changed in percona-server:
status: Confirmed → Triaged
importance: Medium → High
tags: added: low-hanging-fruit
Laurynas Biveinis (laurynas-biveinis)
tags: added: slow-extended
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

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.

Laurynas Biveinis (laurynas-biveinis)
no longer affects: percona-server/5.6
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-512

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.