Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-4302

Enabling the InnoDB Lock Monitor with XtraDB+ does not add any extra logging information

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed (View Workflow)
    • Priority: Minor
    • Resolution: Won't Fix
    • Affects Version/s: 5.5.30, 5.1.67, 5.2.14, 5.3.12
    • Fix Version/s: 5.5.31
    • Component/s: None
    • Labels:
    • Environment:
      Windows, Linux

      Description

      If you are running MariaDB 5.5.30 (at least on Windows) and you enable the InnoDB Lock Monitor (i.e., CREATE TABLE innodb_lock_monitor (id int) ENGINE=InnoDB), no extra lock information is logged. It is the same output as SHOW ENGINE INNODB STATUS. This differs from the standard InnoDB Plugin, as it displays much more lock information.

      1. Start MariaDB 5.5.30
      2. SHOW ENGINE INNODB STATUS\G
      3. CREATE TABLE innodb_lock_monitor (id int) ENGINE=InnoDB;
      4. SHOW ENGINE INNODB STATUS\G
      5. Compare the 2 SHOW ENGINE INNODB STATUS Outputs. You'll see they are identical. This is not the case with the standard MySQL InnoDB Plugin.
      6. You can also examine the error log, which you will see the output written there matches that of the above.

      See my 3 outputs below (SHOW INNODB STATUS #1, SHOW INNODB STATUS #2, Error log):

      1st SHOW ENGINE INNODB STATUS Output

      mysql> show engine innodb status\G
      *************************** 1. row ***************************
        Type: InnoDB
        Name:
      Status:
      =====================================
      130319 14:15:22 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 5 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 12 1_second, 12 sleeps, 1 10_second, 2 background, 2 flush
      srv_master_thread log flush and writes: 139
      ----------
      SEMAPHORES
      ----------
      OS WAIT ARRAY INFO: reservation count 4, signal count 4
      Mutex spin waits 1, rounds 30, OS waits 1
      RW-shared spins 3, rounds 90, OS waits 3
      RW-excl spins 0, rounds 0, OS waits 0
      Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 0.00 RW-excl
      --------
      FILE I/O
      --------
      I/O thread 0 state: native aio handle (insert buffer thread)
      I/O thread 1 state: native aio handle (log thread)
      I/O thread 2 state: native aio handle (read thread)
      I/O thread 3 state: native aio handle (read thread)
      I/O thread 4 state: native aio handle (read thread)
      I/O thread 5 state: native aio handle (read thread)
      I/O thread 6 state: native aio handle (write thread)
      I/O thread 7 state: native aio handle (write thread)
      I/O thread 8 state: native aio handle (write thread)
      I/O thread 9 state: native aio handle (write thread)
      Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
       ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
      Pending flushes (fsync) log: 0; buffer pool: 0
      246 OS file reads, 18 OS file writes, 8 OS fsyncs
      0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
      -------------------------------------
      INSERT BUFFER AND ADAPTIVE HASH INDEX
      -------------------------------------
      Ibuf: size 1, free list len 0, seg size 2, 0 merges
      merged operations:
       insert 0, delete mark 0, delete 0
      discarded operations:
       insert 0, delete mark 0, delete 0
      Hash table size 199289, node heap has 1 buffer(s)
      0.00 hash searches/s, 0.00 non-hash searches/s
      ---
      LOG
      ---
      Log sequence number 1723639
      Log flushed up to   1723639
      Last checkpoint at  1723639
      Max checkpoint age    84223550
      Checkpoint age target 81591565
      Modified age          0
      Checkpoint age        0
      0 pending log writes, 0 pending chkp writes
      11 log i/o's done, 0.00 log i/o's/second
      ----------------------
      BUFFER POOL AND MEMORY
      ----------------------
      Total memory allocated 103415808; in additional pool allocated 0
      Internal hash tables (constant factor + variable factor)
          Adaptive hash index 1614912         (1594312 + 20600)
          Page hash           100424 (buffer pool 0 only)
          Dictionary cache    844668  (798704 + 45964)
          File system         83536   (82672 + 864)
          Lock system         250600  (249848 + 752)
          Recovery system     0       (0 + 0)
      Dictionary memory allocated 45964
      Buffer pool size        6143
      Buffer pool size, bytes 100646912
      Free buffers            5906
      Database pages          236
      Old database pages      0
      Modified db pages       0
      Pending reads 0
      Pending writes: LRU 0, flush list 0, single page 0
      Pages made young 0, not young 0
      0.00 youngs/s, 0.00 non-youngs/s
      Pages read 235, created 1, written 11
      0.00 reads/s, 0.00 creates/s, 0.00 writes/s
      No buffer pool page gets since the last printout
      Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
      LRU len: 236, unzip_LRU len: 0
      I/O sum[0]:cur[0], unzip sum[0]:cur[0]
      --------------
      ROW OPERATIONS
      --------------
      0 queries inside InnoDB, 0 queries in queue
      1 read views open inside InnoDB
      ---OLDEST VIEW---
      Normal read view
      Read view low limit trx n:o 700
      Read view up limit trx id 700
      Read view low limit trx id 700
      Read view individually stored trx ids:
      -----------------
      Main thread id 10564, state: waiting for server activity
      Number of rows inserted 5, updated 0, deleted 0, read 5
      0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 703
      Purge done for trx's n:o < 3A3 undo n:o < 0
      History list length 41
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 0, not started
      MySQL thread id 2, OS thread handle 0x3444, query id 8 localhost ::1 root
      show engine innodb status
      ---TRANSACTION 702, ACTIVE 16 sec
      2 lock struct(s), heap size 376, 6 row lock(s)
      MySQL thread id 1, OS thread handle 0x3444, query id 7 localhost ::1 root
      TABLE LOCK table `test1`.`t` trx id 702 lock mode IX
      RECORD LOCKS space id 0 page no 401 n bits 72 index `GEN_CLUST_INDEX` of table `test1`.`t` trx id 702 lock_mode X
      ----------------------------
      END OF INNODB MONITOR OUTPUT
      ============================
       
      1 row in set (0.04 sec)

      2nd SHOW ENGINE INNODB STATUS Output

      mysql> create table innodb_lock_monitor (id int) engine=innodb;
      Query OK, 0 rows affected (0.05 sec)
       
      mysql> show engine innodb status\G
      *************************** 1. row ***************************
        Type: InnoDB
        Name:
      Status:
      =====================================
      130319 14:15:51 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 29 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 13 1_second, 13 sleeps, 1 10_second, 4 background, 4 flush
      srv_master_thread log flush and writes: 140
      ----------
      SEMAPHORES
      ----------
      OS WAIT ARRAY INFO: reservation count 5, signal count 5
      Mutex spin waits 1, rounds 30, OS waits 1
      RW-shared spins 4, rounds 120, OS waits 4
      RW-excl spins 0, rounds 0, OS waits 0
      Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 0.00 RW-excl
      --------
      FILE I/O
      --------
      I/O thread 0 state: native aio handle (insert buffer thread)
      I/O thread 1 state: native aio handle (log thread)
      I/O thread 2 state: native aio handle (read thread)
      I/O thread 3 state: native aio handle (read thread)
      I/O thread 4 state: native aio handle (read thread)
      I/O thread 5 state: native aio handle (read thread)
      I/O thread 6 state: native aio handle (write thread)
      I/O thread 7 state: native aio handle (write thread)
      I/O thread 8 state: native aio handle (write thread)
      I/O thread 9 state: native aio handle (write thread)
      Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
       ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
      Pending flushes (fsync) log: 0; buffer pool: 0
      247 OS file reads, 33 OS file writes, 12 OS fsyncs
      0.03 reads/s, 16384 avg bytes/read, 0.52 writes/s, 0.14 fsyncs/s
      -------------------------------------
      INSERT BUFFER AND ADAPTIVE HASH INDEX
      -------------------------------------
      Ibuf: size 1, free list len 0, seg size 2, 0 merges
      merged operations:
       insert 0, delete mark 0, delete 0
      discarded operations:
       insert 0, delete mark 0, delete 0
      Hash table size 199289, node heap has 1 buffer(s)
      0.00 hash searches/s, 0.24 non-hash searches/s
      ---
      LOG
      ---
      Log sequence number 1726126
      Log flushed up to   1726126
      Last checkpoint at  1726126
      Max checkpoint age    84223550
      Checkpoint age target 81591565
      Modified age          0
      Checkpoint age        0
      0 pending log writes, 0 pending chkp writes
      13 log i/o's done, 0.07 log i/o's/second
      ----------------------
      BUFFER POOL AND MEMORY
      ----------------------
      Total memory allocated 103415808; in additional pool allocated 0
      Internal hash tables (constant factor + variable factor)
          Adaptive hash index 1614912         (1594312 + 20600)
          Page hash           100424 (buffer pool 0 only)
          Dictionary cache    848790  (798704 + 50086)
          File system         83536   (82672 + 864)
          Lock system         250600  (249848 + 752)
          Recovery system     0       (0 + 0)
      Dictionary memory allocated 50086
      Buffer pool size        6143
      Buffer pool size, bytes 100646912
      Free buffers            5903
      Database pages          239
      Old database pages      0
      Modified db pages       0
      Pending reads 0
      Pending writes: LRU 0, flush list 0, single page 0
      Pages made young 0, not young 0
      0.00 youngs/s, 0.00 non-youngs/s
      Pages read 236, created 3, written 23
      0.03 reads/s, 0.07 creates/s, 0.41 writes/s
      Buffer pool hit rate 981 / 1000, young-making rate 0 / 1000 not 0 / 1000
      Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
      LRU len: 239, unzip_LRU len: 0
      I/O sum[0]:cur[0], unzip sum[0]:cur[0]
      --------------
      ROW OPERATIONS
      --------------
      0 queries inside InnoDB, 0 queries in queue
      1 read views open inside InnoDB
      ---OLDEST VIEW---
      Normal read view
      Read view low limit trx n:o 700
      Read view up limit trx id 700
      Read view low limit trx id 700
      Read view individually stored trx ids:
      -----------------
      Main thread id 10564, state: waiting for server activity
      Number of rows inserted 5, updated 0, deleted 0, read 5
      0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 704
      Purge done for trx's n:o < 3A3 undo n:o < 0
      History list length 41
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 0, not started
      MySQL thread id 2, OS thread handle 0x3444, query id 10 localhost ::1 root
      show engine innodb status
      ---TRANSACTION 702, ACTIVE 45 sec
      2 lock struct(s), heap size 376, 6 row lock(s)
      MySQL thread id 1, OS thread handle 0x3444, query id 7 localhost ::1 root
      TABLE LOCK table `test1`.`t` trx id 702 lock mode IX
      RECORD LOCKS space id 0 page no 401 n bits 72 index `GEN_CLUST_INDEX` of table `test1`.`t` trx id 702 lock_mode X
      ----------------------------
      END OF INNODB MONITOR OUTPUT
      ============================
       
      1 row in set (0.00 sec)
       
      mysql> drop table innodb_lock_monitor;
      Query OK, 0 rows affected (0.05 sec)

      Error Log:

      130319 13:56:59 InnoDB: The InnoDB memory heap is disabled
      130319 13:56:59 InnoDB: Mutexes and rw_locks use Windows interlocked functions
      130319 13:56:59 InnoDB: Compressed tables use zlib 1.2.3
      130319 13:56:59 InnoDB: Initializing buffer pool, size = 96.0M
      130319 13:56:59 InnoDB: Completed initialization of buffer pool
      130319 13:56:59 InnoDB: highest supported file format is Barracuda.
      130319 13:56:59  InnoDB: Waiting for the background threads to start
      130319 13:57:00 Percona XtraDB (http://www.percona.com) 5.5.30-MariaDB-30.1 started; log sequence number 1721723
      130319 13:57:00 [Note] Plugin 'FEEDBACK' is disabled.
      130319 13:57:01 [Note] Event Scheduler: Loaded 0 events
      130319 13:57:01 [Note] C:\Program Files\MariaDB 5.5\bin\mysqld.exe: ready for connections.
      Version: '5.5.30-MariaDB'  socket: ''  port: 3310  mariadb.org binary distribution
       
      =====================================
      130319 14:15:59 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 8 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 13 1_second, 13 sleeps, 1 10_second, 4 background, 4 flush
      srv_master_thread log flush and writes: 140
      ----------
      SEMAPHORES
      ----------
      OS WAIT ARRAY INFO: reservation count 5, signal count 5
      Mutex spin waits 1, rounds 30, OS waits 1
      RW-shared spins 4, rounds 120, OS waits 4
      RW-excl spins 0, rounds 0, OS waits 0
      Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 0.00 RW-excl
      --------
      FILE I/O
      --------
      I/O thread 0 state: native aio handle (insert buffer thread)
      I/O thread 1 state: native aio handle (log thread)
      I/O thread 2 state: native aio handle (read thread)
      I/O thread 3 state: native aio handle (read thread)
      I/O thread 4 state: native aio handle (read thread)
      I/O thread 5 state: native aio handle (read thread)
      I/O thread 6 state: native aio handle (write thread)
      I/O thread 7 state: native aio handle (write thread)
      I/O thread 8 state: native aio handle (write thread)
      I/O thread 9 state: native aio handle (write thread)
      Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
       ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
      Pending flushes (fsync) log: 0; buffer pool: 0
      247 OS file reads, 33 OS file writes, 12 OS fsyncs
      0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
      -------------------------------------
      INSERT BUFFER AND ADAPTIVE HASH INDEX
      -------------------------------------
      Ibuf: size 1, free list len 0, seg size 2, 0 merges
      merged operations:
       insert 0, delete mark 0, delete 0
      discarded operations:
       insert 0, delete mark 0, delete 0
      Hash table size 199289, node heap has 1 buffer(s)
      0.00 hash searches/s, 0.00 non-hash searches/s
      ---
      LOG
      ---
      Log sequence number 1726126
      Log flushed up to   1726126
      Last checkpoint at  1726126
      Max checkpoint age    84223550
      Checkpoint age target 81591565
      Modified age          0
      Checkpoint age        0
      0 pending log writes, 0 pending chkp writes
      13 log i/o's done, 0.00 log i/o's/second
      ----------------------
      BUFFER POOL AND MEMORY
      ----------------------
      Total memory allocated 103415808; in additional pool allocated 0
      Internal hash tables (constant factor + variable factor)
          Adaptive hash index 1614912 	(1594312 + 20600)
          Page hash           100424 (buffer pool 0 only)
          Dictionary cache    848790 	(798704 + 50086)
          File system         83536 	(82672 + 864)
          Lock system         250600 	(249848 + 752)
          Recovery system     0 	(0 + 0)
      Dictionary memory allocated 50086
      Buffer pool size        6143
      Buffer pool size, bytes 100646912
      Free buffers            5903
      Database pages          239
      Old database pages      0
      Modified db pages       0
      Pending reads 0
      Pending writes: LRU 0, flush list 0, single page 0
      Pages made young 0, not young 0
      0.00 youngs/s, 0.00 non-youngs/s
      Pages read 236, created 3, written 23
      0.00 reads/s, 0.00 creates/s, 0.00 writes/s
      No buffer pool page gets since the last printout
      Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
      LRU len: 239, unzip_LRU len: 0
      I/O sum[0]:cur[0], unzip sum[0]:cur[0]
      --------------
      ROW OPERATIONS
      --------------
      0 queries inside InnoDB, 0 queries in queue
      1 read views open inside InnoDB
      ---OLDEST VIEW---
      Normal read view
      Read view low limit trx n:o 700
      Read view up limit trx id 700
      Read view low limit trx id 700
      Read view individually stored trx ids:
      -----------------
      Main thread id 10564, state: waiting for server activity
      Number of rows inserted 5, updated 0, deleted 0, read 5
      0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 704
      Purge done for trx's n:o < 3A3 undo n:o < 0
      History list length 41
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 0, not started
      MySQL thread id 2, OS thread handle 0x3444, query id 10 localhost ::1 root
      ---TRANSACTION 702, ACTIVE 53 sec
      2 lock struct(s), heap size 376, 6 row lock(s)
      MySQL thread id 1, OS thread handle 0x3444, query id 7 localhost ::1 root
      TABLE LOCK table `test1`.`t` trx id 702 lock mode IX
      RECORD LOCKS space id 0 page no 401 n bits 72 index `GEN_CLUST_INDEX` of table `test1`.`t` trx id 702 lock_mode X
      ----------------------------
      END OF INNODB MONITOR OUTPUT
      ============================

        Attachments

          Activity

            People

            Assignee:
            serg Sergei Golubchik
            Reporter:
            ccalender Chris Calender
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: