SHOWENGINE INNODB STATUS詳細介紹

SHOWENGINE INNODB STATUS詳細介紹

很多人用過SHOW ENGINE INNODB STATUS來檢視伺服器資訊以及定位問題，但它的輸出内容比較複雜難懂。而網上也基本沒有這方面的介紹材料– 特别是中文資料。

本文接下來詳細介紹這些資訊的含義，也包含一些資訊産生的前因後果。希望能對你有所幫助，也希望各位看客對于文中的錯誤加以指正。

Header

這部分簡單的列印，輸出的時間，以及自從上次輸出的間隔時間。

1 =====================================

2 07091310:31:48 INNODB MONITOR OUTPUT

3 =====================================

4 Persecond averages calculated from the last 49 seconds

SEMAPHORES

如果你有一個高并發的系統，你需要關注這一部分的輸出。

它由兩部分組成，event counters, 和可選項輸出,即目前等待的事件(current waits)。

下面給出了一個示例輸出。

1 ----------

2 SEMAPHORES

3 ----------

4 OSWAIT ARRAY INFO: reservation count 13569, signal count 11421

5 --Thread1152170336 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds

the semaphore:

6 Mutexat 0x2a957858b8 created file buf0buf.c line 517, lock var 0

7 waitersflag 0

8 waitis ending

9 --Thread1147709792 has waited at ./../include/buf0buf.ic line 630 for 0.00 seconds

10 Mutexat 0x2a957858b8 created file buf0buf.c line 517, lock var 0

11 waitersflag 0

12 waitis ending

13 Mutexspin waits 5672442, rounds 3899888, OS waits 4719

14 RW-sharedspins 5920, OS waits 2918; RW-excl spins 3463, OS waits 3163

第4行表示，OS WAIT的資訊，reservation count表示Innodb産生了多少次OS WAIT, signal count表示，進行OS WAIT的線程，接收到多少次信号（singal）被喚醒。

如果你看到signal的數值很大，通常是幾十萬，上百萬。就表明，可能是很多I/O的等待，或是Innodb争用(contention)問題。關于争用問題，可能與OS的程序排程有關，你可嘗試減少innodb_thread_concurrency參數。

在接下來，下面的介紹之前，有必要明白什麼是OS Wait,什麼是spin wait。

要明白這個，首先你要明白Innodb如何處理互斥量(Mutexes)，以及什麼是兩步獲得鎖(two-step approach)。首先程序，試圖獲得一個鎖，如果此鎖被它人占用。它就會執行所謂的spin wait,即所謂循環的查詢”鎖被釋放了嗎？”。如果在循環過程中，一直未得到鎖釋放的資訊，則其轉入OS WAIT，即所謂線程進入挂起(suspended)狀态。直到鎖被釋放後，通過信号(singal)喚醒線程。

• Mutex spin     waits 是線程無法擷取鎖，而進入的spin wait
• rounds 是spin wait進行輪詢檢查Mutextes的次數
• OS waits 是線程放棄spin-wait進入挂起狀态

Spin wait的消耗遠小于OS waits。Spinwait利用cpu的空閑時間，檢查鎖的狀态，OS Wait會有所謂content switch，從CPU核心中換出目前執行線程以供其它線程使用。你可以通過innodb_sync_spin_loops參數來平衡spin wait和os wait。

http://dev.mysql.com/doc/refman/5.6/en/innodb-parameters.html#sysvar_innodb_sync_spin_loops

5-12行，顯示的是具體争用（contention）等待的事件，這個要求你對于MySQL的代碼比較熟悉。

如示例，buf0buf.c實際上表示伺服器有buffer pool争用的情況。

13-14顯示了更詳細的鎖（Mutexes）的資訊，如RW-shared表示共享鎖，RW-excl表示排它鎖

LATEST DETECTED DEADLOCK

當你伺服器發生了死鎖的情況時，這部分會顯示出來。死鎖通常的原因很複雜，但是這一部分隻會顯示最後兩個發生死鎖的事務，盡管可能也有其它事務也包含在死鎖過程中。不過，盡管資訊被删減了，通常你也能夠通過這些資訊找出死鎖的原因。

下面給出了一個例子：

1 ------------------------

2 LATESTDETECTED DEADLOCK

3 ------------------------

4 07091311:14:21

5 ***(1) TRANSACTION:

6 TRANSACTION0 3793488, ACTIVE 2 sec, process no 5488, OS thread id 1141287232

startingindex read

7 mysqltables in use 1, locked 1

8 LOCKWAIT 4 lock struct(s), heap size 1216

