InnoDB Monitors | SHOW ENGINE INNODB STATUS

参考 《mysql 5.7手册》，15.17章节

InnoDB监视器提供有关InnoDB内部状态的信息。 这些信息对于性能调优非常有用。其实所谓的监视器，就是 show engine innodb status 命令。

InnoDB监视器类型

有两种类型的InnoDB监视器：

1. 标准InnoDB监视器（The standard InnoDB Monitor）显示以下类型的信息：

• 每个活动事务持有的表和记录锁
• 事务的锁等待
• 线程的信号量等待
• 待处理文件的I/O请求 （Pending file I/O requests）
• 缓冲池统计信息 （Buffer pool statistics）
•  Purge and change buffer merge activity of the main InnoDB thread

2. InnoDB锁定监视器（The InnoDB Lock Monitor）将额外的锁信息作为标准InnoDB监视器输出的一部分进行打印。

开启 InnoDB Monitor

开启  standard InnoDB Monitor (需要PROCESS权限)

> set GLOBAL innodb_status_output=ON;

上面的语句可定期写入到标准错误输出（stderr，即error log，大概每15s写一次），你也可以使用 SHOW ENGINE INNODB STATUS 语句直接在客户端获取innodb信息。

而开启 InnoDB Lock Monitor 需要同时打开以下2个参数，它的信息也是随 InnoDB Standard Monitor 的信息一起打印出来：

> set GLOBAL innodb_status_output=ON;
> set GLOBAL innodb_status_output_locks=ON;

InnoDB 标准监视器和锁监视器的输出信息

锁监视器与标准监视器基本相同，只是它包含了附加的锁信息（lock information）。

Example Standard Monitor output:

