SHOW INNODB STATUS 探祕

[InnoDB系列] -- SHOW INNODB STATUS 探祕

SHOW INNODB STATUS 探祕

原文譯自:http://www.mysqlperformanceblog.com/2006/07/17/show-innodb-status-walk-through/node

 

不少人讓我來闡述一下 SHOW INNODB STATUS 的輸出信息, 瞭解 SHOW INNODB STATUS 都輸出了些什麼信息,而且咱們能從這些信息中獲取什麼資訊,得以提升 MySQL 性能。mysql

首先,讓咱們來了解一下 SHOW INNODB STATUS 輸出的基礎,它打印了不少關於 InnoDB 內部性能相關的計數器、統計、事務處理信息等。在 MySQL 5 中,InnoDB 的性能統計結果也在 SHOW STATUS 結果中顯示了。大部分和 SHOW INNODB STATUS 的其餘信息相同,在舊版本中尚未這個功能。web

SHOW INNODB STATUS 中的不少統計值都是每秒更新一次的,若是你打算利用這些統計值的話,那麼最好統計一段時間內的結果。InnoDB 首先輸出如下信息:sql

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

首先要確認這是至少統計了 20-30 秒的樣本數據。若是平均統計間隔是0或1秒,那麼結果就沒什麼意義了。
說實在的我不喜歡InnoDB提供的平均值,由於很難取得合理的平均間隔統計值,若是你是寫腳原本取得 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 會頻繁回退到系統等待。若是等待是經過自旋鎖來解決的話,那麼這些信息就就不會顯示了。併發

經過這部分信息,你就會知道系統負載的熱點在哪了。不過這須要瞭解一下源碼相關的知識 - 從上面的信息中就能夠看出來是哪一個源碼文件中的哪行(不一樣的版本結果可能不一樣),只是從這裏卻看不出來任何信息。儘管如此,仍是能夠從文件名中猜到一些東西 - 好比本例中,文件名 "buf0buf.ic" 預示着和一些緩衝池爭奪有關係。若是想了解更多,就去看源碼吧。異步

還有一些關於等待的更多細節。"lock var" 表示當前的 mutex 對象的值(被鎖住 = 1 / 釋放 = 0) 值,"waiters flag" 表示當前的等待個數。另外,本例中還能夠看到等待狀態信息 "wait is ending",這表示 mutex 已經釋放,可是系統調度線程還正在處理。ide

第二塊是事件統計 - "reservation count" 和 "signal count" 顯示了 innodb 使用內部同步陣列的活躍程度 - 時間片(slot)分配以及線程信號使用同步陣列的頻繁程度。這些統計信息能夠用於表示 innodb 回退到系統等待的頻率。還有關於系統等待的直接相關信息,能夠看到"OS Waits"的互斥信號燈(mutexes),以及讀寫鎖。這些信息中顯示了互斥鎖和共享鎖。系統等待和 "保留(reservation)" 不徹底同樣,在回退到用 sync_array 的複雜等待模式前,innodb 會嘗試 "輸出(yield)" 到系統,但願下一次調度時間對象裏命名線程已經釋放了。系統等待相對較慢,若是每秒發生了上萬次系統等待,則可能會有問題。另外一個觀察方法是查看系統狀態中的上下文(context)交換頻率。高併發

另外一塊重要的信息是 "spin waits" 和 "spin rounds" 的數量。相較於系統等待,自旋鎖是低成本的等待;不過它是一個活躍的等待,會浪費一些cpu資源。所以若是看到大量的自旋等待和自旋輪轉,則很顯然它浪費了不少cpu資源。浪費cpu時間和無謂的上下文切換之間能夠用 innodb_sync_spin_loops 來平衡。

接下來的這段顯示死鎖情況:

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 最後檢測到事務引起的死鎖,包括髮生死鎖時的狀態,加了什麼鎖,在等待什麼鎖釋放,以及 Innodb 決定哪一個事務會被回滾。注意,innodb只顯示了事務持有鎖的相關簡單信息。而且只顯示了每一個事務最後執行的語句,發生死鎖的記錄就是因爲這些語句引發的。查看複雜的死鎖信息還須要查看日誌文件,才能找到真正引起衝突的語句。大部分狀況下,SHOW INNODB STATUS 顯示的信息基本足夠了。

