1. 程式人生 > >0719show engine innodb status解讀

0719show engine innodb status解讀

key cnblogs tuple 邏輯 evict nes line pla 特定

轉自 http://www.cnblogs.com/zengkefu/p/5678100.html

註:以下內容為根據《高性能mysql第三版》和《mysql技術內幕innodb存儲引擎》的innodb status部分的個人理解,如果有錯誤,還望指正!!

  innodb存儲引擎在show engine innodb status(老版本對應的是show innodb status)輸出中,顯示除了大量的內部信息,它輸出就是一個單獨的字符串,沒有行和列,內容分為很多小段,每一段對應innodb存儲引擎不同部分的信息,其中有一些信息對於innodb開發者來說非常有用,但是,許多信息,如果你嘗試去理解,並且應用到高性能innodb調優的時候,你會發現它們非常有趣,甚至是非常有必要的。

輸出內容中包含了一些平均值的統計信息,這些平均值是自上次輸出結果生成以來的統計數,因此,如果你正在檢查這些值,那就要確保已經等待了至少30s的時間,使兩次采樣之間的積累足夠長的統計時間並多次采樣,檢查計數器變化從而弄清其行為,並不是所有的輸出都會在一個時間點上生成,因而也不是所有的顯示出來的平均值會在同一時間間隔裏重新再計算。而且,innodb有一個內部復位間隔,而它是不可預知的,各個版本也不一樣。

這些輸出信息足夠提供給手工計算出大多數你想要的統計信息,有一款監控工具innotop可以幫你計算出增量差值和平均值。下面,在你的mysql命令行敲下show engine innodb status;看著輸出跟著下面的步驟一步一步理解輸出信息是什麽含義:

註意:以下使用mysql5.5.24版本做解讀,mysql5.6.x和5.7.x輸出內容有些地方有調整。



1.第一段是頭部信息,它僅僅聲明了輸出的開始,其內容包括當前的日期和時間,以及自上次輸出以來經過的時長。

=====================================
160129 12:07:26 INNODB MONITOR OUTPUT #第二行是當前日期和時間
=====================================
Per second averages calculated from the last 24 seconds #第四行顯示的是計算出這一平均值的時間間隔,即自上次輸出以來的時間,或者是距上次內部復位的時長



2.從innodb1.0.x開始,可以使用命令show engine innodb status;來查看master thread的狀態信息:

-----------------
BACKGROUND THREAD
-----------------

srv_master_thread loops: 30977173 1_second, 30975685 sleeps, 3090359 10_second, 166112 background, 165988 flush #這行顯示主循環進行了30977173 1_second次,每秒掛起的操作進行了30975685 sleeps次(說明負載不是很大),10秒一次的活動進行了3090359 10_second次,1秒循環和10秒循環比值符合1:10,backgroup loop進行了166112 background次,flush loop進行了165988 flush次,如果在一臺很大壓力的mysql上,可能看到每秒運行次數和掛起次數比例小於1很多,這是因為innodb對內部進行了一些優化,當壓力大時間隔時間並不總是等待1秒,因此,不能認為每秒循環和掛起的值總是相等,在某些情況下,可以通過兩者之間的差值來比較反映當前數據庫的負載壓力。


srv_master_thread log flush and writes: 31160103



3.如果有高並發的工作負載,你就要關註下接下來的段(SEMAPHORES信號量),它包含了兩種數據:事件計數器以及可選的當前等待線程的列表,如果有性能上的瓶頸,可以使用這些信息來找出瓶頸,不幸的是,想知道怎麽使用這些信息還是有一點復雜,下面先給出一些解釋:

----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 68581015, signal count 218437328
--Thread 140653057947392 has waited at btr0pcur.c line 437 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7ff536c7d3c0 created in file buf0buf.c line 916
a writer (thread id 140653057947392) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3097
Last time write locked in file /usr/local/src/soft/mysql-5.5.24/storage/innobase/buf/buf0buf.c line 3151
--Thread 140653677291264 has waited at btr0pcur.c line 437 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7ff53945b240 created in file buf0buf.c line 916
a writer (thread id 140653677291264) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3097
Last time write locked in file /usr/local/src/soft/mysql-5.5.24/storage/innobase/buf/buf0buf.c line 3151
Mutex spin waits 1157217380, rounds 1783981614, OS waits 10610359
RW-shared spins 103830012, rounds 1982690277, OS waits 52051891
RW-excl spins 43730722, rounds 602114981, OS waits 3495769
Spin rounds per wait: 1.54 mutex, 19.10 RW-shared, 13.77 RW-excl


內容比較多,下面分段依次解釋:
3.1.
OS WAIT ARRAY INFO: reservation count 68581015, signal count 218437328 #這行給出了關於操作系統等待數組的信息,它是一個插槽數組,innodb在數組裏為信號量保留了一些插槽,操作系統用這些信號量給線程發送信號,使線程可以繼續運行,以完成它們等著做的事情,這一行還顯示出innodb使用了多少次操作系統的等待:保留統計(reservation count)顯示了innodb分配插槽的頻度,而信號
計數(signal count)衡量的是線程通過數組得到信號的頻度,操作系統的等待相對於空轉等待(spin wait)要昂貴些。


3.2.