9 MySQLthread id 11, query id 350 localhost baron Updating

10 UPDATEtest.tiny_dl SET a = 0 WHERE a <> 0

11 ***(1) WAITING FOR THIS LOCK TO BE GRANTED:

12 RECORDLOCKS space id 0 page no 3662 n bits 72 index `GEN_CLUST_INDEX` of table

`test/tiny_dl`trx id 0 3793488 lock_mode X waiting

13 Recordlock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0

14 0:len 6; hex 000000000501 ...[ omitted ] ...

15

16 ***(2) TRANSACTION:

17 TRANSACTION0 3793489, ACTIVE 2 sec, process no 5488, OS thread id 1141422400

startingindex read, thread declared inside InnoDB 500

18 mysqltables in use 1, locked 1

19 4lock struct(s), heap size 1216

20 MySQLthread id 12, query id 351 localhost baron Updating

21 UPDATEtest.tiny_dl SET a = 1 WHERE a <> 1

22 ***(2) HOLDS THE LOCK(S):

23 RECORDLOCKS space id 0 page no 3662 n bits 72 index `GEN_CLUST_INDEX` of table

`test/tiny_dl`trx id 0 3793489 lock mode S

24 Recordlock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0

25 0:... [ omitted ] ...

26

27 ***(2) WAITING FOR THIS LOCK TO BE GRANTED:

SHOW INNODB STATUS | 571

28 RECORDLOCKS space id 0 page no 3662 n bits 72 index `GEN_CLUST_INDEX` of table

`test/tiny_dl`trx id 0 3793489 lock_mode X waiting

29 Recordlock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0

30 0:len 6; hex 000000000501 ...[ omitted ] ...

31

32 *** WE ROLL BACK TRANSACTION (2)

第4行顯示了死鎖發生的時間。第5-10行，顯示了第一個死鎖的第一個事務，下一節我會繼續詳細說明它的意思。

11-15行顯示了死鎖發生時事務1等待的鎖。14行，可以忽略，顯示的資訊隻有在調試Innodb時有用。重要的是12行，它說明了事務想獲得test.tiny_dl 表的GEN_CLUST_INDEX* 索引對應的X 排它鎖（有必要說明一下，Innodb的鎖是與索引相關的，具體可以看我的部落格關于Innodb鎖的介紹）。

16-21行顯示了事務2的狀态，22-26顯示了事務2獲得的鎖，27-31顯示了事務2等待的鎖。

Innodb不會顯示目前事務所有獲得的，以及等待的鎖，但它給予了足夠的資訊，如目前查詢使用的索引，它會幫助你定位問題以及如何避免死鎖。當然，這類資訊通常不是那麼的直覺，你可以通過列印出了SQL語句，以及索引等資訊，找到問題代碼，進行分析。

32行，顯示了它選擇哪一個事務復原，以避免無限期的死鎖等待。關于這點，Innodb有一個内在的死鎖檢測機制，當死鎖等待超過一定時間後，就會復原其中一個事務。innodb_lock_wait_timeout可配置死鎖的等待逾時時間。

TRANSACTIONS

這一部分包含Innodb 事務（transactions）的統計資訊，還有目前活動的事務清單。

接下來，先介紹開始的統計部分

1 ------------

2 TRANSACTIONS

3 ------------

4 Trx id counter 080157601

5 Purge done fortrx's n:o <0 80154573 undo n:o <0 0

6 History listlength 6

7 Total number oflock structs in row lock hash table 0

第4行顯示的是目前的transaction id, 這個ID是一個系統變量随時每次新的transaction産生而增加。

第5行顯示的正在進行清空（purge）操作的transaction ID。你可以通過檢視第4和第5行ID的差別，明白沒有被purge的事務落後的情況。關于什麼是purge操作，我在下面進行了詳細說明。

第6行，記錄了undo spaces内unpurged的事務的個數。

（注：有心人也許會計算4,5行ID之差，與第6行的這個數值比較，可能會發現完全不比對。這點我也困惑了一段時間。其實是這樣，事務的ID并不是按順序purge的，是以有可能ID大于第5行目前purge的ID的事務，已經在前面被purge了。Purge的原則就是記錄沒有被其它事務繼續使用了。）

第7行，英文的原文解釋如下，這個我沒弄明白。the number of lock structs. Each lock struct usually holds many row locks,so this is not the same as the number of rows locked.

什麼是purge操作

要明白什麼清空（purge）操作，你得明白什麼是事務的多版本控制，即MVCC(multi-version concurrency control)。Innodb為了實作MVCC，需要在表空間内儲存老版本的記錄資訊，這些資訊存儲于復原段中（rollback segment），所謂復原段，在實體存儲上是UNDO log的記錄。

