SHOW INNODB STATUS

SHOW INNODB STATUS walk through

In SHOW INNODB STATUS many values are per second. If you're planning to use these values make sure they are sampled over decent period of time. In the very start of printout Innodb will print:

在 SHOW INNODB STATUS 中许多值都是按秒统计的，如果要使用这些值，就得隔适当的时间取样。SHOW INNODB STATUS 的开头应该是：

1. =====================================
2. 060717 3:07:56 INNODB MONITOR OUTPUT
3. =====================================
4. Per second averages calculated from the last 44 seconds

数据的取样应该至少是20－30秒。最好是写一个脚本来统计 SHOW INNODB STATUS 的结果。

下面是 Semaphores 信息:

1. ----------
2. SEMAPHORES
3. ----------
4. OS WAIT ARRAY INFO: reservation count 13569, signal count 11421
5. --Thread 1152170336 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds the semaphore:
6. Mutex at 0x2a957858b8 created file buf0buf.c line 517, lock var 0
7. waiters flag 0
8. wait is ending
9. --Thread 1147709792 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds the semaphore:
10. Mutex at 0x2a957858b8 created file buf0buf.c line 517, lock var 0
11. waiters flag 0
12. wait is ending
13. Mutex spin waits 5672442, rounds 3899888, OS waits 4719
14. RW-shared spins 5920, OS waits 2918; RW-excl spins 3463, OS waits 3163

该部分有2部分。一个是当前等待列表，如果并发数很大，Innodb就必须频繁等待 OS。那么该部分不包含由spinlock解决的等待。

该部分需要对源代码有一定了解，因为只能看到文件名和行数。但可以从文件名猜出其含义－buf0buf.ic是缓存池的内容。

“lock var”是当前互斥对象(locked=1/free=0)的值，"waiters flag"是当前等待线程数，还有一些状态信息："wait is ending"意思是互斥锁已经释放，但OS还没有分配，这时这个对象可以执行。

第二部分是事件信息。"reservation count" 和 "signal count" 表明InnoDB使用内部同步数组的频繁程度。这些数值表示InnoDB需要等待OS的频率。"OS Waits" 表明由于互斥的OS的等待。OS Wait is not exactly the same as "reservation" - before falling back to complex wait using sync_array Innodb tries to "yield" to OS hoping when name thread is scheduled next time object will be free already. OS Waits 相对较慢，如果每秒钟该值有几万，就有问题。另外一种方式来看该值是通过OS状态的 context switch.

另一个重要信息是"spin waits"和"spin rounds"的数量。与OS wait相比，Spin locks 是低消耗的等待，但它是一种活跃的等待，会浪费CPU资源，因此spin waits和spin rounds 如果很大，CPU资源会被浪费。如果该值达到几十万，CPU危险了。

死锁部分：

1. ------------------------
2. LATEST DETECTED DEADLOCK
3. ------------------------
4. 060717 4:16:48
5. *** (1) TRANSACTION:
6. TRANSACTION 0 42313619, ACTIVE 49 sec, process no 10099, OS thread id 3771312 starting index read
7. mysql tables in use 1, locked 1
8. LOCK WAIT 3 lock struct(s), heap size 320
9. MySQL thread id 30898, query id 100626 localhost root Updating
10. update iz set pad='a' where i=2
11. *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
12. RECORD LOCKS space id 0 page no 16403 n bits 72 index `PRIMARY` of table `test/iz` trx id 0 42313619 lock_mode X locks rec but not gap waiting
13. Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
14. 0: len 4; hex 80000002; asc ;; 1: len 6; hex 00000285a78f; asc ;; 2: len 7; hex 00000040150110; asc @ ;; 3: len 10; hex 61202020202020202020; asc a ;;
15. 
    
16. *** (2) TRANSACTION:
17. TRANSACTION 0 42313620, ACTIVE 24 sec, process no 10099, OS thread id 4078512 starting index read, thread declared inside InnoDB 500
18. mysql tables in use 1, locked 1
19. 3 lock struct(s), heap size 320
20. MySQL thread id 30899, query id 100627 localhost root Updating
21. update iz set pad='a' where i=1
22. *** (2) HOLDS THE LOCK(S):
23. RECORD LOCKS space id 0 page no 16403 n bits 72 index `PRIMARY` of table `test/iz` trx id 0 42313620 lock_mode X locks rec but not gap
24. Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
25. 0: len 4; hex 80000002; asc ;; 1: len 6; hex 00000285a78f; asc ;; 2: len 7; hex 00000040150110; asc @ ;; 3: len 10; hex 61202020202020202020; asc a ;;
26. 
    