--Thread 140653057947392 has waited at btr0pcur.c line 437 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7ff536c7d3c0 created in file buf0buf.c line 916
a writer (thread id 140653057947392) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3097
Last time write locked in file /usr/local/src/soft/mysql-5.5.24/storage/innobase/buf/buf0buf.c line 3151
--Thread 140653677291264 has waited at btr0pcur.c line 437 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x7ff53945b240 created in file buf0buf.c line 916
a writer (thread id 140653677291264) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3097
Last time write locked in file /usr/local/src/soft/mysql-5.5.24/storage/innobase/buf/buf0buf.c line 3151
這部分顯示的是當前正在等待互斥量的innodb線程,在這裏可以看到有兩個線程正在等待,每一個都是以--Thread <數字> has waited...開始,這一段內容在正常情況下應該是空的(即查看的時候沒有這部分內容),除非服務器運行著高並發的工作負載,促使innodb采取讓操作系統等待的措施,除非你對innodb源碼熟悉,否則這裏看到的最有用的信息就是發生線程等待的代碼文件名 /usr/local/src/soft/mysql-5.5.24/storage/innobase/buf/buf0buf.c line 3151。


在innodb內部哪裏才是熱點?舉例來說,如果看到許多線程都在一個名為buf0buf.c的文件上等待,那就意味著你的系統裏存在著
緩沖池競爭,這個輸出信息還顯示了這些線程等待了多少時間,其中waiters flag顯示了有多少個等待著正在等待同一個互斥量。 如果waiters flag為0那就表示沒有線程在等待同一個互斥量(此時在waiters flag 0後面可能可以看到wait is ending,表示這個互斥量已經被釋放了,但操作系統還沒有把線程調度過來運行)。

你可能想知道innodb真正等待的是什麽,innodb使用了互斥量和信號量來保護代碼的臨界區,如:限定每次只能有一個線程進入臨界區,或者是當有活動的讀時,就限制寫入等。在innodb代碼裏有很多臨界區,在合適的條件下,它們都可能出現在那裏,常常能見到的一種情形是:獲取緩沖池分頁的訪問權的時候。

3.3.
在等待線程之後的部分信息如下,這部分顯示了更多的事件計數器,在每一個情形中,都能看到innodb依靠操作系統等待的頻度:

Mutex spin waits 1157217380, rounds 1783981614, OS waits 10610359 #這行顯示的是跟互斥量相關的幾個計數器
RW-shared spins 103830012, rounds 1982690277, OS waits 52051891 #這行顯示讀寫的共享鎖的計數器
RW-excl spins 43730722, rounds 602114981, OS waits 3495769 #這行顯示讀寫的排他鎖的計數器
Spin rounds per wait: 1.54 mutex, 19.10 RW-shared, 13.77 RW-excl

innodb有著一個多階段等待的策略,首先,它會試著對鎖進行空轉等待,如果經歷了一個預設的空轉等待周期(設置innodb_sync_spin_loops配置變量命令)之後還沒有成功,那就會退到更昂貴更復雜的等待數組中。
空轉等待的成本相對較低,但是它們要不停地檢查一個資源能否被鎖定,這種方式會消耗CPU周期,但是,這沒有聽起來那麽糟糕,因為當處理器在等待IO時,一般都有一些空閑的CPU周期可用,即使是沒有空閑的CPU周期,空等也要比其他方式更加廉價一些。然而,當另外一個線程能做一些事情的時候,空轉等待也還會把CPU獨占著。
空轉等待的替代方案就是讓操作系統做上下文切換,這樣,當一個線程在等待時,另外一個線程就可以被運行,然後,通過等待數組裏的信號量發出信號,喚醒那個沈睡的線程,通過信號量來發送信號是比較有效的,但是上下文切換就很昂貴,這很快就會積少成多,每秒鐘幾千次的切換會引發大量的系統開銷。
你可以通過修改innodb_sync_spin_loops的值,試著在空轉等待與操作系統等待之間達成平衡,不要擔心空轉等待,除非你在一秒裏看到幾十萬個空轉等待。此時,你可以考慮performance_schema庫或者show engine innodb mutex;查看下相關信息。


4.下面這一段外鍵錯誤的信息一般不會出現,除非你服務器上發生了外鍵錯誤,有時問題在於事務在插入,更新或刪除一條記錄時要尋找父表或子表,還有時候是當innodb嘗試增加或刪除一個外鍵或者修改一個已經存在的外鍵時,發現表之間類型不匹配,這部分輸出對於調試與innodb不明確的外鍵錯誤發生的準確原因非常有幫助,下面搞一個示例來看看:

4.1 創建父表:
mysql> create table parent(parent_id int not null,primary key(parent_id)) engine=innodb;

4.2 創建子表:
mysql> create table child(child_id int not null,key child_id(child_id),constraint i_child foreign key(child_id) references parent(parent_id)) engine=innodb;

4.3 插入數據:
mysql> insert into parent(parent_id) values(1);
mysql> insert into child(child_id) values(1);

4.5 有兩種基本的外鍵錯誤:
第一種:以某種可能違反外鍵約束關系的方法增加,更新,刪除數據,將導致第一類錯誤,如,在父表中刪除行時發生如下錯誤:

mysql> delete from parent;
ERROR 1451 (23000): Cannot delete or update a parent row: a foreign key constraint fails (`xiaoboluo`.`child`, CONSTRAINT `i_child` FOREIGN KEY (`child_id`) REFERENCES `parent` (`parent_id`))


錯誤信息相當明了,對所有由增加,刪除,更新不匹配的行導致的錯誤都會看到相似的信息,下面是show engine innodb status的輸出:

