Uploaded image for project: 'Percona Server'
  1. Percona Server
  2. PS-3828

InnoDB statistics in extended slow query log always zero

    XMLWordPrintable

    Details

      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.

        Attachments

          Activity

            People

            • Assignee:
              laurynas.biveinis Laurynas Biveinis
              Reporter:
              laurynas.biveinis Laurynas Biveinis
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 1 week, 3 days, 1 hour, 28 minutes
                1w 3d 1h 28m