下面是關於外鍵約束引起的死鎖信息:

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    @   ;;

Innodb會顯示引起錯誤的語句。外鍵約束定義失敗,以及定義關係最密切的父表。有不少嵌接信息都是用16進製表示,不過對於問題診斷並非過重要,它們主要用於給 Innodb 的開發者來查看或者用於調試目的。

接下來是顯示 Innodb 當前活躍的事務:

1.------------
2.TRANSACTIONS
3.------------
4.Trx id counter 0 80157601
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 只會顯示他們的數量,減小輸出的列表信息,使得輸出結果不會太多。

事務ID是當前事務的標識,事務的id每次都會增長。Purge done for trx's n:o 是指淨化(purge)線程已經完成的事務數。Innodb僅清除那些被當前事務認爲再也不須要的舊版本數據。那些未提交的舊事務可能會阻塞淨化線程而且消耗資源。經過查看2次清除事務數之差,就能夠知道是否發生了這種狀況。少數狀況下,淨化線程可能難以跟上更新的速度,2次查看值之差可能會愈來愈大;那麼,innodb_max_purge_lag 就派得上用場了。 "undo n:o" 顯示了淨化線程當前正在處理的回滾日誌號,若是當前不處於活躍狀態,則它的值是 0。

History list length 6 是指在回滾空間中的未清除事務數。隨着事務的提交,它的值會增長;隨着清除線程的運行,它的值會減少。

Total number of lock structs in row lock hash table 是指事務分配過的行鎖結構總數。它和曾經被鎖住過的行總數不必定相等,一般是一個鎖結構對應多行記錄。

MySQL中,每一個鏈接若是沒有活動的事務,則它的狀態是 not started,若是有活動的事務,則是 ACTIVE。注意,儘管事務是活動的,可是其鏈接的狀態卻多是 "睡眠(sleep)" - 若是是在一個有多條語句的事務裏的話。Innodb 會同時顯示系統的線程號以及進程號,這有助於利用gdb來調試或者其餘相似用途。另外,事務的狀態也會根據當前實際狀態來顯示,例如 "讀取記錄(fetching rows)",em>"更新(updating)"等等。"Thread declared inside InnoDB 400" 的意思是 Innodb 內核正在運行該線程,而且還須要400個票。Innodb 會根據 innodb_thread_concurrency 的值來限制同時併發的線程數不超過它。若是線程當前不在 Innodb 的內核中運行,則它的狀態多是"waiting in InnoDB queue"  "sleeping before joining InnoDB queue"。後面這個狀態有點意思 - Innodb 爲了不有太多的線程同時搶着要進入運行隊列,那麼就會嘗試讓這些線程進入等待狀態(若是沒有足夠的空閒插槽(slot)的話)。這就可能會致使 Innodb 內核中當前活躍的線程數可能比 innodb_thread_concurrency 的值還小。某種負載環境下,這可能有助於減少線程進入隊列的時間。能夠經過調整innodb_thread_sleep_delay 來實現,它的單位是微妙。

mysql tables in use 1, locked 0 是指事務中已經用過的數據表個數(已經訪問過了的),以及被鎖的個數。Innodb 通常狀況不會鎖表,所以鎖表數通常是0,除非是 ALTER TABLE 或者其餘相似 LOCK TABLES 的語句。

除了Innodb相關的特定信息外,一些基本信息能夠經過  來查看,例如正在執行什麼語句,查詢ID號,查詢狀態等。

下面這部分顯示的是跟IO相關的具體信息:

1.--------
2.FILE I/O
3.--------
4.I/O thread 0 state: waiting for i/o request (insert buffer thread)
5.I/O thread 1 state: waiting for i/o request (log thread)
6.I/O thread 2 state: waiting for i/o request (read thread)
7.I/O thread 3 state: 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.17909940 OS file reads, 22088963 OS file writes, 1743764 OS fsyncs
12.0.20 reads/s, 16384 avg bytes/read, 5.00 writes/s, 0.80 fsyncs/s