------------------------
LATEST FOREIGN KEY ERROR
------------------------
160128 1:17:06 Transaction: #這行顯示了最近一次外鍵錯誤的日期和時間
TRANSACTION D203D6, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 1
MySQL thread id 20027, OS thread handle 0x7f0a4c0f8700, query id 1813996 localhost root updating
delete from parent
Foreign key constraint fails for table `xiaoboluo`.`child`:
, #上面部分顯示了關於破壞外鍵約束的事務詳情。後邊部分顯示了發現錯誤時innodb正嘗試修改的準確數據,輸出中有許多是轉換成可打印格式的行數據
CONSTRAINT `i_child` FOREIGN KEY (`child_id`) REFERENCES `parent` (`parent_id`)
Trying to delete or update in parent table, in index `PRIMARY` tuple:
DATA TUPLE: 3 fields;
0: len 4; hex 80000001; asc ;;
1: len 6; hex 000000d203d6; asc ;;
2: len 7; hex 1e000001ca0110; asc ;;

But in child table `xiaoboluo`.`child`, in index `child_id`, there is a record:
PHYSICAL RECORD: n_fields 2; compact format; info bits 0
0: len 4; hex 80000001; asc ;;
1: len 6; hex 000013a99b3e; asc >;;


4.6 第二種:嘗試修改父表的表結構時發生的錯誤,這種錯誤就沒有那麽清楚了,這可能會讓調試更困難:

mysql> alter table parent modify parent_id int unsigned not null;
ERROR 1025 (HY000): Error on rename of ‘./xiaoboluo/#sql-b695_4e3b‘ to ‘./xiaoboluo/parent‘ (errno: 150)

查看show engine innodb status輸出信息:

------------------------
LATEST FOREIGN KEY ERROR
------------------------
160128 1:32:33 Error in foreign key constraint of table xiaoboluo/child:
there is no index in referenced table which would contain
the columns as the first columns, or the data types in the
referenced table do not match the ones in table. Constraint:
,
CONSTRAINT "i_child" FOREIGN KEY ("child_id") REFERENCES "parent" ("parent_id")
The index in the foreign key in table is "child_id"
See http://dev.mysql.com/doc/refman/5.5/en/innodb-foreign-key-constraints.html
for correct foreign key definition.
InnoDB: Renaming table `xiaoboluo`.<result 2 when explaining filename ‘#sql-b695_4e3b‘> to `xiaoboluo`.`parent` failed!


上面的錯誤是數據類型不匹配,外鍵列必須有完全相同的數據類型,包括任何的修飾符(如這裏父表多加了一個unsigned,這也是問題所在),當看到1025錯誤並不理解為什麽時,最好查看下innodb status。在每次看到有新錯誤時,外鍵錯誤信息都會被重寫,percona toolkit中的pt-fk-error-logger工具可以用表保存這些信息以供後續分析。


5.與外鍵錯誤一樣,這部分只有當服務器產生死鎖時才會出現,死鎖信息同樣在每次有新的死鎖錯誤時被重寫,percona toolkit中的pt-deadlock-logger工具可以用表保存這些信息以供後續分析
死鎖在等待關系圖裏是一個循環,就是一個鎖定了行的數據結構又在等待別的鎖,這個循環可以任意地大,innodb會立即檢測到死鎖,因為每當有事務等待行鎖的時候,它都會去檢查等待關系圖裏是否有循環,死鎖的情況可能會比較復雜,但是,這一部分只顯示了最近的兩個死鎖的情況,它們在各自的事務裏執行的最後一條語句,以及它們在等待關系圖裏形成環鎖的信息。在這個循環裏你看不到其他事務,也可能看不到在事務裏早先真正獲得了鎖的語句,盡管如此,通常還是可以通過查看這些輸出結果來確定到底是什麽引起了死鎖。

在innodb裏實際上有兩種死鎖,第一種就是常常碰到的那種,它在等待關系圖裏是一個真正的循環,另外一種就是在一個等待關系圖裏,因代價昂貴而無法檢測它是不是包含了循環,如果innodb要在關系圖裏檢查超過100W個鎖,或者在檢查過程中,innodb要重做200個以上的事務,那它會放棄,並宣布這裏有一個死鎖,這些數值都是硬編碼在innodb代碼裏的常量,無法配置(如果你NB可以修改代碼然後重新編譯)。第二種死鎖報錯你可以在輸出裏看到一條信息:TOO DEEP OR LONG SEARCH IN THE LOCK TABLE WAITS-FOR GRAPH


innodb不僅會打印出事務和事務持有和等待的鎖,而且還有記錄本身,不幸的是,它至於可能超過為輸出結果預留的長度(只能打印1M的內容且只能保留最近一次的死鎖信息),如果你無法看到完整的輸出,此時可以在任意庫下創建innodb_monitor或innodb_lock_monitor表,這樣innodb status信息會完整且每15s一次被記錄到錯誤日誌中。如:create table innodb_monitor(a int)engine=innodb;,不需要記錄到錯誤日誌中時就刪掉這個表即可。



5.1 下面也搞一個示例來看看:

5.1.1 建表:

mysql> create table test_deadlock(id int unsigned not null primary key auto_increment,test int unsigned not null);
Query OK, 0 rows affected (0.02 sec)

5.1.2 插入測試數據:
mysql> insert into test_deadlock(test) values(1),(2),(3),(4),(5);
Query OK, 5 rows affected (0.00 sec)
Records: 5 Duplicates: 0 Warnings: 0


打開兩個會話終端:
5.1.3 會話1執行下面的SQL:

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from test_deadlock where id=1 for update;
+----+------+
| id | test |
+----+------+
| 1 | 1 |
+----+------+
1 row in set (0.00 sec)

5.1.4 接著會話2執行下面的SQL:

mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from test_deadlock where id=2 for update;
+----+------+
| id | test |
+----+------+
| 2 | 2 |
+----+------+
1 row in set (0.00 sec)


5.1.5 回到會話1執行下面的SQL,會發生等待:

mysql> select * from test_deadlock where id=2 for update;


5.1.6 回到會話2執行下面的SQL,產生死鎖,會話2被回滾:

mysql> select * from test_deadlock where id=1 for update;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

5.2 查看innodb status信息:

------------------------
LATEST DETECTED DEADLOCK
------------------------
160128 1:51:53 #這裏顯示了最近一次發生死鎖的日期和時間
*** (1) TRANSACTION:
TRANSACTION D20847, ACTIVE 141 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 376, 2 row lock(s)
MySQL thread id 20027, OS thread handle 0x7f0a4c0f8700, query id 1818124 localhost root statistics
select * from test_deadlock where id=2 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20847 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 00000002; asc ;;
1: len 6; hex 000000d20808; asc ;;
2: len 7; hex ad000001ab011d; asc ;;
3: len 4; hex 00000002; asc ;;

*** (2) TRANSACTION:
TRANSACTION D20853, ACTIVE 119 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1248, 2 row lock(s)
MySQL thread id 20081, OS thread handle 0x7f0a0f020700, query id 1818204 localhost root statistics
select * from test_deadlock where id=1 for update
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20853 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 00000002; asc ;;
1: len 6; hex 000000d20808; asc ;;
2: len 7; hex ad000001ab011d; asc ;;
3: len 4; hex 00000002; asc ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20853 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 00000001; asc ;;
1: len 6; hex 000000d20808; asc ;;
2: len 7; hex ad000001ab0110; asc ;;
3: len 4; hex 00000001; asc ;;

*** WE ROLL BACK TRANSACTION (2)


這部分內容比較多,下面分段逐一進行解釋:
5.2.1 下面這部分顯示的是死鎖的第一個事務的信息:

*** (1) TRANSACTION:
TRANSACTION D20847, ACTIVE 141 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 376, 2 row lock(s)
MySQL thread id 20027, OS thread handle 0x7f0a4c0f8700, query id 1818124 localhost root statistics
select * from test_deadlock where id=2 for update

TRANSACTION D20847, ACTIVE 141 sec starting index read:這行表示事務D20847,ACTIVE 141 sec表示事務處於活躍狀態141s,starting index read表示正在使用索引讀取數據行
mysql tables in use 1, locked 1#這行表示事務D20847正在使用1個表,且涉及鎖的表有1個
LOCK WAIT 3 lock struct(s), heap size 376, 2 row lock(s) #這行表示在等待3把鎖,占用內存376字節,涉及2行記錄,如果事務已經鎖定了幾行數據,這裏將會有一行信息顯示出鎖定結構的數目(註意,這跟行鎖是兩回事)和堆大小,堆的大小指的是為了持有這些行鎖而占用的內存大小,Innodb是用一種特殊的位圖表來實現行鎖的,從理論上講,它可將每一個鎖定的行表示為一個比特,經測試顯示,每個鎖通常不超過4比特
MySQL thread id 20027, OS thread handle 0x7f0a4c0f8700, query id 1818124 localhost root statistics #這行表示該事務的線程ID信息,操作系統句柄信息,連接來源、用戶
select * from test_deadlock where id=2 for update #這行表示事務涉及的SQL


5.2.2 下面這一部分顯示的是當死鎖發生時,第一個事務正在等待的鎖等信息:

*** (1) WAITING FOR THIS LOCK TO BE GRANTED: #這行信息表示第一個事務正在等待鎖被授予
RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20847 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 00000002; asc ;;
1: len 6; hex 000000d20808; asc ;;
2: len 7; hex ad000001ab011d; asc ;;
3: len 4; hex 00000002; asc ;;

RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20847 lock_mode X locks rec but not gap waiting#這行信息表示等待的鎖是一個record lock,空間id是441,頁編號為3,大概位置在頁的72位處,鎖發生在表xiaoboluo.test_deadlock的主鍵上,是一個X鎖,但是不是gap lock。 waiting表示正在等待鎖
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 #這行表示record lock的heap no 位置

#這部分剩下的內容只對調試才有用。

0: len 4; hex 00000002; asc ;;
1: len 6; hex 000000d20808; asc ;;
2: len 7; hex ad000001ab011d; asc ;;
3: len 4; hex 00000002; asc ;;


5.2.3 下面這部分是事務二的狀態:

*** (2) TRANSACTION:
TRANSACTION D20853, ACTIVE 119 sec starting index read #事務2處於活躍狀態119s
mysql tables in use 1, locked 1 #正在使用1個表,涉及鎖的表有1個
3 lock struct(s), heap size 1248, 2 row lock(s) #涉及3把鎖,2行記錄
MySQL thread id 20081, OS thread handle 0x7f0a0f020700, query id 1818204 localhost root statistics
select * from test_deadlock where id=1 for update #第二個事務的SQL

5.2.4 下面這部分是事務二的持有鎖信息:

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20853 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 00000002; asc ;;
1: len 6; hex 000000d20808; asc ;;
2: len 7; hex ad000001ab011d; asc ;;
3: len 4; hex 00000002; asc ;;

RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20853 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 #從這兩行持有鎖信息計息後面幾行調試信息上看,就是事務1正在等待的鎖。

