Skip to:

  1. Skip to Jira Navigation
  2. Skip to Side Navigation
  3. Skip to Main Content

InnoDB statistics in extended slow query log always zero

Description

In 5.7, with InnoDB extensions in slow query log enabled, these are shown as zeros incorrectly:

# InnoDB_trx_id: 509 #   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

whereas the actual data should be

# InnoDB_trx_id: 509 #   InnoDB_IO_r_ops: 1  InnoDB_IO_r_bytes: 16384  InnoDB_IO_r_wait: 0.000024 #   InnoDB_rec_lock_wait: 2.004502  InnoDB_queue_wait: 0.000000 #   InnoDB_pages_distinct: 6

To repeat,

--source include/have_innodb.inc CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=InnoDB; INSERT INTO t1 VALUES (1); BEGIN; SELECT * FROM t1 FOR UPDATE; --source include/count_sessions.inc --connect(con1,localhost,root,,) SET SESSION log_slow_verbosity='innodb'; SET SESSION long_query_time=0; --let log_file=percona.slow_extended_lock_time.log --source include/log_start.inc send DELETE FROM t1 WHERE a = 1; --connection default # TODO wait condition --real_sleep 2 SHOW PROCESSLIST; ROLLBACK; --connection con1 reap; --source include/log_stop.inc --disconnect con1 --connection default DROP TABLE t1; --source include/wait_until_count_sessions.inc --cat_file $MYSQLTEST_VARDIR/$log_file.slog --source include/log_cleanup.inc

This appears to be caused by trx_commit_in_memory calling trx_init which zeroes out the stat fields in trx object before ha_innobase::external_lock sends them back to the server layer. This is a 5.7-only regression.

Environment

None

Smart Checklist

Activity

Done

Details

Assignee

Reporter

Labels

Time tracking

1w 3d 1h 28m logged

Fix versions

Affects versions

Priority

Smart Checklist

Created February 14, 2018 at 1:23 PM
Updated March 6, 2024 at 1:38 PM
Resolved June 19, 2018 at 12:14 PM

Flag notifications