Purge到底做了些什麼？其實它就相當于一個垃圾收集器。取個例子，當使用者下一個指令，如 “DELETE FROM t WHERE c = 1;”, InnoDB 不會馬上删除對應的記錄，它會做如下三件事情:

1. 它标記此記錄為删除（通過删除标記位）
2. 存儲原始的記錄到UNDO log
3. 更新記錄列DB_TRX_ID和DB_ROLL_PTR（這些列是Innodb在原記錄列上增加的）。DB_TRX_ID記錄了最後操作記錄的事務ID。DB_ROLL_PTR也叫復原指針(rollback pointer)，指向UNDO log 記錄，此UNDO Log記錄了原始記錄的資訊，這些資訊可以用來重建原始記錄（如發生了rollback的情況）。如果操作是插入，還會有一個

   DB_ROW_ID

   ，這個指明了新記錄的行号

   .

當事務送出後，那些标記了删除的記錄，以及UNDOLog中的記錄并不會馬上清除，這些記錄資訊可以被其它事務所重用，或是共享。隻有當沒有任何事務共享這些記錄的時候，這些記錄才會被清除（purge）。這就是所謂purge操作。而為了提高資料庫的操作效率，purge操作是由另外的線程異步完成。這就是為何前面你所看到的為何存在unpurged的事務的原因。

接下來，是事務的清單，如下有一個例子。

1 ---TRANSACTION0 80157600, ACTIVE 4 sec, process no 3396, OS thread id 1148250464,

thread declared inside InnoDB 442

2 mysqltables in use 1, locked 0

3 MySQLthread id 8079, query id 728899 localhost baron Sending data

4 selectsql_calc_found_rows * from b limit 5

5 Trxread view will not see trx with id>= 0 80157601, sees <0 80157597

第 1 行顯示了事務ID。ACTIVE 4 sec表示事務處于ACTIVE狀态已經4秒鐘了。其它可能的狀态還包括“not started,” “active,” “prepared,” and “committedin memory”(once it commits to disk, the state willchange to “not started”)

“threaddeclared inside InnoDB 442”表示，這個thread處于Innodb核心，還有422個tickets可以使用。有一個參數，innodb_concurrency_tickets可以配置一個thread可用的tickets數。

何謂tickets數呢？當Innodb内部線程達到innodb_thread_concurrency上限時，新的thread就需要在thread隊列内排隊等待進行Innodb核心執行。Thread tickets可以讓已經進行Innodb核心的線程，可以執行多次（即多次執行一個時間片周期），這個次數由tickets來決定。直到用完tickets，此線程才會換出核心進入隊列。這樣做的用處是避免所謂threadthrashing問題，避免線程不停的從核心中換入換出。

一個常見的例子是，如果你有執行時間長的SQL語句在指定tickets内還無法完成，這樣就會被換出核心。如此增加的thread的context switch的開銷是驚人的。在這種情況下，可考慮增大tickets的值。

第2行，顯示了目前事務鎖定的資料表

第3行顯示了thread id,這個值與是在show full processlist 指令顯示的程序ID是一樣的。

第4行顯示了目前事務執行的SQL語句。

第5行，顯示了MVCC,多版本并發控制的資訊，表明了哪些其它事務可以看到此記錄，哪些不能。

FILE I/O

FILE I/O部分顯示了I/O Helper thread的狀态，包括一些統計資訊

1 --------

2 FILEI/O

3 --------

4 I/Othread 0 state: waiting for i/o request (insert buffer thread)

5 I/Othread 1 state: waiting for i/o request (log thread)

6 I/Othread 2 state: waiting for i/o request (read thread)

7 I/Othread 3 state: waiting for i/o request (write thread)

8 Pendingnormal aio reads: 0, aio writes: 0,

9 ibufaio reads: 0, log i/o's: 0, sync i/o's: 0

10 Pendingflushes (fsync) log: 0; buffer pool: 0

11 17909940OS file reads, 22088963 OS file writes, 1743764 OS fsyncs

12 0.20 reads/s, 16384 avg bytes/read, 5.00 writes/s, 0.80fsyncs/s

4-7行顯示了I/O helper thread 的狀态.

8-10行顯示了各個I/O helper thread的pending operations, pending的log和buffer pool thread的fsync()調用。關于什麼是fsync()調用，以及為何有fsync調用，我會專門再拿出一章來說明。請大家等待我的部落格後繼更新。