5.2.5 下面這部分是事務二正在等待的鎖,從下面的信息上看,等待的是同一個表,同一個索引,同一個page上的record lock X鎖,但是heap no位置不同,即不同的行上的鎖:

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 441 page no 3 n bits 72 index `PRIMARY` of table `xiaoboluo`.`test_deadlock` trx id D20853 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 00000001; asc ;;
1: len 6; hex 000000d20808; asc ;;
2: len 7; hex ad000001ab0110; asc ;;
3: len 4; hex 00000001; asc ;;

*** WE ROLL BACK TRANSACTION (2) #這個表示事務2被回滾,因為兩個事務的回滾開銷一樣,所以選擇了後提交的事務進行回滾,如果兩個事務回滾的開銷不同(undo 數量不同),那麽就回滾開銷最小的那個事務。

當一個事務持有了其他事務需要的鎖,同時又想獲得其他事務持有的鎖時,等待關系圖上就會產生循環,Innodb不會顯示所有持有和等待的鎖,但是,它顯示了足夠的信息來幫你確定,查詢操作正在使用哪些索引,這對於你確定能否避免死鎖有極大的價值。

如果能使兩個查詢對同一個索引朝同一個方向進行掃描,就能降低死鎖的數目,因為,查詢在同一個順序上請求鎖的時候不會創建循環,有時候,這是很容易做到的,如:要在一個事務裏更新許多條記錄,就可以在應用程序的內存裏把它們按照主鍵進行排序,然後,再用同樣的順序更新到數據庫裏,這樣就不會有死鎖發生,但是在另一些時候,這個方法也是行不通的(如果有兩個進程使用了不同的索引區間操作同一張表的時候)。


6. 下面這部分包含了一些關於innodb事務的總結信息,緊隨其後的是當前活躍事務列表,如:
------------

TRANSACTIONS
------------
Trx id counter 4E0132AD
Purge done for trx‘s n:o < 4E01090B undo n:o < 0
History list length 1853
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 4E0131D3, not started
MySQL thread id 26208218, OS thread handle 0x7fec7c582700, query id 5274800318 10.207.162.69 gdsser
---TRANSACTION 4E01323F, not started
MySQL thread id 26208217, OS thread handle 0x7fec7c1b3700, query id 5274800938 10.207.162.69 gdsser

....................
---TRANSACTION 4E0132AC, ACTIVE 0 sec preparing
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1
MySQL thread id 26208200, OS thread handle 0x7fec567e0700, query id 5274801557 10.207.162.69 gdsser
commit
---TRANSACTION 4E0110E7, ACTIVE 188 sec
mysql tables in use 1, locked 0
MySQL thread id 26208154, OS thread handle 0x7fec7c235700, query id 5274800671 10.143.90.228 root Sending data
SELECT /*!40001 SQL_NO_CACHE */ * FROM `m_flowskillpoint`
Trx read view will not see trx with id >= 4E0110E8, sees < 4E0108EE
---TRANSACTION 4E0108EF, ACTIVE 233 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 26208131, OS thread handle 0x7fec578e3700, query id 5274801341 10.143.90.228 root Sending data
SELECT /*!40001 SQL_NO_CACHE */ * FROM `m_flowsilver`
Trx read view will not see trx with id >= 4E0108F0, sees < 4E0108EC
---TRANSACTION 4E0108EE, ACTIVE 233 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 26208132, OS thread handle 0x7fec7c78a700, query id 5274797797 10.143.90.228 root Sending data
SELECT /*!40001 SQL_NO_CACHE */ * FROM `m_flowmail`
Trx read view will not see trx with id >= 4E0108EF, sees < 4E0108EC

這部分內容比較多,下面分段逐一進行解釋:
6.1.

Trx id counter 4E0132AD #這行表示當前事務ID,這是一個系統變量,每創建一個新事務都會增加
Purge done for trx‘s n:o < 4E01090B undo n:o < 0 #這是innodb清除舊MVCC行時所用的事務ID,將這個值和當前事務ID進行比較,就可以知道有多少老版本的數據未被清除。這個數字多大才可以安全的取值沒有硬性和速成的規定,如果數據沒做過任何更新,那麽一個巨大的數字也不意味著有未清除的數據,因為實際上所有事務在數據庫裏查看的都是同一個版本的數據(此時只是事務ID在增加,而數據沒有變更),另一方面,如果有很多行被更新,那每一行就會有一個或多個版本留在內存裏,減少此類開銷的最好辦法就是確保事務已完成就立即提交,不要讓它長時間地處於打開狀態,因為一個打開的事務即使不做任何操作,也會影響到innodb清理舊版本的行數據。 undo n:o < 0這個是innodb清理進程正在使用的撤銷日誌編號,為0 0時說明清理進程處於空閑狀態。
History list length 1853 #歷史記錄的長度,即位於innodb數據文件的撤銷空間裏的頁面的數目,如果事務執行了更新並提交,這個數字就會增加,而當清理進程移除舊版本數據時,它就會減少,清理進程也會更新Purge done for.....這行中的數值。

6.2.
頭部信息之後就是一個事務列表,當前版本的mysql還不支持嵌套事務,因此,在某個時間點上,每個客戶端連接能夠擁有的事務數量是有一個上限的,而且每一個事務只能屬於單一連接(即一個事務只能使用單個線程執行,不能使用多個線程)。在輸出信息裏,每一個事務至少占有兩行內容,如:

---TRANSACTION 4E0131D3, not started #每個事務的第一行以事務的ID和狀態開始,not started表示這個事務已經提交並且沒有再發起影響事務的語句,可能剛好空閑
MySQL thread id 26208218, OS thread handle 0x7fec7c582700, query id 5274800318 10.207.162.69 gdsser#然後每個事務的第二行是一些線程等信息,MySQL thread id <數字>部分和是hi用show full processlist;命令看到的id列相同。緊隨其後的是一個內部查詢id和一些連接信息,這些信息同樣與show full processlist中的輸出相同。
---TRANSACTION 4E01323F, not started
MySQL thread id 26208217, OS thread handle 0x7fec7c1b3700, query id 5274800938 10.207.162.69 gdsser