本部分顯示了IO助手線程狀態 - 插入緩衝線程,日誌線程,讀、寫線程。它們分別對應插入緩衝合併,異步日誌刷新,預讀以及刷新髒數據。源自查詢的正常讀取是由正在運行的查詢執行的。在Unix/Linux平臺下,總能看見4個線程,在Windows上能夠經過innodb_file_io_threads 來調整。每一個線程準備好以後都能看到其狀態:waiting for i/o request 或者正在執行特定的操做。

每一個線程都會顯示正在進行的操做數量 - 同時正要執行或者正在執行的操做數量。另外,正在執行的 fsync 操做數量也會顯示出來。有寫數據時,Innodb須要確保數據最終被寫到磁盤上,只是把它們放在系統緩存裏是不夠的。一般是調用 fsync() 來完成的。若是它的值一直很高,那意味這Innodb多是處於IO負載較高狀態。注意,由線程執行請求引起的IO請求是不計算在內的,所以儘管系統的IO負載較高,可是它們的值卻可能爲 0。

接下來顯示的是IO操做的平均統計值,它們對於圖形顯示或者監控頗有用。
"16384 avg bytes/read" 是讀請求的平均值。隨機IO的話,每一個頁的大小是16K,全表掃描或索引掃描時的預讀會致使這個值明顯的增長。所以,它體現了預讀的效率。

1.-------------------------------------
2.INSERT BUFFER AND ADAPTIVE HASH INDEX
3.-------------------------------------
4.Ibuf for space 0: size 1, free list len 887, seg size 889, is not empty
5.Ibuf for space 0: size 1, free list len 887, seg size 889,
6.2431891 inserts, 2672643 merged recs, 1059730 merges
7.Hash table size 8850487, used cells 2381348, node heap has 4091 buffer(s)
8.2208.17 hash searches/s, 175.05 non-hash searches/s

本部分顯示了插入緩衝以及自適應哈希索引的狀態。第一行顯示了插入緩衝的狀態 - 段的大小以及空閒列表,以及緩衝中有多少記錄。接下來顯示了緩衝中已經完成了多少次插入,有多少記錄已經合併,有多少次合併已經完成。合併次數除以插入次數獲得的比率能夠反映出插入緩衝的效率如何。

Innodb採用哈希索引創建內存頁索引造成自適應哈希索引而不是採 B-tree 索引,得以加速行記錄到內存頁的檢索。這裏顯示了哈希表的大小,以及自適應哈希索引使用了多少單元和緩衝。能夠經過計算利用哈希索引檢索的次數以及沒利用它檢索的次數來了解哈希索引的效率。

當前對自適應哈希索引基本沒有什麼辦法能夠調整它,主要仍是用於查看。

1.---
2.LOG
3.---
4.Log sequence number 84 3000620880
5.Log flushed up to   84 3000611265
6.Last checkpoint at  84 2939889199
7.0 pending log writes, 0 pending chkp writes
8.14073669 log i/o's done, 10.90 log i/o's/second

接下來顯示的是Innodb的日誌子系統相關信息。能夠看到當前的日誌序列號 - 至關於Innodb自從表空間開始建立直到如今已經寫入日誌文件的總字節數。還能夠看到日誌已經刷新到哪一個點,一樣也能夠根據最後檢查點計算出還有多少日誌沒有刷新到文件中去。Innodb採用模糊檢查點,所以這行顯示的是已經從緩衝池中刷新到文件的日誌序列號。因爲更高的日誌序列號可能不會被馬上刷新到日誌文件中去,所以日誌序列號不能被覆蓋掉。經過監控刷新到哪一個日誌的日誌序列,能夠斷定 innodb_log_buffer_size的設置是否合理,若是看到超過 30% 的日誌尚未刷新到日誌文件中,則須要考慮增長它的值了。