11行顯示了reads, writes, and fsync()調用次數。

12行顯示了每秒的統計資訊

第8-9行可以用來檢測I/O-bound問題，如果出現很多pending operations，很有可能你的伺服器出現了I/O-bound問題。其中縮略詞“aio”表示“ 異步I/O(asynchronous I/O).”

INSERT BUFFER AND ADAPTIVE HASHINDEX

1 -------------------------------------

2 INSERTBUFFER AND ADAPTIVE HASH INDEX

3 -------------------------------------

4 Ibuffor space 0: size 1, free list len 887, seg size 889, is not empty

5 Ibuffor space 0: size 1, free list len 887, seg size 889,

6 2431891inserts, 2672643 merged recs, 1059730 merges

7 Hashtable size 8850487, used cells 2381348, node heap has 4091 buffer(s)

8 2208.17 hash searches/s, 175.05 non-hash searches/s

第4行顯示了insertbuffer的一些資訊，包括free list, segment size

其中space 0，表示可能有多個insert buffer, 如space 0, space 1等。但實際上MySQL并沒有多個insert buffer,是以你能看到4,5行是重複的。這算是一個多餘的輸出。在新版本中，去除了此輸出。

第6行顯示了Innodb進行了多少次buffer操作。通過比較 inserts和 merges，可以看出insert buffer的效率

第7行顯示了hash table的一些資訊

第8行顯示了每秒進行了多少次hash搜尋，以及非hash搜尋

LOG

這裡記錄了tansaction log子系統的資訊（如果你不記得了，請看FILE I/O那一節所看到的I/O Helper Thread）

1 ---

2 LOG

3 ---

4 Logsequence number 84 3000620880

5 Logflushed up to 84 3000611265

6 Lastcheckpoint at 84 2939889199

7 0pending log writes, 0 pending chkp writes

8 14073669 log i/o's done, 10.90 log i/o's/second

第4行，顯示了目前的log sequencenumber。Log sequence number表示有多少位元組寫入到了log檔案内

第5行，顯示了已經被flushed(寫入磁盤)的logs

第6行，顯示了最後一個checkpoint的logs

第7，8行，顯示了pending log 的統計資訊

BUFFER POOL AND MEMORY

1 ----------------------

2 BUFFERPOOL AND MEMORY

3 ----------------------

4 Totalmemory allocated 4648979546; in additional pool allocated 16773888

5 Bufferpool size 262144

6 Freebuffers 0

7 Databasepages 258053

8 Modifieddb pages 37491

9 Pendingreads 0

10 Pendingwrites: LRU 0, flush list 0, single page 0

11 Pagesread 57973114, created 251137, written 10761167

12 9.79reads/s, 0.31 creates/s, 6.00 writes/s

13 Buffer pool hit rate 999 / 1000

第4行顯示了配置設定給Innodb的記憶體大小，以及additional pool使用的大小（如果沒有使用，會顯示為0）

第5-8行顯示了buffer pool的資訊。分别顯示了Buffer pool大小，空閑的buffers, database pages, 髒頁(dirty pages)。你會看到buffer pool size比database pages要大，這是因為buffer pool還會存放lock index, hash index等一些其它的系統資訊。

9-10行顯示了pending的reads 和writes

11行顯示了Innodb讀寫和建立的頁面（pages）

13行顯示了Innodb的buffer pool命中率，通常要保證在998/1000以上。如果沒有，可考慮增大buffer pool size，以及優化你的查詢

ROW OPERATIONS

這一部分顯示了rowoperation及其它的一些統計資訊

1 --------------

2 ROWOPERATIONS

3 --------------

4 0queries inside InnoDB, 0 queries in queue

5 1read views open inside InnoDB

6 Mainthread process no. 10099, id 88021936, state: waiting for server activity

7 Numberof rows inserted 143, updated 3000041, deleted 0, read 24865563

8 0.00inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

9 ----------------------------

10 ENDOF INNODB MONITOR OUTPUT

11 ============================

第4行顯示了有多少線程在Innodb核心（你可回顧transaction一章）

第5行顯示了有多少read view被打開了，一個read view是一緻性保證的MVCC “snapshot”

第6行顯示了核心的main thread的狀态資訊，其餘可能的狀态還會有：

archiving log (if log archive is on)

doing background droptables

doing insert buffer merge

flushing buffer pool pages

flushing log

making checkpoint

purging

reserving kernel mutex

sleeping

suspending

waiting for buffer poolflush to end

waiting forser veractivity

7-8行顯示了行操作(rowoperation)的一些統計資訊。