6.3.
上面是not started狀態的事務信息,下面來看看為ACTIVE狀態的事務信息:

---TRANSACTION 4E0110E7, ACTIVE 188 sec #這行顯示次事務處於活躍狀態已經188s,可能的所有狀態有not started,active,prepared和committed in memory,一旦事務日誌落盤了就會變成not started狀態。在時間後面會顯示出當前事務正在做什麽(在這裏為空沒有顯示出來),在源代碼中有超過30個字符串常量可以顯示在時間後面,如:fetching,preparing,rows,adding foreign keys等等
mysql tables in use 1, locked 0 #該事務用到的表數和涉及表鎖的表數,Innodb一般不會鎖定表,但對有些語句會鎖定,如果mysql服務器在高於innodb層之上將表鎖定,這裏也是能夠顯示出來的,如果事務已經鎖定了幾行數據,這裏將會有一行信息顯示出鎖定結構的數目(註意,這跟行鎖是兩回事)和和堆大小,如:2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1,堆的大小指的是為了持有這些行鎖而占用的內存大小,Innodb是用一種特殊的位圖表來實現行鎖的,從理論上講,它可將每一個鎖定的行表示為一個比特,經測試顯示,每個鎖通常不超過4比特。
MySQL thread id 26208154, OS thread handle 0x7fec7c235700, query id 5274800671 10.143.90.228 root Sending data #與show processlist輸出結果大部分相同
SELECT /*!40001 SQL_NO_CACHE */ * FROM `m_flowskillpoint` #如果事務正在運行一個查詢,那麽這裏就會顯示事務涉及的SQL,註意:有些版本可能只顯示其中一小段,而不是完整的SQL
Trx read view will not see trx with id >= 4E0110E8, sees < 4E0108EE #這行顯示了事務的讀視圖,它表明了因為版本關系而產生的對於事務可見和不可見兩種類型的事務ID的範圍,在這裏,兩個數字之間有一個事務的間隙,這個間隙裏的事務可能是不可見的,innodb在執行查詢時,對於那些事務ID正好在這個間隙的行,還會檢查其可見性。

註:如果事務正在等待一個鎖,那麽在查詢SQL文本後面將可以看到這個鎖的信息,在上文的死鎖例子裏,這樣的信息看到過很多了,不幸的是,輸出信息並沒有說出這個鎖正被其他哪個事務持有,不過可以通過information_schema庫下的innodb_trx,innodb_lock_waits,innodb_locks三個表來查明這一點。如果輸出信息裏有很多個事務,innodb可能會限制要打印出來的事務數目,以免輸出信息增長得太大,這時就會看到...truncated...提示。


7.FILE I/O部分顯示的是I/O輔助線程的狀態,還有性能計數器的狀態,如下:

--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread) #insert buffer thread
I/O thread 1 state: waiting for i/o request (log thread) #log thread
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: doing file i/o (read thread) ev set #以上為默認的4個read thread
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 state: waiting for i/o request (write thread) #以上為默認的4個write thread
Pending normal aio reads: 128 [0, 0, 0, 128] , aio writes: 0 [0, 0, 0, 0] , #讀線程和寫線程掛起操作的數目等,aio的意思是異步I/O
ibuf aio reads: 0, log i/o‘s: 0, sync i/o‘s: 0 #insert buffer thread掛起的fsync()操作數目等
Pending flushes (fsync) log: 0; buffer pool: 0 #log thread掛起的fsync()操作數目等
146246831 OS file reads, 760501349 OS file writes, 247143684 OS fsyncs #這行顯示了讀,寫和fsync()調用執行的數目,在你的機器環境負載下這些絕對值可能會有所不同,因此更重要的是監控它們過去一段時間內是如何改變的。
1 pending preads, 0 pending pwrites #這行顯示了當前被掛起的讀和寫操作數
145.49 reads/s, 783677 avg bytes/read, 28.75 writes/s, 10.67 fsyncs/s #這行顯示了在頭部顯示的時間(指的是第1部分的時間)段內的每秒平均值。

註:三行掛起讀寫線程、緩沖池線程、日誌線程的統計信息的值是檢測I/O受限的應用的一個好方法,如果這些I/O大部分有掛起操作,那麽負載可能I/O受限。在linux系統下使用參數:innodb_read_io_threads和innodb_write_io_threads兩個變量來配置讀寫線程的數量,默認為各4個線程。
insert buffer thread:負責插入緩沖合並,如:記錄被從插入緩沖合並到表空間中
log thread:負責異步刷事務日誌
read thread:執行預讀操作以嘗試預先讀取innodb預感需要的數據
write thread:刷新臟頁緩沖


8.這部分顯示了insert buffer和adaptive hash index兩個部分的結構的狀態

-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------


Ibuf: size 12, free list len 27559, seg size 27572, 18074934 merges #這行顯示了關於size(size 12代表了已經合並記錄頁的數量)、free list(代表了插入緩沖中空閑列表長度)和seg size大小(seg size 27572顯示了當前insert buffer的長度,大小為27572*16K=440M左右)的信息。18074934 merges代表合並插入的次數
merged operations: #這個標簽下的一行信息insert,delete mark,delete分別表示merge操作合並了多少個insert buffer,delete buffer,purge buffer
insert 81340470, delete mark 8893610, delete 818579

