Log all statements in transaction with same id, lp:897715

[ihanick]

https://bugs.launchpad.net/percona-server/+bug/897715
http://jenkins.percona.com/job/percona-server-5.6-param/

I have considered to use thread_id + statement start time as a uniq identifier.
Only explicit transactions are tracked.
I'm not sure if additional flag is required for log_slow_verbosity or existing one (e.g. microtime) could be used.
It could be also implemented for 5.5 in the same way.

This kind of functionality will be useful with:

• find a transactions caused metadata lock
• find whole transaction (including non-innodb statements at transaction start) by thread id (from processlist) or innodb transaction id (from innodb status).
• find incorrect transactions usage (set auto_commit = 0, connection pool on application side, some application threads using transactions and some expecting auto_commit=1).

Mysql 5.7 has thd->get_transaction()->sequence_number but it always empty.

[laurynas-biveinis]

Why is this attached to microtime verbosity?

[laurynas-biveinis]

We end up with two trx ids, innodb one, and thread id. Probably it's better to implement the InnoDB trx id for "COMMIT", and nothing for "BEGIN" (maybe in some cases BEGIN gets InnoDB trx id - what about "WITH CONSISTENT SNAPSHOT"?)

[ihanick]

http://jenkins.percona.com/job/percona-server-5.6-param/1535/

• changed transaction id to innodb_trx_id
• now transaction tracked after any innodb statement inside transaction until commit or rollback.

both timestamp based and Innodb_trx_id producing different numbers for base session and for consistent snapshot.

[laurynas-biveinis]

Can you provide an example of a slow query log with changed output?

[laurynas-biveinis]

Why is this needed?

[laurynas-biveinis]

Assuming it is needed, then it probably needs some sort of initialisation/reset in THD or it looks like some of the reads will be uninitialized

[ihanick]

http://jenkins.percona.com/job/percona-server-5.6-param/1541/

• clear_slow_extended clears innodb_trx_id only if not running inside transaction
• during init innodb_trx_id always cleared, because server_status= SERVER_STATUS_AUTOCOMMIT; (no SERVER_STATUS_IN_TRANS).
• remove save_innodb_trx_id variable

Test queries:

create table t(c int) engine=innodb;
select 1;
begin;
  select 2;
  select * from t;
  select 3;
commit;
select 4;

Slow log example

# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000131  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 56
# No InnoDB statistics available for this query
SET timestamp=1481896052;
select 1;
# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000047  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 11
# No InnoDB statistics available for this query
SET timestamp=1481896052;
begin;
# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000071  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 56
# No InnoDB statistics available for this query
SET timestamp=1481896052;
select 2;
# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.001138  Lock_time: 0.000909  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 57
# InnoDB_trx_id: 509
#   InnoDB_IO_r_ops: 8  InnoDB_IO_r_bytes: 131072  InnoDB_IO_r_wait: 0.000142
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 22
SET timestamp=1481896052;
select * from t;
# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000158  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 56
# InnoDB_trx_id: 509
# No InnoDB statistics available for this query
SET timestamp=1481896052;
select 3;
# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000104  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 11
# InnoDB_trx_id: 509
# No InnoDB statistics available for this query
SET timestamp=1481896052;
commit;
# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000684  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 56
# No InnoDB statistics available for this query
SET timestamp=1481896052;
select 4;
# User@Host: root[root] @ localhost []  Id:     2
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 0.000013  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 0
# No InnoDB statistics available for this query
SET timestamp=1481896052;

[laurynas-biveinis]

Can we remove thd->innodb_was_used check?

[ihanick]

http://jenkins.percona.com/job/percona-server-5.6-param/1579/

• removed redundant thd->innodb_was_use check:
  thd->innodb_trx_id is zero if not in transaction in clear_slow_extended, called from THD::init and before running command at dispatch_command.