InnoDB and query plan information are logged when not enabled

Baron,

It is designed behavior. Why it should not be included in default output ?

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.

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_admin_statements and slow queries from
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://bugs.launchpad.net/bugs/730173
>
> Title:
> InnoDB and query plan information are logged when not enabled
>
> Status in Percona Server with XtraDB:
> New
>
> Bug description:
> mysql> select @@log_slow_verbosity;
> +----------------------+
> | @@log_slow_verbosity |
> +----------------------+
> | 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=1299425910;
> 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://www.percona.com/support/

Do I right understand, we should do following:
1) log_slow_admin_statements=ON by default
2) log_slow_slave_statements=ON by default
3) log_slow_verbosity=full by default
4) What about InnoDB transaction ID? Should be logged when log_slow_verbosity not set to "innodb" or not?

I'm not suggesting to enable anything new by default. I think that
should be a different feature request / bug.

Valentin, please investigate how should work

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_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 0

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?

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.

Added tests for initial issue (see linked branches), reassigning to Oleg

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