discarded operations: #這個標簽下的一行信息表示當change buffer發生merge時表已經被刪除了,就不需要再將記錄合並到輔助索引中了
insert 0, delete mark 0, delete 0
Hash table size 87709057, node heap has 10228 buffer(s) #這行顯示了自使用哈希索引的狀態,其中,Hash table size 87709057表示AHI的大小,node heap has 10228 buffer(s)表示AHI的使用情況
1741.05 hash searches/s, 539.48 non-hash searches/s #這行顯示了在頭部第1部分提及的時間內Innodb每秒完成了多少哈希索引操作,1741.05 hash searches/s表示每秒使用AHI搜索的情況,539.48 non-hash searches/s表示每秒沒有使用AHI搜索的情況(因為哈希索引只能用於等值查詢,而範圍查詢,模糊查詢是不能使用哈希索引的。),通過hash searches: non-hash searches的比例大概可以了解使用哈希索引後的效率,哈希索引查找與非哈希索引查找的比例僅供參考,自適應哈希索引無法配置,但是可以通過innodb_adaptive_hash_index=ON|OFF參數來選擇是否需要這個特性。

註:


innodb從1.0.x開始引入change buffer,可以視為insert buffer的升級,從這個版本開始,innodb可以對DML操作(insert,delete,update)都進行緩沖,他們分別是insert buffer,delete buffer,purge buffer,當然和之前insert buffer一樣,change buffer適用對象仍然是非唯一索引的輔助索引,因為沒有update buffer,所以對一條記錄進行update的操作可以分為兩個過程:

A:將記錄標記為刪除

B:真正將記錄刪除

因此,delete buffer對應update 操作的第一個過程,即將記錄標記為刪除,purge buffer對應update的第二個過程,即將記錄真正地刪除




9.這部分顯示了關於innodb事務日誌(重做日誌)子系統的統計:

---
LOG
---
Log sequence number 1351392990515 #這行顯示了當前最新數據產生的日誌序列號
Log flushed up to 1351392989504 #這行顯示了日誌已經刷新到哪個位置了(已經落盤到事務日誌中的日誌序列號)
Last checkpoint at 1351373900020 #這行顯示了上一次檢查點的位置(一個檢查點表示一個數據和日誌文件都處於一致狀態的時刻,並且能用於恢復數據),如果上一次檢查點落後與上一行太多,並且差異接近於事務日誌文件的大小,Innodb會觸發“瘋狂刷”,這對性能而言非常糟糕。
0 pending log writes, 0 pending chkp writes #這行顯示了當前掛起的日誌讀寫操作,可以將這行的值與第7部分FILE I/O對應的值做比較,以了解你的I/O有多少是由於日誌系統引起的。
286879989 log i/o‘s done, 15.92 log i/o‘s/second #這行顯示了日誌操作的統計和每秒日誌I/O數,可以將這行的值與第7部分FILE I/O對應的值做比較,以了解你的I/O有多少是由於日誌系統引起的。


9.這部分顯示了關於innodb緩沖池及其如何使用內存的統計:
9.1.

----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 45357793280; in additional pool allocated 0 #這行顯示了由innodb分配的總內存,以及其中多少是額外內存池分配,額外內存池僅分配了其中很小一部分內存,由內部內存分配器分配,現在的innodb版本一般使用操作系統的內存分配器,但老版本使用自己的,這是由於在那個時代有些操作系統並未提供一個非常好的內存分配實現。
Dictionary memory allocated 12681573


Buffer pool size 2705015 #從這行開始的下面4行顯示緩沖池度量值,以頁為單位,度量值有總的緩沖池大小,空閑頁數,分配用來存儲數據庫頁的頁數,以及臟數據庫頁數。這行顯示了緩沖池總共有多少個頁,即即2705015*16K,共有43G的緩沖池
Free buffers 5 #這行顯示了緩沖池空閑頁數
Database pages 2694782 #這行顯示了分配用來存儲數據庫頁的頁數,即,表示LRU列表中頁的數量,包含young sublist和old sublist
Old database pages 994651 #這行顯示了LRU中的old sublist部分頁的數量
Modified db pages 10610 #這行顯示臟數據庫頁數
Pending reads 128 #這行顯示了掛起讀的數量
Pending writes: LRU 0, flush list 0, single page 0 #這行顯示了掛起寫的數量
#註意,這裏掛起的讀和寫操作並不與FILE I/O部分的值匹配,因為Innodb可能合並許多的邏輯讀寫操作到一個物理I/O操作中,LRU代表最近使用到的被掛起數量,它是通過沖刷緩沖中不經常使用的頁來釋放空間以供給經常使用的頁的一種方法,沖刷列表flush list存放著檢查點處理需要沖刷的舊頁被掛起的數量,單頁single page被掛起的數量(single page寫是獨立的頁面寫,不會被合並)。
Pages made young 3014373561, not young 0 #這行顯示了LRU列表中頁移動到LRU首部的次數,因為該服務器在運行階段改變沒有達到innodb_old_blocks_time閥值的值,因此not young為0
6960.42 youngs/s, 0.00 non-youngs/s #表示每秒young和non-youngs這兩類操作的次數