另外,還能看到日誌寫入以及檢查點的數目。根據日誌 I/O 操做的數目能夠區分開表空間相關的IO請求和日誌IO請求數量,進而能夠肯定到底須要幾個日誌文件。注意,innodb_flush_log_at_trx_commit 的值能夠影響到日誌寫操做的代價高或低。若是 innodb_flush_logs_at_trx_commit=2,則日誌是寫到系統緩存,而後再順序寫到日誌文件中,所以相對會快不少。

1.----------------------
2.BUFFER POOL AND MEMORY
3.----------------------
4.Total memory allocated 4648979546; in additional pool allocated 16773888
5.Buffer pool size   262144
6.Free buffers       0
7.Database pages     258053
8.Modified db pages  37491
9.Pending reads 0
10.Pending writes: LRU 0, flush list 0, single page 0
11.Pages read 57973114, created 251137, written 10761167
12.9.79 reads/s, 0.31 creates/s, 6.00 writes/s
13.Buffer pool hit rate 999 / 1000

這部分顯示了緩衝池和內存的利用率相關信息。能夠看到Innodb分配的全部內存(有些時候可能比你設置的還要多點),以及額外的內存池分配狀況(能夠檢查它的大小是否正好),緩衝池總共有多少個內存頁,有多少空閒內存頁,數據庫分配了多少個內存頁以及有多少個髒內存頁。從這些信息中,就能夠判斷內存緩衝池是否設定合理,若是老是有大量空閒內存頁,則不須要設置那麼多內存,能夠適當減少一點。若是空閒內存頁爲 0,這種狀況下數據庫內存頁就不必定會和緩衝池的總數一致,由於緩衝池還須要保存鎖信息,自適應哈希索引以及其餘系統結構等信息。

等待中的讀寫是指內存緩衝池級別的請求。Innodb可能會把多個文件級別的請求合併到一個上,所以各不相同。咱們還能夠看到Innodb提交的各類不一樣類型的IO,LRU內存頁中須要刷新的頁 - 髒內存頁,它們不會被長時間存取;刷新列表 -
檢查點進程處理完以後須要刷新的舊內存頁;獨立內存頁 - 獨立的寫內存頁。

咱們還能夠看到內存頁總共讀寫了多少次。已經建立的內存頁是當前一個內存頁中的內容沒有讀取到內存緩衝池中時,專門爲新數據建立的空內存頁。

最後咱們能夠看到緩衝池的命中率,它預示着緩衝池的效率。1000/1000 至關於 100% 的命中率。不過這樣也很難說明緩衝池的命中率就足夠高了,這要須要根據不一樣的負載環境而定。一般狀況下,950/1000 就夠了,有些時候在IO負載較高的環境下,命中率可能爲 995/1000。

1.--------------
2.ROW OPERATIONS
3.--------------
4.0 queries inside InnoDB, 0 queries in queue
5.1 read views open inside InnoDB
6.Main thread process no. 10099, id 88021936, state: waiting for server activity
7.Number of rows inserted 143, updated 3000041, deleted 0, read 24865563
8.0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s

最後一部分,顯示了數據行操做以及一些系統信息相關狀況。

一開始顯示了Innodb線程隊列狀態 - 有多少線程處於等待或活躍的。Innodb內部打開了多少讀視圖 -
這是在事務開始後,可是當前尚未活躍語句的狀況,Innodb主線程的狀態控制了系統操做調度的數量 - 刷新髒內存頁、檢查點、淨化線程、刷新日誌、合併插入緩衝等。"state" 的值則表示了主線程當前的狀態。

接下來能夠看到自從系統啓動以來,全部的數據行操做數量及其平均值。它們能夠很方便地用於監控以及畫出系統狀態圖,數據行操做次數能夠很好的衡量Innodb的負載。不是全部的數據行操做帶來的負載都是同樣的,存取10字節的行比10Mb的行相比會小了不少,不過相對於查詢的總次數來講這個信息但是有用的多了,差異也很大。

還有一點須要注意的是,SHOW INNODB STATUS 不是一成不變的,有些時間點上可能會不相符。SHOW INNODB STATUS結果中,不一樣時間可能會顯示不一樣結果,所以有些時候可能會看到衝突的信息。這是因爲設計時須要由全局鎖提供一致性信息,致使了大量的開銷。



相關文章
相關標籤/搜索