27. *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
28. RECORD LOCKS space id 0 page no 16403 n bits 72 index `PRIMARY` of table `test/iz` trx id 0 42313620 lock_mode X locks rec but not gap waiting
29. Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
30. 0: len 4; hex 80000001; asc ;; 1: len 6; hex 00000285a78e; asc ;; 2: len 7; hex 000000003411d9; asc 4 ;; 3: len 10; hex 61202020202020202020; asc a ;;
31. 
    
32. *** WE ROLL BACK TRANSACTION (2)

InnoDB只打印锁的几个信息，且只显示事务的最后一条语句，有可能被锁的行由前面一条语句引起。对复杂死锁的研究得看日志文件。

外键信息与死锁信息相似:

1. ------------------------
2. LATEST FOREIGN KEY ERROR
3. ------------------------
4. 060717 4:29:00 Transaction:
5. TRANSACTION 0 336342767, ACTIVE 0 sec, process no 3946, OS thread id 1151088992 inserting, thread declared inside InnoDB 500
6. mysql tables in use 1, locked 1
7. 3 lock struct(s), heap size 368, undo log entries 1
8. MySQL thread id 9697561, query id 188161264 localhost root update
9. insert into child values(2,2)
10. Foreign key constraint fails for table `test/child`:
11. ,
12. CONSTRAINT `child_ibfk_1` FOREIGN KEY (`parent_id`) REFERENCES `parent` (`id`) ON DELETE CASCADE
13. Trying to add in child table, in index `par_ind` tuple:
14. DATA TUPLE: 2 fields;
15. 0: len 4; hex 80000002; asc ;; 1: len 6; hex 000000000401; asc ;;
16. 
    
17. But in parent table `test/parent`, in index `PRIMARY`,
18. the closest match we can find is record:
19. PHYSICAL RECORD: n_fields 3; 1-byte offs TRUE; info bits 0
20. 0: len 4; hex 80000001; asc ;; 1: len 6; hex 0000140c2d8f; asc - ;; 2: len 7; hex 80009c40050084; asc @ ;;

看不懂的16进制信息没关系－那是程序的调试信息。

当前活跃的事务:

1. ------------
2. TRANSACTIONS
3. ------------
4. Trx id counter080157601
5. Purge done for trx's n:o <0 80154573 undo n:o <0 0
6. History list length 6
7. Total number of lock structs in row lock hash table 0
8. LIST OF TRANSACTIONS FOR EACH SESSION:
9. ---TRANSACTION 0 0, not started, process no 3396, OS thread id 1152440672
10. MySQL thread id 8080, query id 728900 localhost root
11. show innodb status
12. ---TRANSACTION 0 80157600, ACTIVE 4 sec, process no 3396, OS thread id 1148250464, thread declared inside InnoDB 442
13. mysql tables in use 1, locked 0
14. MySQL thread id 8079, query id 728899 localhost root Sending data
15. select sql_calc_found_rows * from b limit 5
16. Trx read view will not see trx with id>= 0 80157601, sees <0 80157597
17. ---TRANSACTION 0 80157599, ACTIVE 5 sec, process no 3396, OS thread id 1150142816 fetching rows, thread declared inside InnoDB 166
18. mysql tables in use 1, locked 0
19. MySQL thread id 8078, query id 728898 localhost root Sending data
20. select sql_calc_found_rows * from b limit 5
21. Trx read view will not see trx with id>= 0 80157600, sees <0 80157596
22. ---TRANSACTION 0 80157598, ACTIVE 7 sec, process no 3396, OS thread id 1147980128 fetching rows, thread declared inside InnoDB 114
23. mysql tables in use 1, locked 0
24. MySQL thread id 8077, query id 728897 localhost root Sending data
25. select sql_calc_found_rows * from b limit 5
26. Trx read view will not see trx with id>= 0 80157599, sees <0 80157595
27. ---TRANSACTION 0 80157597, ACTIVE 7 sec, process no 3396, OS thread id 1152305504 fetching rows, thread declared inside InnoDB 400
28. mysql tables in use 1, locked 0
29. MySQL thread id 8076, query id 728896 localhost root Sending data
30. select sql_calc_found_rows * from b limit 5
31. Trx read view will not see trx with id>= 0 80157598, sees <0 80157594

如果连接数量很大，InnoDB只能打印出其中的一部分，以维持整个列表的长度。

