Tuesday, April 7, 2015

Enable Innodb lock monitor

mysql> prompt session 3>
PROMPT set to 'prompt session 3 '

session 3> CREATE TABLE innodb_lock_monitor (a INT) ENGINE=INNODB;
Query OK, 0 rows affected, 1 warning (0.03 sec)

As of MySQL 5.6.16, you can also enable the InnoDB Lock Monitor by setting the innodb_status_output_locks system variable to ON. As with the CREATE TABLE method for enabling InnoDB Monitors, both the InnoDB standard Monitor and InnoDB Lock Monitor must be enabled to have InnoDBLock Monitor data printed periodically:


session 3> status;
--------------
/usr/local/mysql/bin/mysql  Ver 14.14 Distrib 5.6.23, for linux-glibc2.5 (x86_64) using  EditLine wrapper

Connection id:          2
Current database:       test
Current user:           root@localhost
SSL:                    Not in use
Current pager:          stdout
Using outfile:          ''
Using delimiter:        ;
Server version:         5.6.23-enterprise-commercial-advanced-log MySQL Enterprise Server - Advanced Edition (Commercial)
Protocol version:       10
Connection:             Localhost via UNIX socket
Server characterset:    latin1
Db     characterset:    latin1
Client characterset:    utf8
Conn.  characterset:    utf8
UNIX socket:            /tmp/mysql-server1.sock
Uptime:                 2 hours 40 min 41 sec

Threads: 3  Questions: 314  Slow queries: 1  Opens: 75  Flush tables: 1  Open tables: 68  Queries per second avg: 0.032
--------------


session 3> set GLOBAL innodb_status_output=ON;
Query OK, 0 rows affected (0.00 sec)

session 3> set GLOBAL innodb_status_output_locks=ON;
Query OK, 0 rows affected (0.00 sec)



session 3> show engine innodb status \G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2015-04-07 14:04:05 7f0fed325700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 10 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 47 srv_active, 0 srv_shutdown, 7787 srv_idle
srv_master_thread log flush and writes: 7834
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 19
OS WAIT ARRAY INFO: signal count 19
Mutex spin waits 1, rounds 30, OS waits 0
RW-shared spins 16, rounds 480, OS waits 16
RW-excl spins 0, rounds 90, OS waits 3
Spin rounds per wait: 30.00 mutex, 30.00 RW-shared, 90.00 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 3020
Purge done for trx's n:o < 3016 undo n:o < 0 state: running but idle
History list length 17
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2, OS thread handle 0x7f0fed325700, query id 301 localhost root init
show engine innodb status
---TRANSACTION 3019, ACTIVE 2 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 4, OS thread handle 0x7f0fed2a3700, query id 300 localhost root updating
delete from tbl_inno
------- TRX HAS BEEN WAITING 2 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6 page no 4 n bits 120 index `GEN_CLUST_INDEX` of table `test`.`tbl_inno` trx id 3019 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 32
 0: len 6; hex 000000000200; asc       ;;
 1: len 6; hex 000000000bb8; asc       ;;
 2: len 7; hex 2b000001bb0110; asc +      ;;
 3: len 4; hex 80000001; asc     ;;
 4: len 30; hex 612020202020202020202020202020202020202020202020202020202020; asc a                             ; (total 255 bytes);

------------------
TABLE LOCK table `test`.`tbl_inno` trx id 3019 lock mode IX
RECORD LOCKS space id 6 page no 4 n bits 120 index `GEN_CLUST_INDEX` of table `test`.`tbl_inno` trx id 3019 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 32
 0: len 6; hex 000000000200; asc       ;;
 1: len 6; hex 000000000bb8; asc       ;;
 2: len 7; hex 2b000001bb0110; asc +      ;;
 3: len 4; hex 80000001; asc     ;;
 4: len 30; hex 612020202020202020202020202020202020202020202020202020202020; asc a                             ; (total 255 bytes);

---TRANSACTION 3000, ACTIVE 1294 sec
5 lock struct(s), heap size 1184, 153 row lock(s), undo log entries 149
MySQL thread id 3, OS thread handle 0x7f0fed2e4700, query id 205 localhost root cleaning up
TABLE LOCK table `test`.`tbl_inno` trx id 3000 lock mode IX
RECORD LOCKS space id 6 page no 4 n bits 120 index `GEN_CLUST_INDEX` of table `test`.`tbl_inno` trx id 3000 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 32
 0: len 6; hex 000000000200; asc       ;;
 1: len 6; hex 000000000bb8; asc       ;;
 2: len 7; hex 2b000001bb0110; asc +      ;;
 3: len 4; hex 80000001; asc     ;;
 4: len 30; hex 612020202020202020202020202020202020202020202020202020202020; asc a                             ; (total 255 bytes);

Record lock, heap no 3 PHYSICAL RECORD: n_fields 5; compact format; info bits 32
 0: len 6; hex 000000000201; asc       ;;
 1: len 6; hex 000000000bb8; asc       ;;
 2: len 7; hex 2b000001bb0136; asc +     6;;
 3: len 4; hex 80000001; asc     ;;
 4: len 30; hex 612020202020202020202020202020202020202020202020202020202020; asc a                             ; (total 255 bytes);


RECORD LOCKS space id 6 page no 5 n bits 120 index `GEN_CLUST_INDEX` of table `test`.`tbl_inno` trx id 3000 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 32
 0: len 6; hex 00000000021a; asc       ;;
 1: len 6; hex 000000000bb8; asc       ;;
 2: len 7; hex 2b000001bb04ec; asc +      ;;
 3: len 4; hex 80000001; asc     ;;
 4: len 30; hex 612020202020202020202020202020202020202020202020202020202020; asc a                             ; (total 255 bytes);

--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (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
181 OS file reads, 669 OS file writes, 295 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 276671, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1868688
Log flushed up to   1868688
Pages flushed up to 1868688
Last checkpoint at  1868688
0 pending log writes, 0 pending chkp writes
233 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137363456; in additional pool allocated 0
Dictionary memory allocated 70412
Buffer pool size   8191
Free buffers       7874
Database pages     316
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 165, created 151, written 414
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 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: 316, 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
0 read views open inside InnoDB
Main thread process no. 2448, id 139706340439808, state: sleeping
Number of rows inserted 149, updated 0, deleted 149, read 298
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)