mysql> SHOW ENGINE INNODB STATUSG
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2014-10-16 18:37:29 0x7fc2a95c1700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 38 srv_active, 0 srv_shutdown, 252 srv_idle
srv_master_thread log flush and writes: 290
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 119
OS WAIT ARRAY INFO: signal count 103
Mutex spin waits 0, rounds 0, OS waits 0
RW-shared spins 38, rounds 76, OS waits 38
RW-excl spins 2, rounds 9383715, OS waits 3
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 mutex, 2.00 RW-shared, 4691857.50 RW-excl,
0.00 RW-sx
------------------------
LATEST FOREIGN KEY ERROR
------------------------
2014-10-16 18:35:18 0x7fc2a95c1700 Transaction:
TRANSACTION 1814, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 3
MySQL thread id 2, OS thread handle 140474041767680, query id 74 localhost
root update
INSERT INTO child VALUES
(NULL, 1)
, (NULL, 2)
, (NULL, 3)
, (NULL, 4)
, (NULL, 5)
, (NULL, 6)
Foreign key constraint fails for table `mysql`.`child`:
,
CONSTRAINT `child_ibfk_1` FOREIGN KEY (`parent_id`) REFERENCES `parent`
(`id`) ON DELETE CASCADE ON UPDATE CASCADE
Trying to add in child table, in index par_ind tuple:
DATA TUPLE: 2 fields;
0: len 4; hex 80000003; asc ;;
1: len 4; hex 80000003; asc ;;
But in parent table `mysql`.`parent`, in index PRIMARY,
the closest match we can find is record:
PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 4; hex 80000004; asc ;;
1: len 6; hex 00000000070a; asc ;;
2: len 7; hex aa0000011d0134; asc 4;;
------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-10-16 18:36:30 0x7fc2a95c1700
*** (1) TRANSACTION:
TRANSACTION 1824, ACTIVE 9 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 3, OS thread handle 140474041501440, query id 80 localhost
root updating
DELETE FROM t WHERE i = 1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 35 page no 3 n bits 72 index GEN_CLUST_INDEX of table
`mysql`.`t` trx id 1824 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info
bits 0
0: len 6; hex 000000000200; asc ;;
1: len 6; hex 00000000071f; asc ;;
2: len 7; hex b80000012b0110; asc + ;;
3: len 4; hex 80000001; asc ;;
*** (2) TRANSACTION:
TRANSACTION 1825, ACTIVE 29 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s)
MySQL thread id 2, OS thread handle 140474041767680, query id 81 localhost
root updating
DELETE FROM t WHERE i = 1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 35 page no 3 n bits 72 index GEN_CLUST_INDEX of table
`mysql`.`t` trx id 1825 lock mode S
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 4; compact format; info bits 0
0: len 6; hex 000000000200; asc ;;
1: len 6; hex 00000000071f; asc ;;
2: len 7; hex b80000012b0110; asc + ;;
3: len 4; hex 80000001; asc ;;
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 35 page no 3 n bits 72 index GEN_CLUST_INDEX of table
`mysql`.`t` trx id 1825 lock_mode X waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info
bits 0
0: len 6; hex 000000000200; asc ;;
1: len 6; hex 00000000071f; asc ;;
2: len 7; hex b80000012b0110; asc + ;;
3: len 4; hex 80000001; asc ;;
*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 1950
Purge done for trx's n:o < 1933 undo n:o < 0 state: running but idle
History list length 23
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421949033065200, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421949033064280, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 1949, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
8 lock struct(s), heap size 1136, 1850 row lock(s), undo log entries 17415
MySQL thread id 4, OS thread handle 140474041235200, query id 176 localhost
root update
INSERT INTO `salaries` VALUES (55723,39746,'1997-02-25','1998-02-25'),
(55723,40758,'1998-02-25','1999-02-25'),(55723,44559,'1999-02-25','2000-02-25'),
(55723,44081,'2000-02-25','2001-02-24'),(55723,44112,'2001-02-24','2001-08-16'),
(55724,46461,'1996-12-06','1997-12-06'),(55724,48916,'1997-12-06','1998-12-06'),
(55724,51269,'1998-12-06','1999-12-06'),(55724,51932,'1999-12-06','2000-12-05'),
(55724,52617,'2000-12-05','2001-12-05'),(55724,56658,'2001-12-05','9999-01-01'),
(55725,40000,'1993-01-30','1994-01-30'),(55725,41472,'1994-01-30','1995-01-30'),
(55725,45293,'1995-01-30','1996-01-30'),(55725,473
--------
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
224 OS file reads, 5770 OS file writes, 803 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 264.84 writes/s, 23.05 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 4425293, node heap has 444 buffer(s)
68015.25 hash searches/s, 106259.24 non-hash searches/s
---
LOG
---
Log sequence number 165913808
Log flushed up to 164814979
Pages flushed up to 141544038
Last checkpoint at 130503656
0 pending log flushes, 0 pending chkp writes
258 log i/o's done, 6.65 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 2198863872
Dictionary memory allocated 776332
Buffer pool size 131072
Free buffers 124908
Database pages 5720
Old database pages 2071
Modified db pages 910
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 4, not young 0
0.10 youngs/s, 0.00 non-youngs/s
Pages read 197, created 5523, written 5060
0.00 reads/s, 190.89 creates/s, 244.94 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: 5720, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size 65536
Free buffers 62412
Database pages 2899
Old database pages 1050
Modified db pages 449
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 3, not young 0
0.05 youngs/s, 0.00 non-youngs/s
Pages read 107, created 2792, written 2586
0.00 reads/s, 92.65 creates/s, 122.89 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: 2899, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 65536
Free buffers 62496
Database pages 2821
Old database pages 1021
Modified db pages 461
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1, not young 0
0.05 youngs/s, 0.00 non-youngs/s
Pages read 90, created 2731, written 2474
0.00 reads/s, 98.25 creates/s, 122.04 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: 2821, 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
Process ID=35909, Main thread ID=140471692396288, state: sleeping
Number of rows inserted 1526363, updated 0, deleted 3, read 11
52671.72 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

有关标准监视器报告的每个度量标准的说明，请参阅：https://dev.mysql.com/doc/mysql-em-plugin/en/

Status

本部分显示时间戳，监视器名称以及每秒平均值所基于的秒数。 秒数是当前时间与最后一次打印InnoDB Monitor输出之间的时间间隔。

BACKGROUND THREAD

srv_master_thread 行显示主线程完成的工作。

SEMAPHORES

----------

SEMAPHORES // 信号
----------
OS WAIT ARRAY INFO: reservation count 118146 //os wait 的信息 ，reservation count 表示InnoDB产生了多少次OS WAIT
OS WAIT ARRAY INFO: signal count 186714 // 进行OS WAIT线程，接收到多少次信号(single)被唤醒，如果这个single数值越大，几十万或者几百万，可能是很多I/0等待或者是InnoDB争用问题(关于争用问题可能与OS调度有关，可以尝试减少innodb_thread_concurrency参数)
Mutex spin waits 1664035, rounds 4276317, OS waits 20348 // Mutex spin线程无法获取锁而进入Spin wait ,rounds是spin wait 进行轮询检查mutextes的次数，os wait 线程放弃spin-wait 进入挂起状态
RW-shared spins 302454, rounds 11667281, OS waits 69050 //RW-shared 共享锁，
RW-excl spins 83942, rounds 4021896, OS waits 28377 // RW-excl 排他锁
Spin rounds per wait: 2.57 mutex, 38.58 RW-shared, 47.91 RW-excl

// 备注：要明白Innodb如何处理互斥量(Mutexes)，以及什么是两步获得锁(two-step approach)。首先进程，试图获得一个锁，如果此锁被它人占用。它就会执行所谓的spin wait,即所谓循环的查询”锁被释放了吗？”。如果在循环过程中，一直未得到锁释放的信息，则其转入OS WAIT，即所谓线程进入挂起(suspended)状态。直到锁被释放后，通过信号(singal)唤醒线程Spin wait的消耗远小于OS waits。Spinwait利用cpu的空闲时间，检查锁的状态，OS Wait会有所谓content switch，从CPU内核中换出当前执行线程以供其它线程使用。你可以通过innodb_sync_spin_loops参数来平衡spin wait和os wait。