Transaction id是当前事务的标识符。Purge done for trx's n:o是 回收程序启动事务的数量。如果回收程序没有运行事务，InnoDB只能回收旧版本。旧的未提交事务可能会阻塞回收进程而吃掉资源。通过查看当前事务数和 最近一次回收事务数的差值就可以发现这个问题。在某些情况下，回收程序效率很低而要维持更新率，在这种情况下差值也会增加，这时innodb_max_purge_lag会有所帮助。"undo n:o"显示回收程序正在处理的undo日志记录数，如果当前没有回收程序运行，则该值为0。

History list length是在回滚段中为回收的事务数。当更新事务提交时该值增加，当回收线程运行时该值减少。

Total number of lock structs in row lock hash table是所有事务分配的行锁结构数。该值并不等于锁住的行数－因为一个锁结构中包含很多行。

MySQL的连接要么是not started状态（该连接没有活动的事务），要么是ACTIVE状态（有活动事务）。注意，尽管连接是"SLEEP"状态，但事务也可以是活跃的－如果事务中有多个语句。事务状态就是事务正在做什么，如"fetching rows","updating"。"Thread declared inside InnoDB 400"意思是线程正在InnoDB内核中运行，当前还可以有400个线程可以进来。InnoDB限制内核中的并发线程数使用变量innodb_thread_concurrency 。如果线程没在InnoDB内核中运行，状态应该是"waiting in InnoDB queue" 或"sleeping before joining InnoDB queue"。为避免太多线程竞争进入InnoDB队列，InnoDB有时会让线程先sleep，而不是wait。这样就会使InnoDB内核中的活跃线程少于innodb_thread_concurrency。这会减少线程等待进入队列的时间，可以调整innodb_thread_sleep_delay的值，该值为微秒。

mysql tables in use 1, locked 0是由线程正使用的表数，和线程锁住的表数。InnoDB一般不会锁表，因此该值一般为0，除非ALTER TABLE或LOCK TABLES相似的操作。

文件I/O:

1. --------
2. FILE I/O
3. --------
4. I/O thread0state: waiting for i/o request(insert buffer thread)
5. I/O thread1state: waiting for i/o request(log thread)
6. I/O thread2state: waiting for i/o request(read thread)
7. I/O thread3state: waiting for i/o request(write thread)
8. Pending normal aio reads:0, aio writes:0,
9. ibuf aio reads:0, log i/o's: 0, sync i/o's:0
10. Pending flushes(fsync)log:0; buffer pool:0
11. 17909940OS file reads,22088963OS file writes,1743764OS fsyncs
12. 0.20reads/s,16384avg bytes/read,5.00writes/s,0.80fsyncs/s

IO的四个进程（括号中的名字）。插入缓存合并，异步刷新，read－ahead和脏缓存刷新。如果线程准备好了则为waiting for i/o request状态，否则它就正在执行某种操作。

Number of pending operation is shown for each of helper threads - these are amount of operations queued for execution or being executed at the same time. Also number of pending fsync operations is displayed. For writes Innodb has to ensure data makes it to the disk - just passing it to OS cache is not enough. This is typically done by calling fsync() for modified files. Constant high values for any of these variables is indication of IO bound workload. Note however - IO requests submited by threads executing requests are not accounted here so you may have these at zeroes while workload being IO bound still.

Next, number of file IO operations is shown as well as computed averages. This is parameters which is great for graphing and monitoring.
"16384 avg bytes/read"shows average size of read requests. For random IO these should be 16K - page size, for full table scan or index scan read-ahead may be performed which can increase average read size significantly. So you can think about this value as read-ahead efficiency.

PLAIN TEXT

CODE:

1. -------------------------------------
2. INSERT BUFFER AND ADAPTIVE HASH INDEX
3. -------------------------------------
4. Ibuf for space0: size1, free list len887, seg size889, is not empty
5. Ibuf for space0: size1, free list len887, seg size889,
6. 2431891inserts,2672643merged recs,1059730merges
7. Hash table size8850487, used cells2381348, node heap has4091buffer(s)
8. 2208.17hash searches/s,175.05non-hash searches/s

This section shows insert buffer and adaptive hash status. First line shows status of insert buffer - segment size and free list as well as if
there are any records is insert buffer. Next it shows how many inserts were done in insert buffer, how many recs were merged and how many merges did it took. Ratio of number of merges to number of inserts is pretty much insert buffer efficiency.

Adaptive hash index is hash index Innodb builds for some pages to speed up row lookup replacing btree search with hash search. This section shows hash table size, number of used cells and number of buffers used by adaptive hash index. You can also see number of hash index lookups and number of non-hash index lookups which is indication of hash index efficiency.

