Time in slow query log displayed incorrectly when slow_query_log_microseconds_timestamp enabled
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
High
|
Laurynas Biveinis | ||
5.1 |
Fix Released
|
High
|
Laurynas Biveinis | ||
5.5 |
Fix Released
|
High
|
Laurynas Biveinis |
Bug Description
When slow_query_
# grep -B 2 '^# Thread_id: 1927989' /var/lib/
# 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_
| log_slow_filter | |
| log_slow_queries | OFF |
| log_slow_rate_limit | 1 |
| log_slow_
| log_slow_
| log_slow_
| log_slow_verbosity | microtime,
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /var/lib/
| slow_query_
| use_global_
+------
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\}\)\([ ]\+\)\(
Related branches
- Stewart Smith (community): Approve
-
Diff: 20056 lines (+9597/-9871)52 files modifiedPercona-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)
- Stewart Smith (community): Approve
-
Diff: 3690 lines (+1002/-1194)55 files modifiedPercona-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)
Changed in percona-server: | |
assignee: | nobody → Oleg Tsarev (tsarev) |
Changed in percona-server: | |
importance: | Undecided → Medium |
Changed in percona-server: | |
assignee: | Oleg Tsarev (tsarev) → nobody |
Changed in percona-server: | |
status: | Confirmed → Triaged |
importance: | Medium → High |
tags: | added: low-hanging-fruit |
tags: | added: slow-extended |
no longer affects: | percona-server/5.6 |
%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)