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 STATUS\G *************************** 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。