There is currently not much you can do to adjust adaptive hash index or insert buffer behavīor so it is pretty much for informational purposes only.

PLAIN TEXT

CODE:

1. ---
2. LOG
3. ---
4. Log sequence number843000620880
5. Log flushed up to843000611265
6. Last checkpoint at842939889199
7. 0pending log writes,0pending chkp writes
8. 14073669log i/o's done, 10.90 log i/o's/second

Log section provides information about log subsystem of Innodb. You can see current log sequence number - which is amount of bytes Innodb has written in log files since system tablespace creation. You can also see up to which point logs have been flushed - so how much data is unflushed in log buffer as well as when last checkpoint was performed. Innodb uses fuzzy checkpointing so this line hold log sequence, all changes up to which has been flushed from buffer pool. Changes having higher log sequences may still only be recored in logs and not flushed from buffer pool so such log sequences can't be overwritten in log files. By monitoring log sequence number and value up to which logs have been flushed you can check if yourinnodb_log_buffer_sizeis optimal - if you see more than 30% of log buffer size being unflushed you may want to increase it.

You also can see number of pending normal log writes and number of checkpoint log writes. Number of log/io operations allows to separate tablespace related IO from log related IO so you can see how much IO your log file requires. Note depending on yourinnodb_flush_log_at_trx_commitvalue your log writes may be more or less expensive. If innodb_flush_logs_at_trx_commit=2 log writes are done to OS cache, and being sequential writes these logs writes are pretty fast.

PLAIN TEXT

CODE:

1. ----------------------
2. BUFFER POOL AND MEMORY
3. ----------------------
4. Total memory allocated4648979546; in additional pool allocated16773888
5. Buffer pool size262144
6. Free buffers0
7. Database pages258053
8. Modified db pages37491
9. Pending reads0
10. Pending writes: LRU0, flush list0, single page0
11. Pages read57973114, created251137, written10761167
12. 9.79reads/s,0.31creates/s,6.00writes/s
13. Buffer pool hit rate999/1000

该部分描述了内存的使用情况。包括的信息有：InnoDB分配的总内存，额外分配的内存，缓存池中的页数，空闲页数，页和脏页数。从这些值中 可以看出是否InnoDB缓存分配得恰当－如果总有很多空闲页，表明数据库要比内存小，可以把innoDB缓存调小些。如果空闲页为0，那么数据库页不会 和缓存容量相同，因为还要存锁、索引和得系统结构。

Pending reads and writes are pending requests on buffer pool level. Innodb may merge multiple requests to one on file level so these are different. We can also see different types of IO submited by Innodb - pages to be flushed via LRU pages - dirty pages which were not accessed long time, flush list - old pages which need to be flushed by checkpointing process and single page - independent page writes.

We can also see number of pages being read and written. Created pages is empty pages created in buffer pool for new data - when previous page content was not read to the buffer pool.

Finally you can see buffer pool hit ratio which measures buffer pool efficiency. 1000/1000 corresponds to 100% hit rate. It is hard to tell what buffer pool hit rate is good enough - it is very workload dependent. Sometimes 950/1000 will be enough, sometimes you can see IO bound workload with hit rate of 995/1000.

PLAIN TEXT

CODE:

1. --------------
2. ROW OPERATIONS
3. --------------
4. 0queries inside InnoDB,0queries in queue
5. 1read views open inside InnoDB
6. Main thread process no.10099, id88021936, state: waiting for server activity
7. Number of rows inserted143, updated3000041, deleted0, read24865563
8. 0.00inserts/s,0.00updates/s,0.00deletes/s,0.00reads/s

Finally last section - row operations which shows activity on the row basics and some system information.

It shows innodb thread queue status - how many threads are waiting and being active. How many read views are open inside Innodb - this is when transaction was started but no statement is currently active, state of Innodb main thread which controls scheduling of number of system operations - flushing dirty pages, checkpointing, purging, flusing logs, doing insert buffer merge. Values for"state"field are rather self explanatory.

You can also see number of rows operation since system startup as well as average values. This is also very good values to monitor and graph - row operations is very good measure of Innodb load. Not all row operations are created equal of course and accessing of 10 byte rows is much cheaper than accessing 10MB blog, but it is still much more helpful than number of queries, which is even more different.

One more thing to note - SHOW INNODB STATUS is not consistent - it does not correspond to some particular point in time. Different lines in SHOW INNODB STATUS populated in different point in times, so sometimes you may see a bit conflicting information. This is by design as requiring global lock to provide consitent information would cause significant overhead.