Pages read 2946570833, created 43450158, written 574214278 #這行顯示了innodb被讀取,創建,寫入了多少頁,讀/寫頁的值是指的從磁盤讀到緩沖池的數據,或者從緩沖池寫到磁盤中的數據,創建頁指的是innodb在緩沖池中分配但沒有從數據文件中讀取內容的頁,因為它並不關心內容是什麽(如,它們可能屬於一個已經被刪除的表)
6960.54 reads/s, 4.42 creates/s, 9.33 writes/s #這行顯示了對應上面一行的每秒read,create,write的頁數
Buffer pool hit rate 955 / 1000, young-making rate 45 / 1000 not 0 / 1000 #這行顯示了緩沖池的命中率,它用來衡量innodb在緩沖池中查找到所需頁的比例,它度量自上次Innodb狀態輸出後到本次輸出這段時間內的命中率,因此,如果服務器自那以後一直很安靜,你將會看到No buffer pool page gets since the last printout。它對於度量緩存池的大小並沒有用處。


Pages read ahead 6928.54/s, evicted without access 8.21/s, Random read ahead 0.00/s #這行顯示了頁面預讀,隨機預讀的每秒頁數
LRU len: 2694782, unzip_LRU len: 0 #innodb1.0.x開始支持壓縮頁的功能,將原來16K的頁壓縮為1K,2K,4K,8K,而由於頁的大小發生了變化,LRU列表也有了些改變,對於非16K的頁,是通過unzip_LRU列表進行管理的,可以看到unzip_LRU len為0表示沒有使用壓縮頁.
I/O sum[60790]:cur[30], unzip sum[0]:cur[0]



對於壓縮頁的表,每個表的壓縮比例可能不同,可能存在有的表頁大小為8K,有的表頁大小為2K的情況,unzip_LRUs 怎樣從緩存池中分配內存的呢?

首先,在unzip_LRU列表中對不同壓縮頁大小的頁進行分別管理,其次,通過夥伴算法進行內存的分配,例如:需要從緩存池中申請頁為4K的大小,其過程如下:

a:檢查4K的unzip_LRU列表,檢查是否有可用的空閑頁

b:若有,則直接使用

c:若沒有,檢查8K的unzip_LRU列表

d:若能夠得到空閑頁,將頁分成2個4K的頁,存放到4K的unzip_LRU列表

e:若不能得到空閑頁,從LRU列表中申請一個16K的頁,將頁分成1個8K,2個4K的頁,分別存放到各自大小對應的unzip_LRU列表中。



註:可能出現Free buffers和Database pages之和不等於Buffer pool size,因為緩沖池中的頁肯會被分配給自適應哈希索引,lock信息,insert buffer等,而這部分頁不需要LRU算法進行維護,因此不在LRU列表中。





9.2.如果innodb buffer pool使用參數innodb

_buffer_pool_instances=num設置了大於1個緩沖池實例,那麽就會按照這個參數把innodb_buffer_pool_size=xxx平分為num份。每份的信息顯示類似如下,這部分的內容和9.1小節內容類似,就不再多說。

----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size 541003
Free buffers 1
Database pages 538965
Old database pages 198933
Modified db pages 2190
Pending reads 128
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 603372180, not young 0
1441.81 youngs/s, 0.00 non-youngs/s
Pages read 589705199, created 8703138, written 116954697
1441.61 reads/s, 0.75 creates/s, 1.83 writes/s
Buffer pool hit rate 955 / 1000, young-making rate 45 / 1000 not 0 / 1000
Pages read ahead 1436.98/s, evicted without access 0.87/s, Random read ahead 0.00/s
LRU len: 538965, unzip_LRU len: 0
I/O sum[12158]:cur[6], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size 541003
Free buffers 1
Database pages 538959
Old database pages 198931
Modified db pages 2025
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 602366394, not young 0
1481.35 youngs/s, 0.00 non-youngs/s
Pages read 588738997, created 8708171, written 113209540
1480.56 reads/s, 0.83 creates/s, 1.92 writes/s
Buffer pool hit rate 958 / 1000, young-making rate 42 / 1000 not 0 / 1000
Pages read ahead 1473.73/s, evicted without access 1.96/s, Random read ahead 0.00/s
LRU len: 538959, unzip_LRU len: 0
I/O sum[12158]:cur[6], unzip sum[0]:cur[0]



10.這部分顯示了其他各項的innodb統計:

--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue #這行顯示了innodb內核內有多少個線程,隊列中有多少個線程,隊列中的查詢是innodb為限制並發執行的線程數量而不運行進入內核的線程。查詢在進入隊列之前會休眠等待。
5 read views open inside InnoDB #這行顯示了有多少打開的innodb讀視圖,讀視圖是包含事務開始點的數據庫內容的MVCC快照,你可以看看某特定事務在第6部分TRANSACTIONS是否有讀視圖
Main thread process no. 4368, id 140653691242240, state: sleeping #這行顯示了內核的主線程狀態
Number of rows inserted 3429012215, updated 153529675, deleted 112310240, read 3739562987410 #這行顯示了多少行被插入,更新和刪除,讀取
428.52 inserts/s, 7.21 updates/s, 0.46 deletes/s, 1047933.92 reads/s #這行顯示了對應上面一行的每秒平均值,如果想查看innodb有多少工作量在進行,那麽這兩行是很好的參考值
----------------------------
END OF INNODB MONITOR OUTPUT #要註意了,如果看不到這行輸出,可能是有大量事務或者是有一個大的死鎖截斷了輸出信息
============================

註:內核的主線程狀態可能的狀態值有如下一些:

A:doing background drop tables

B:doing insert buffer merge

C:flushing buffer pool pages

D:making checkpoint

E:purging

F:reserving kernel mutex

G:sleeping

H:suspending

I:waiting for buffer pool flush to end

J:waiting for server activity

0719show engine innodb status解讀