InnoDB and query plan information are logged when not enabled

[Baron Schwartz]

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".

[Vadim Tkachenko (vadim-tk)]

Baron,

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

[Baron Schwartz (baron-xaprb)]

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)]

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: [phone] ext 501 Skype: peter_zaitsev
24/7 Emergency Line [phone] ext 911

Looking for MySQL Support ?
http://www.percona.com/support/

[Oleg Tsarev (tsarev)]

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?

[Baron Schwartz (baron-xaprb)]

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

[Oleg Tsarev (tsarev)]

Valentin, please investigate how should work

[Valentine Gostev (longbow)]

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?

[Alexey Kopytov (akopytov)]

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.

[Valentine Gostev (longbow)]

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