InnoDB and query plan information are logged when not enabled
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
| Percona Server moved to https://jira.percona.com/projects/PS |
Fix Released
|
Low
|
Laurynas Biveinis | |
| 5.1 |
Fix Released
|
Low
|
Laurynas Biveinis | |
| 5.5 |
Fix Released
|
Low
|
Laurynas Biveinis |
Bug Description
mysql> select @@log_slow_
+------
| @@log_slow_
+------
| microtime |
+------
mysql> insert into a(a) values(1);
The resulting slow query log entry:
# Time: 110306 10:38:30
# User@Host: root[root] @ localhost [127.0.0.1]
# Thread_id: 18 Schema: test Last_errno: 0 Killed: 0
# Query_time: 0.060034 Lock_time: 0.000330 Rows_sent: 0 Rows_examined: 0 Rows_affected: 1 Rows_read: 2
# Bytes_sent: 11 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 2D01
SET timestamp=
insert into a(a) values(1);
The InnoDB transaction ID shouldn't be included in the log if log_slow_verbosity doesn't include "innodb", and the temp table information shouldn't be included unless log_slow_verbosity includes "query_plan".
Related branches
- Stewart Smith (community): Approve on 2013-02-11
-
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 on 2013-02-08
-
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)
Vadim Tkachenko (vadim-tk) wrote : | #1 |
Baron Schwartz (baron-xaprb) wrote : Re: [Bug 730173] Re: InnoDB and query plan information are logged when not enabled | #2 |
As a user, I would expect it to behave pretty much like the normal
query log, unless extra things are enabled; especially if there is a
switch that seems to control those extra things but doesn't.
Peter Zaitsev (pz-percona) wrote : | #3 |
Yup,
I agree. Though may be in 5.5 we should have "full" as default. To have
extended information in slow query logs unless it is disabled,
what do you think ?
I'd also recommend enabling log_slow_
replication thread by default (both can be disabled if needed)
On Sun, Mar 6, 2011 at 11:09 AM, Xaprb <email address hidden> wrote:
> As a user, I would expect it to behave pretty much like the normal
> query log, unless extra things are enabled; especially if there is a
> switch that seems to control those extra things but doesn't.
>
> --
> You received this bug notification because you are a member of Percona
> developers, which is the registrant for Percona Server.
> https:/
>
> Title:
> InnoDB and query plan information are logged when not enabled
>
> Status in Percona Server with XtraDB:
> New
>
> Bug description:
> mysql> select @@log_slow_
> +------
> | @@log_slow_
> +------
> | microtime |
> +------
>
> mysql> insert into a(a) values(1);
>
> The resulting slow query log entry:
>
> # Time: 110306 10:38:30
> # User@Host: root[root] @ localhost [127.0.0.1]
> # Thread_id: 18 Schema: test Last_errno: 0 Killed: 0
> # Query_time: 0.060034 Lock_time: 0.000330 Rows_sent: 0 Rows_examined:
> 0 Rows_affected: 1 Rows_read: 2
> # Bytes_sent: 11 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
> # InnoDB_trx_id: 2D01
> SET timestamp=
> insert into a(a) values(1);
>
> The InnoDB transaction ID shouldn't be included in the log if
> log_slow_verbosity doesn't include "innodb", and the temp table
> information shouldn't be included unless log_slow_verbosity includes
> "query_plan".
>
--
Peter Zaitsev, CEO, Percona Inc.
Tel: +1 888 401 3401 ext 501 Skype: peter_zaitsev
24/7 Emergency Line +1 888 401 3401 ext 911
Looking for MySQL Support ?
http://
Changed in percona-server: | |
status: | New → Confirmed |
Changed in percona-server: | |
importance: | Undecided → Medium |
status: | Confirmed → Triaged |
Oleg Tsarev (tsarev) wrote : | #4 |
Do I right understand, we should do following:
1) log_slow_
2) log_slow_
3) log_slow_
4) What about InnoDB transaction ID? Should be logged when log_slow_verbosity not set to "innodb" or not?
Changed in percona-server: | |
assignee: | nobody → Oleg Tsarev (tsarev) |
status: | Triaged → Incomplete |
Baron Schwartz (baron-xaprb) wrote : | #5 |
I'm not suggesting to enable anything new by default. I think that
should be a different feature request / bug.
Oleg Tsarev (tsarev) wrote : | #6 |
Valentin, please investigate how should work
Changed in percona-server: | |
assignee: | Oleg Tsarev (tsarev) → Valentine Gostev (longbow) |
Valentine Gostev (longbow) wrote : | #7 |
I do not see any bug here.
both query_plan and innodb verbosity levels provide more detailed information about query in comparison with just microtime
innodb adds:
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_
# InnoDB_
query_plan shows details of query's execution plan:
# QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
Is it worth not to show InnoDB trx id when verbosity is set to microtime?
Changed in percona-server: | |
status: | Incomplete → Invalid |
Alexey Kopytov (akopytov) wrote : | #8 |
The bug is not about logging with 'innodb' or 'query_plan' enabled. It is about not logging any extra information unless it is requested by activating the corresponding log_slow_verbosity flags.
As I understand, that's not the case currently: temp. tables info and InnoDB_trx_id are logged unconditionally, regardless of the log_slow_verbosity value.
Changed in percona-server: | |
status: | Invalid → New |
Valentine Gostev (longbow) wrote : | #9 |
Added tests for initial issue (see linked branches), reassigning to Oleg
tags: | added: slow-extended |
no longer affects: | percona-server/5.6 |
Percona now uses JIRA for bug reports so this bug report is migrated to: https:/
Baron,
It is designed behavior. Why it should not be included in default output ?