溫馨提示×
您好，登錄后才能下訂單哦！
點擊 登錄注冊 即表示同意《億速云用戶服務條款》
您好，登錄后才能下訂單哦！
經過前面6個篇幅的學習，相信大家對什么是performance_schema，已經初步形成了一個整體認識，但我想很多同行看完之前的文章之后可能還是一臉懵逼，今天就為大家帶來performance_schema系列的最后一個篇章(全系共7個篇章)，在這一期里，我們將為大家列舉數十個performance_schema應用示例。下面，請跟隨我們一起開始performance_schema系統的學習之旅吧。
1.利用等待事件排查MySQL性能問題
通常，在生產服務器上線之前， 我們會對數據庫服務器的硬件進行IO基準測試，對數據庫進行增刪改查的基準測試，建立基線參考數據，以便日后的服務器擴容或架構升級提供數據支撐。在基準測試規劃時，我們通常需要選擇一款基準測試軟件（IO基準測試通常選擇fio和iozone，MySQL數據庫基準測試通常選擇sysbench、tpcc-mysql、workbench等），在使用這些基準測試軟件對服務器壓測到一個極限值時，我們認為所得數據就是被測試服務器的最高性能。但這還不夠，測試性能無法繼續提升的原因還可能是因為你的服務器在BIOS設置、硬件搭配、操作系統參數、文件系統策略、數據庫配置參數等方面不夠優化。所以我們還需要借助一些性能排查手段來找出性能瓶頸所在，以使得我們對數據庫服務器一旦上線之后可能的瓶頸點心中有數。以下我們以sysbench基準測試工具壓測MySQL數據庫為例，介紹如何使用performance_schema的等待事件來排查數據庫性能瓶頸所在。
首先，使用performance_schema配置表啟用等待事件的采集與記錄
# 啟用所有的等待事件的instruments admin@localhost : performance_schema 11:47:46> use performance_schema Database changed # 修改setup_instruments 表的enabled和timed字段為yes，表示啟用對應的instruments admin@localhost : performance_schema 11:48:05> update setup_instruments set enabled='yes',timed='yes' where name like 'wait/%'; Query OK, 269 rows affected (0.00 sec) Rows matched: 323 Changed: 269 Warnings: 0 # 查看修改結果，enabled和timed字段為YES即表示當前instruments已經啟用（但此時采集器并不會立即采集事件數據，需要保存這些等待事件的表--consumers，啟用之后才會開始采集） admin@localhost : performance_schema 11:49:40> select * from setup_instruments where name like 'wait/%'; +--------------------------------------------------------------------+---------+-------+ | NAME | ENABLED | TIMED | +--------------------------------------------------------------------+---------+-------+ | wait/synch/mutex/sql/TC_LOG_MMAP::LOCK_tc | YES | YES | | wait/synch/mutex/sql/LOCK_des_key_file | YES | YES | ............ | wait/io/socket/sql/server_tcpip_socket | YES | YES | | wait/io/socket/sql/server_unix_socket | YES | YES | | wait/io/socket/sql/client_connection | YES | YES | | wait/lock/metadata/sql/mdl | YES | YES | +--------------------------------------------------------------------+---------+-------+ 323 rows in set (0.01 sec) # 啟用等待事件的consumers admin@localhost : performance_schema 11:48:21> update setup_consumers set enabled='yes' where name like '%wait%'; Query OK, 3 rows affected (0.00 sec) Rows matched: 3 Changed: 3 Warnings: 0 admin@localhost : performance_schema 11:49:20> select * from setup_consumers where name like '%wait%'; +---------------------------+---------+ | NAME | ENABLED | +---------------------------+---------+ | events_waits_current | YES | | events_waits_history | YES | | events_waits_history_long | YES | +---------------------------+---------+ 3 rows in set (0.00 sec)
然后，使用sysbench對數據庫執行加壓，并逐漸增加并發線程數，直到tps、qps不再隨著線程數的增加而增加為止。
sysbench --test=oltp --db-driver=mysql --mysql-table-engine=innodb --mysql-host=10.10.10.10 --mysql-port=3306 --mysql-db=sbtest --mysql-user='qbench' --mysql-password='qbench' --test=/usr/share/doc/sysbench/tests/db/oltp.lua --oltp-table-size=5000000 --oltp-tables-count=8 --num-threads=16 --max-time=1800 --max-requests=0 --report-interval=1 run ............ [ 111s] threads: 16, tps: 52.99, reads/s: 668.93, writes/s: 171.98, response time: 629.52ms (95%) [ 112s] threads: 16, tps: 42.00, reads/s: 650.93, writes/s: 202.98, response time: 688.46ms (95%) ............
從sysbench的輸出結果中，我們可以看到在16個并發線程oltp壓力下，tps只能跑到100不到，且延遲在600ms+，說明存在嚴重的性能瓶頸（或者在MySQL內部發生了嚴重的互斥等待，或者硬件設備嚴重的性能不足），現在，我們先使用操作系統命令查看硬件負載情況。
# top命令查看到CPU資源絕大部分都消耗在了%wa上，說明IO設備性能出現嚴重不足 [root@localhost ~]# top top - 18:59:03 up 7:02, 3 users, load average: 4.28, 5.82, 4.22 Tasks: 186 total, 1 running, 185 sleeping, 0 stopped, 0 zombie Cpu0 : 4.1%us, 8.5%sy, 0.0%ni, 11.9%id, 75.4%wa, 0.0%hi, 0.0%si, 0.0%st Cpu1 : 4.0%us, 13.1%sy, 0.0%ni, 17.5%id, 65.0%wa, 0.0%hi, 0.3%si, 0.0%st Cpu2 : 9.4%us, 32.1%sy, 0.0%ni, 2.3%id, 55.5%wa, 0.0%hi, 0.7%si, 0.0%st Cpu3 : 3.0%us, 5.3%sy, 0.0%ni, 31.0%id, 60.0%wa, 0.0%hi, 0.7%si, 0.0%st Mem: 8053664k total, 1684236k used, 6369428k free, 87868k buffers Swap: 2031612k total, 0k used, 2031612k free, 150680k cached # iostat命令查看磁盤負載，通過%util列可以看到，磁盤處于100%滿負載狀態 avg-cpu: %user %nice %system %iowait %steal %idle 1.77 0.00 2.28 95.70 0.00 0.25 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util dm-2 0.00 0.00 277.00 160.00 8864.00 2774.00 26.63 47.84 112.98 2.29 100.10 avg-cpu: %user %nice %system %iowait %steal %idle 5.05 0.00 11.62 64.14 0.00 19.19 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util dm-2 0.00 0.00 267.00 244.00 8544.00 4643.00 25.81 28.20 40.29 1.96 100.00
通過查詢系統負載，一眼就可以看出來是由于磁盤性能嚴重不足導致的，但是，在數據庫內部的事件信息是如何體現的呢（注意：如果你沒有足夠的performance_schema使用經驗，此時是絕好的學習積累的機會，不要錯過，也許哪一天操作系統負載并不能看出來端倪的時候，這些事件信息能幫上大忙）
# 為了方便查詢等待事件統計，我們可以先創建一個視圖，用于實時統計當前等待事件（非歷史數據） admin@localhost : performance_schema 12:14:14> create view sys.test_waits as select sum(TIMER_WAIT) as TIMER_WAIT,sum(NUMBER_OF_BYTES) as NUMBER_OF_BYTES, EVENT_NAME,OPERATION from events_waits_current where EVENT_NAME!='idle' group by EVENT_NAME,OPERATION; Query OK, 0 rows affected (0.04 sec) # 使用前面創建的視圖進行查詢，對這個視圖查詢結果進行降序排序查詢。從下面的查詢結果中，我們可以看到時間開銷排名前5的有4個都是與IO相關的等待，剩下1個是binlog相關的互斥等待 admin@localhost : performance_schema 12:30:38> select sys.format_time(TIMER_WAIT),sys.format_bytes(NUMBER_OF_BYTES),EVENT_NAME,OPERATION from sys.test_waits where sys.format_time(TIMER_WAIT) not regexp 'ns|us' order by TIMER_WAIT desc; +-----------------------------+-----------------------------------+------------------------------------------------+------------+ | sys.format_time(TIMER_WAIT) | sys.format_bytes(NUMBER_OF_BYTES) | EVENT_NAME | OPERATION | +-----------------------------+-----------------------------------+------------------------------------------------+------------+ | 16.60 s | 224.00 KiB | wait/io/file/innodb/innodb_data_file | read | | 16.05 s | 553 bytes | wait/io/table/sql/handler | fetch | | 1.96 s | NULL | wait/io/file/sql/binlog | sync | | 1.96 s | NULL | wait/synch/cond/sql/MYSQL_BIN_LOG::update_cond | timed_wait | | 1.85 s | 1.34 KiB | wait/io/file/sql/binlog | write | | 56.66 ms | NULL | wait/io/file/innodb/innodb_log_file | sync | +-----------------------------+-----------------------------------+------------------------------------------------+------------+ 6 rows in set (0.01 sec) # 當然，你也可以直接查詢events_waits_current表（返回數據行數可能比較多，且查詢結果并沒有做分組聚合，是逐行的事件記錄數據） admin@localhost : performance_schema 11:59:25> select THREAD_ID,EVENT_NAME,sys.format_time(TIMER_WAIT),INDEX_NAME,NESTING_EVENT_TYPE,OPERATION,NUMBER_OF_BYTES from events_waits_current where EVENT_NAME!='idle' order by TIMER_WAIT desc; +-----------+------------------------------------------------+-----------------------------+------------+--------------------+------------+-----------------+ | THREAD_ID | EVENT_NAME | sys.format_time(TIMER_WAIT) | INDEX_NAME | NESTING_EVENT_TYPE | OPERATION | NUMBER_OF_BYTES | +-----------+------------------------------------------------+-----------------------------+------------+--------------------+------------+-----------------+ | 115 | wait/io/table/sql/handler | 169.48 ms | PRIMARY | STATEMENT | fetch | 39 | | 115 | wait/io/file/innodb/innodb_data_file | 169.48 ms | NULL | WAIT | read | 16384 | | 101 | wait/io/table/sql/handler | 93.76 ms | PRIMARY | STATEMENT | fetch | 39 | | 101 | wait/io/file/innodb/innodb_data_file | 93.76 ms | NULL | WAIT | read | 16384 | | 111 | wait/io/file/innodb/innodb_data_file | 73.08 ms | NULL | STATEMENT | read | 16384 | | 103 | wait/io/file/innodb/innodb_data_file | 63.13 ms | NULL | STATEMENT | read | 16384 | | 106 | wait/io/file/innodb/innodb_data_file | 53.24 ms | NULL | STATEMENT | read | 16384 | | 113 | wait/io/table/sql/handler | 51.90 ms | PRIMARY | STATEMENT | fetch | 39 | | 113 | wait/io/file/innodb/innodb_data_file | 51.90 ms | NULL | WAIT | read | 16384 | | 49 | wait/synch/cond/sql/MYSQL_BIN_LOG::update_cond | 27.48 ms | NULL | STATEMENT | timed_wait | NULL | ............ 57 rows in set (0.00 sec)
從上述等待事件的查詢結果中，我們可以非常清晰地看到，事務大多數的延遲時間花在了等待IO上（主要是undo log、redo log，獨立表空間文件，binlog的fetch和read系統調用），說明IO設備可能出現了嚴重的性能瓶頸，這里與操作系統命令查看到的磁盤性能嚴重不足相對應。
結論：通過以上測試數據表明，MySQL的性能嚴重低下的原因是因為磁盤性能嚴重不足成為了瓶頸（一般情況下，4個core的cpu在內存和磁盤不構成瓶頸的情況下可以達到800+ tps才可能會構成瓶頸）
針對IO性能不足，建議優化策略：
更換IO性能更好的設備
新增2個獨立的相同設備，把MySQL 中的redo log、binlog、其他data file分別放在3個獨立的IO設備上，以便數據庫中的隨機IO和順序IO不會因為相互爭搶資源而導致IO等待
PS：
當然，你也許會說，我們在這個案例里故意使用一臺配置很差的服務器。是的沒錯。但我們可以去思考一個問題：performance_schema到底能夠對我們使用MySQL提供多大幫助呢？對于目前來講，互聯網上并不能找到太多靠譜的performance_schema使用經驗，需要我們不斷地去挖掘。我們建議有條件的同行可以準備兩臺測試服務器(一臺低配置，一臺高配置服務器)，通過對比測試數據你就能得出performance_schema的使用經驗了，正所謂沒有對比就沒有傷害。
2.鎖問題排查
2.1 找出誰持有全局讀鎖
全局讀鎖通常是由flush table with read lock;這類語句添加，這類語句通常是在各種備份工具為了拿到一致性備份時使用，另外，在具有主從復制架構的環境中做主備切換時也常常使用，除了這兩種情況之外，還有一種情況也是最難排查的一種情況，那就是線上系統權限約束不規范的時候，各種人員使用的數據庫帳號都具有RELOAD權限時，都可以對數據庫加全局讀鎖。
在MySQL 5.7之前的版本，要排查誰持有全局讀鎖通常在數據庫層面是很難直接查詢到有用數據（innodb_locks表也只能記錄innodb層的鎖信息，而全局讀鎖是server層的鎖，所以也無法查詢到），從MySQL 5.7開始提供表performance_schema.metadata_locks表記錄一些Server層的鎖信息（包括全局讀鎖和MDL鎖等），下面我們通過一個示例來演示然后使用performance_schema來找出誰持有全局讀鎖。
首先，開啟第一個會話，執行全局讀鎖。
# 執行加鎖語句 root@localhost : sbtest 12:28:30> flush table with read lock; Query OK, 0 rows affected (0.00 sec) # 查詢以下加鎖線程的process id，以便后續排查過程好對應 root@localhost : sbtest 12:31:48> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 4 | +-----------------+ 1 row in set (0.00 sec)
現在，我們開啟第二個會話執行任意可能對數據造成修改的語句，我們就以update操作為例吧。
root@localhost : sbtest 12:42:36> use sbtest Database changed root@localhost : sbtest 12:42:38> select * from sbtest1 limit 1\G; *************************** 1. row *************************** id: 21 k: 2483476 c: 09279210219-37745839908-56185699327-79477158641-86711242956-61449540392-42622804506-61031512845-36718422840-11028803849 pad: 96813293060-05308009118-09223341195-19224109585-45598161848 1 row in set (0.00 sec) ERROR: No query specified root@localhost : sbtest 12:42:39> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 5 | +-----------------+ 1 row in set (0.00 sec) root@localhost : sbtest 12:42:44> update sbtest1 set pad='xxx' where id=21; 操作被阻塞
現在，我們開啟第三個會話，開始使用一些手段進行排查。
root@localhost : (none) 12:42:25> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 16 | +-----------------+ 1 row in set (0.00 sec) # 查詢processlist信息，這里只能看到processid為5的線程State為Waiting for global read lock，表示正在等待全局讀鎖 root@localhost : (none) 12:43:11> show processlist; +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------------------------------+ | 3 | qfsys | 192.168.2.168:41042 | NULL | Binlog Dump | 11457 | Master has sent all binlog to slave; waiting for more updates | NULL | | 4 | root | localhost | sbtest | Sleep | 234 | | NULL | | 5 | root | localhost | sbtest | Query | 26 | Waiting for global read lock | update sbtest1 set pad='xxx' where id=21 | | 16 | root | localhost | NULL | Query | 0 | starting | show processlist | +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------------------------------+ 4 rows in set (0.00 sec) # 繼續查詢information_schema.innodb_locks、innodb_lock_waits、innodb_trx表，發現三個表均為空 root@localhost : (none) 12:59:30> select * from information_schema.innodb_locks; Empty set, 1 warning (0.00 sec) root@localhost : (none) 12:59:40> select * from information_schema.innodb_lock_waits; Empty set, 1 warning (0.00 sec) root@localhost : (none) 12:59:43> select * from information_schema.innodb_trx\G Empty set (0.00 sec) # 再使用show engine innodb status;查看一把（這里只需要看TRANSACTION段落即可），仍然無任何有用的鎖信息 root@localhost : (none) 12:59:48> show engine innodb status; ...... ===================================== 2018-06-25 13:01:43 0x7fe55ded8700 INNODB MONITOR OUTPUT ===================================== ...... ------------ TRANSACTIONS ------------ Trx id counter 2527502 Purge done for trx's n:o < 2527500 undo n:o < 0 state: running but idle History list length 3 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 422099353083504, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 422099353082592, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 422099353081680, not started 0 lock struct(s), heap size 1136, 0 row lock(s) -------- FILE I/O ......
通過上面的常規手段查詢下來，無任何有用信息，這個時候，有gdb調試經驗的老鳥估計就要開始使用gdb，strace，pstack什么的命令查看MySQL 調用棧、線程信息什么的了，但這對于沒有C語言基礎的人來說，基本上是看天書，好在從MySQL 5.7版本開始，提供performance_schema.metadata_locks表，該表記錄了各種Server層的鎖信息（包括全局讀鎖和MDL鎖信息），下面我們開啟第三個會話查詢該表試試看。
# 我們還可以通過performance_schema.metadata_locks表來排查誰持有全局讀鎖，全局讀鎖通常在該表記錄著同一個會話的OBJECT_TYPE為global和commit、LOCK_TYPE都為SHARED的兩把顯式鎖，如下 root@localhost : (none) 01:01:43> select * from performance_schema.metadata_locks where OWNER_THREAD_ID!=sys.ps_thread_id(connection_id())\G; *************************** 1. row *************************** OBJECT_TYPE: GLOBAL OBJECT_SCHEMA: NULL OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: 140621322913984 LOCK_TYPE: SHARED # 共享鎖 LOCK_DURATION: EXPLICIT # 顯式 LOCK_STATUS: GRANTED # 已授予 SOURCE: lock.cc:1110 OWNER_THREAD_ID: 94 # 持有鎖的內部線程ID為94 OWNER_EVENT_ID: 16 *************************** 2. row *************************** OBJECT_TYPE: COMMIT OBJECT_SCHEMA: NULL OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: 140621322926064 LOCK_TYPE: SHARED # 共享鎖 LOCK_DURATION: EXPLICIT # 顯式 LOCK_STATUS: GRANTED # 已授予 SOURCE: lock.cc:1194 OWNER_THREAD_ID: 94 # 持有鎖的內部線程ID為94 OWNER_EVENT_ID: 16 *************************** 3. row *************************** OBJECT_TYPE: GLOBAL OBJECT_SCHEMA: NULL OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: 140621391527216 LOCK_TYPE: INTENTION_EXCLUSIVE # 意向排它鎖 LOCK_DURATION: STATEMENT # 語句 LOCK_STATUS: PENDING # 狀態為pending，表示正在等待被授予 SOURCE: sql_base.cc:3190 OWNER_THREAD_ID: 95 # 被阻塞的內部線程ID為95 OWNER_EVENT_ID: 38 3 rows in set (0.00 sec) # 查看process id為4，5 各自對應的內部線程ID是多少 root@localhost : (none) 01:33:36> select sys.ps_thread_id(4); +---------------------+ | sys.ps_thread_id(4) | +---------------------+ | 94 | # process id=4的線程對應的內部線程ID正好為94，說明就是process id=4的線程持有了全局讀鎖 +---------------------+ 1 row in set (0.00 sec) root@localhost : (none) 01:34:10> select sys.ps_thread_id(5); +---------------------+ | sys.ps_thread_id(5) | +---------------------+ | 95 | # proces id=5的線程對應的內部線程正好是95，說明在等待全局讀鎖的就是process id=5的線程 +---------------------+ 1 row in set (0.00 sec)
如果是生產環境，綜合上述信息，通過show processlist信息中對應的process id=4的行記錄中找到user、host、db信息，大致判斷一下是屬于什么業務用途，找相關人員詢問清楚，該殺掉就殺掉，順便討論下今后如何避免這個問題。
我們可能經常會發現執行語句時被阻塞等待MDL鎖，例如：使用show processlist;語句查看線程信息時可能會發現State列為"Waiting for table metadata lock"，碰到這種情況我們應該如何去排查是誰持有了MDL鎖沒有釋放呢，下面我們嘗試著進行MDL鎖等待場景模擬（mdl鎖記錄對應的instruments為wait/lock/metadata/sql/mdl，默認未啟用，對應的consumers為performance_schema.metadata_locks，在setup_consumers只受全局配置項global_instrumentation控制，默認啟用）。
首先，打開兩個會話，分別執行如下語句。
# 會話1，顯式開啟一個事務，并執行一個update語句更新sbtest1表不提交 root@localhost : sbtest 12:26:25> use sbtest Database changed root@localhost : sbtest 12:26:30> begin; Query OK, 0 rows affected (0.00 sec) root@localhost : sbtest 12:26:32> update sbtest1 set pad='yyy' where id=1; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 # 會話2，對sbtest1表執行DDL語句添加一個普通索引 root@localhost : sbtest 12:42:50> use sbtest Database changed root@localhost : sbtest 12:42:56> alter table sbtest1 add index i_c(c); # 被阻塞
此時，我們另外開啟一個會話3，使用show processlist語句查詢線程信息，可以發現update語句正在等待MDL鎖(Waiting for table metadata lock)。
root@localhost : (none) 12:37:49> show processlist; +----+------+-----------+--------+---------+------+---------------------------------+--------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+------+-----------+--------+---------+------+---------------------------------+--------------------------------------+ | 92 | root | localhost | sbtest | Query | 121 | Waiting for table metadata lock | alter table sbtest1 add index i_c(c) | | 93 | root | localhost | NULL | Query | 0 | starting | show processlist | | 94 | root | localhost | sbtest | Sleep | 1078 | | NULL | +----+------+-----------+--------+---------+------+---------------------------------+--------------------------------------+ 3 rows in set (0.00 sec)
在MySQL 5.7版本之前，我們不能從數據庫層面很直觀地去查詢誰持有MDL鎖信息（當然你可以說你會gdb之類的工具來查看，但這類工具的使用需要具有一定c編程語言基礎），現在，我們可以通過查詢performance_schema.metadata_locks表得知MDL鎖信息，發現有5行MDL鎖記錄，其中， 第一行為sbtest.sbtest1表的SHARED_WRITE鎖，處于GRANTED狀態，為136線程持有(對應process id為94)，其他后續4行中，有sbtest.sbtest1表的SHARED_UPGRADABLE、EXCLUSIVE鎖，其中SHARED_UPGRADABLE處于GRANTED狀態，EXCLUSIVE處于PENDING狀態，為134線程持有（對應process id為92）。說明134線程在等待MDL鎖。
root@localhost : (none) 01:23:05> select * from performance_schema.metadata_locks where OWNER_THREAD_ID!=sys.ps_thread_id(connection_id())\G; *************************** 1. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: sbtest OBJECT_NAME: sbtest1 OBJECT_INSTANCE_BEGIN: 139886013386816 LOCK_TYPE: SHARED_WRITE LOCK_DURATION: TRANSACTION LOCK_STATUS: GRANTED SOURCE: sql_parse.cc:5996 OWNER_THREAD_ID: 136 OWNER_EVENT_ID: 721 *************************** 2. row *************************** OBJECT_TYPE: GLOBAL OBJECT_SCHEMA: NULL OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: 139886348911600 LOCK_TYPE: INTENTION_EXCLUSIVE LOCK_DURATION: STATEMENT LOCK_STATUS: GRANTED SOURCE: sql_base.cc:5497 OWNER_THREAD_ID: 134 OWNER_EVENT_ID: 4667 *************************** 3. row *************************** OBJECT_TYPE: SCHEMA OBJECT_SCHEMA: sbtest OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: 139886346748096 LOCK_TYPE: INTENTION_EXCLUSIVE LOCK_DURATION: TRANSACTION LOCK_STATUS: GRANTED SOURCE: sql_base.cc:5482 OWNER_THREAD_ID: 134 OWNER_EVENT_ID: 4667 *************************** 4. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: sbtest OBJECT_NAME: sbtest1 OBJECT_INSTANCE_BEGIN: 139886346749984 LOCK_TYPE: SHARED_UPGRADABLE LOCK_DURATION: TRANSACTION LOCK_STATUS: GRANTED SOURCE: sql_parse.cc:5996 OWNER_THREAD_ID: 134 OWNER_EVENT_ID: 4669 *************************** 5. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: sbtest OBJECT_NAME: sbtest1 OBJECT_INSTANCE_BEGIN: 139886348913168 LOCK_TYPE: EXCLUSIVE LOCK_DURATION: TRANSACTION LOCK_STATUS: PENDING SOURCE: mdl.cc:3891 OWNER_THREAD_ID: 134 OWNER_EVENT_ID: 4748 5 rows in set (0.00 sec)
通過上述數據，我們知道了是哪個線程持有了MDL鎖，通過show processlist語句的查詢結果可以看到process id為94的線程已經長時間處于sleep狀態，但是我們在這里并不能看到這個線程執行了什么語句，我們可能需要查詢一下information_schema.innodb_trx表，確認一下該線程是否存在著一個沒有提交的事務。如下，通過查詢該表發現process id為94(trx_mysql_thread_id=94)的線程確實有一個未提交的事務，但并沒有太多的有用信息，除了一個事務開始時間和process id（trx_started: 2018-01-14 01:19:25， trx_mysql_thread_id: 94）
root@localhost : (none) 01:32:17> select * from information_schema.innodb_trx\G; *************************** 1. row *************************** trx_id: 2452892 trx_state: RUNNING trx_started: 2018-01-14 01:19:25 trx_requested_lock_id: NULL trx_wait_started: NULL trx_weight: 3 trx_mysql_thread_id: 94 ...... 1 row in set (0.00 sec)
此時，從我們掌握的所有數據信息來看，雖然知道了是136線程的事務沒有提交導致的134線程發生MDL鎖等待，但是我們并不知道136線程正在做什么事情。我們當然可以kill掉136線程讓134線程繼續往下執行，但是我們不知道136線程在執行什么語句，就無法找到相關的開發人員進行優化，下次我們還可能再次碰到類似的問題，所以，我們還可以借助performance_schema.events_statements_current表來查詢某個線程正在執行或者說最后一次執行完成的語句事件信息(這里信息并不一定可靠，因為該表中對于每個線程只能記錄當前正在執行和最近一次執行完成的語句事件信息，一旦這個線程執行新的語句，信息就會被覆蓋)，如下：
root@localhost : (none) 01:47:53> select * from performance_schema.events_statements_current where thread_id=136\G; *************************** 1. row *************************** THREAD_ID: 136 EVENT_ID: 715 END_EVENT_ID: 887 EVENT_NAME: statement/sql/update SOURCE: socket_connection.cc:101 ...... SQL_TEXT: update sbtest1 set pad='yyy' where id=1 DIGEST: 69f516aa8eaa67fd6e7bfd3352de5d58 DIGEST_TEXT: UPDATE `sbtest1` SET `pad` = ? WHERE `id` = ? CURRENT_SCHEMA: sbtest ...... MESSAGE_TEXT: Rows matched: 1 Changed: 1 Warnings: 0 ...... 1 row in set (0.00 sec)
從performance_schema.events_statements_current 表的查詢信息中，通過SQL_TEXT字段我們可以清晰地看到該線程正在執行的SQL語句是什么。如果是生產環境，現在，你可以去找相關的開發人員交涉，下次碰到類似的語句必須及時提交，避免下次再發生類似的問題。
表級鎖對應的instruments(wait/lock/table/sql/handler)默認啟用，對應的consumers表為performance_schema.table_handles在setup_consumers只受全局配置項global_instrumentation控制，默認啟用。所以，默認情況下只需要設置系統配置參數performance_schema=ON即可，下面我們通過一個示例演示如何找出誰持有表級鎖。
首先，開啟兩個會話，第一個會話對一個表(innodb引擎)執行顯式加表級鎖，第二個會話對該表執行DML語句操作。
# 會話1加表級鎖 root@localhost : sbtest 02:15:17> use sbtest Database changed root@localhost : sbtest 02:40:27> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 18 | +-----------------+ 1 row in set (0.00 sec) root@localhost : sbtest 02:40:29> lock table sbtest1 read; Query OK, 0 rows affected (0.00 sec) # 會話2對該表執行update更新 root@localhost : sbtest 10:26:37> use sbtest Database changed root@localhost : sbtest 02:15:33> select connection_id(); +-----------------+ | connection_id() | +-----------------+ | 19 | +-----------------+ 1 row in set (0.00 sec) root@localhost : sbtest 02:40:34> update sbtest1 set pad='xxx' where id=1; # 被阻塞
然后，開啟第三個會話，使用show processlist語句查詢線程信息，可以發現update語句正在等待MDL鎖(Waiting for table metadata lock)
root@localhost : (none) 02:40:14> show processlist; +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+-----------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+-----------------------------------------+ | 3 | qfsys | 192.168.2.168:41042 | NULL | Binlog Dump | 18565 | Master has sent all binlog to slave; waiting for more updates | NULL | | 18 | root | localhost | sbtest | Sleep | 67 | | NULL | | 19 | root | localhost | sbtest | Query | 51 | Waiting for table metadata lock | update sbtest1 set pad='xxx' where id=1 | | 20 | root | localhost | NULL | Query | 0 | starting | show processlist | +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+-----------------------------------------+ 4 rows in set (0.00 sec)
如上所示，既然是等待MDL鎖，那么我們在會話3查詢performance_schema.metadata_locks表，記錄的順序代表持有鎖的時間順序，如下：
root@localhost : (none) 02:41:41> select * from performance_schema.metadata_locks where OWNER_THREAD_ID!=sys.ps_thread_id(connection_id())\G; *************************** 1. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: sbtest OBJECT_NAME: sbtest1 OBJECT_INSTANCE_BEGIN: 140622530920576 LOCK_TYPE: SHARED_READ_ONLY LOCK_DURATION: TRANSACTION LOCK_STATUS: GRANTED SOURCE: sql_parse.cc:5996 OWNER_THREAD_ID: 113 #內部ID為 113 的線程被授予了LOCK_TYPE: SHARED_READ_ONLY，持有該所的線程不允許其他線程修改sbtest1表的數據 OWNER_EVENT_ID: 11 *************************** 2. row *************************** OBJECT_TYPE: GLOBAL OBJECT_SCHEMA: NULL OBJECT_NAME: NULL OBJECT_INSTANCE_BEGIN: 140620517607728 LOCK_TYPE: INTENTION_EXCLUSIVE LOCK_DURATION: STATEMENT LOCK_STATUS: GRANTED SOURCE: sql_base.cc:3190 OWNER_THREAD_ID: 114 # 內部ID為114的線程被授予了LOCK_TYPE: INTENTION_EXCLUSIVE，但這只是個意向鎖 OWNER_EVENT_ID: 12 *************************** 3. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: sbtest OBJECT_NAME: sbtest1 OBJECT_INSTANCE_BEGIN: 140620517607824 LOCK_TYPE: SHARED_WRITE LOCK_DURATION: TRANSACTION LOCK_STATUS: PENDING SOURCE: sql_parse.cc:5996 OWNER_THREAD_ID: 114 # 內部ID為114的線程正在等待LOCK_TYPE: SHARED_WRITE被授予 OWNER_EVENT_ID: 12 3 rows in set (0.00 sec)
排查陷入僵局，我們知道MDL鎖非常常見，對表的絕大部分的操作都會先對表加MDL鎖（根據performance_schema.metadata_locks表中記錄的鎖信息也不頂用了），通常看到這些信息時，我們可能會立馬聯想到，需要去查詢一下information_schema下的三張關于Innodb引擎的鎖和事務信息表(INNODB_LOCK_WAITS、INNODB_LOCKS、INNODB_TRX)，我們嘗試著查看一下這三張表（會話3執行），可以發現都沒有記錄。
root@localhost : (none) 02:41:53> select * from information_schema.INNODB_TRX; Empty set (0.00 sec) root@localhost : (none) 02:42:58> select * from information_schema.INNODB_LOCKS; Empty set, 1 warning (0.00 sec) root@localhost : (none) 02:43:02> select * from information_schema.INNODB_LOCK_WAITS; Empty set, 1 warning (0.00 sec)
當然，可能有的人會說，就4個線程，第二個會話的"Command "為sleep，應該可能是它，把它kill試試看。是的，在該案例中確實可以做這個嘗試，但如果是生產環境中有數十上百個正常的長連接處于sleep狀態呢？這個時候我們就不能挨個去嘗試了，這個時候我們可以嘗試著去查詢一些表級別的鎖信息（通過會話3查詢performance_schema.table_handles表），如下：
root@localhost : (none) 02:43:06> select * from performance_schema.table_handles where OWNER_THREAD_ID!=0\G; *************************** 1. row *************************** OBJECT_TYPE: TABLE OBJECT_SCHEMA: sbtest OBJECT_NAME: sbtest1 OBJECT_INSTANCE_BEGIN: 140622530923216 OWNER_THREAD_ID: 113 OWNER_EVENT_ID: 11 INTERNAL_LOCK: NULL EXTERNAL_LOCK: READ EXTERNAL # 發現內部ID為113的線程持有了sbtest1表的READ EXTERNAL表級鎖，這個也是為什么內部ID為114的線程無法獲取到MDL寫鎖的原因 1 row in set (0.00 sec)
通過上述查詢到的相關數據，113線程對sbtest1表顯式加了表級讀鎖，而且長時間處于sleep狀態，但我們并不知道該線程正在執行什么SQL語句，我們可以通過performance_schema.events_statements_current表查詢，如下：
root@localhost : (none) 02:43:22> select * from performance_schema.events_statements_current where thread_id=113\G; *************************** 1. row *************************** THREAD_ID: 113 EVENT_ID: 10 END_EVENT_ID: 10 EVENT_NAME: statement/sql/lock_tables SOURCE: socket_connection.cc:101 TIMER_START: 18503556405463000 TIMER_END: 18503556716572000 TIMER_WAIT: 311109000 LOCK_TIME: 293000000 SQL_TEXT: lock table sbtest1 read # 這里可以看到，內部ID為113的線程對表sbtest1執行了加讀鎖語句 DIGEST: 9f987e807ca36e706e33275283b5572b DIGEST_TEXT: LOCK TABLE `sbtest1` READ CURRENT_SCHEMA: sbtest ...... 1 row in set (0.00 sec)
從performance_schema.events_statements_current 表的查詢信息中，通過SQL_TEXT字段我們可以清晰地看到該線程正在執行的SQL語句是什么。如果是生產環境，現在，你可以去找相關的開發人員確認，如果沒有什么特殊操作，就可以嘗試著kill掉這個線程(會話3執行，processlist_id為18)，同時針對這個問題進行優化，避免下次再發生類似的問題。
# 如何知道內部ID 113對應的process id是多少呢？我們可以通過performance_schema.threads表查詢 root@localhost : (none) 02:48:19> select processlist_id from performance_schema.threads where thread_id=113; +----------------+ | processlist_id | +----------------+ | 18 | +----------------+ 1 row in set (0.00 sec) # 執行kill root@localhost : (none) 02:48:24> kill 18; Query OK, 0 rows affected (0.00 sec) root@localhost : (none) 02:48:40> show processlist; +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------+ | 3 | qfsys | 192.168.2.168:41042 | NULL | Binlog Dump | 18994 | Master has sent all binlog to slave; waiting for more updates | NULL | | 19 | root | localhost | sbtest | Sleep | 480 | | NULL | | 20 | root | localhost | NULL | Query | 0 | starting | show processlist | +----+-------+---------------------+--------+-------------+-------+---------------------------------------------------------------+------------------+ 3 rows in set (0.00 sec) # 返回執行update語句的會話2，語句已經執行成功 root@localhost : sbtest 02:40:34> update sbtest1 set pad='xxx' where id=1; Query OK, 0 rows affected (7 min 50.23 sec) Rows matched: 0 Changed: 0 Warnings: 0
該案例中涉及的performance_schema.data_lock表在MySQL 8.0中新增，在8.0之前的版本中不支持，在這里僅作為針對MySQL 5.7的performance_schema的一個延伸學習
如果一個事務長時間未提交，我們雖然可以從information_schema.innodb_trx、performance_schema.events_transactions_current等表中查詢到相應的事務信息，但卻無從知道這個事務持有了哪些鎖。雖然information_schema.innodb_locks表是用于記錄事務鎖信息的，但需要在兩個不同的事務發生鎖等待時該表才會記錄兩個事務的鎖信息。從8.0開始，在performance_schema中提供了一個data_locks表用于記錄任意事務的鎖信息(同時廢棄了information_schema.innodb_locks表)，不需要有鎖等待關系存在(注意，該表中只記錄innodb存儲引擎層的鎖)，如下
首先，我們在8.0中打開一個會話(會話1)，顯式開啟一個事務。
root@localhost : xiaoboluo 01:26:09> use xiaoboluo Database changed root@localhost : xiaoboluo 01:26:19> select * from t_luoxiaobo limit 1; +----+------+---------------------+ | id | test | datet_time | +----+------+---------------------+ | 2 | 1 | 2017-09-06 01:11:59 | +----+------+---------------------+ 1 row in set (0.00 sec) root@localhost : xiaoboluo 01:26:21> begin; Query OK, 0 rows affected (0.00 sec) root@localhost : xiaoboluo 01:26:23> update t_luoxiaobo set datet_time=now() where id=2; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0
打開另外一個會話（會話2）查詢data_locks表
root@localhost : performance_schema 01:27:21> select * from data_locks\G; *************************** 1. row *************************** ENGINE: INNODB ENGINE_LOCK_ID: 55562:62 ENGINE_TRANSACTION_ID: 55562 THREAD_ID: 54 # 持有線程內部ID EVENT_ID: 85 OBJECT_SCHEMA: xiaoboluo # 庫名 OBJECT_NAME: t_luoxiaobo # 表名 PARTITION_NAME: NULL SUBPARTITION_NAME: NULL INDEX_NAME: NULL # 索引名稱 OBJECT_INSTANCE_BEGIN: 140439793477144 LOCK_TYPE: TABLE # 表級鎖 LOCK_MODE: IX # IX鎖 LOCK_STATUS: GRANTED # 被授予狀態 LOCK_DATA: NULL *************************** 2. row *************************** ENGINE: INNODB ENGINE_LOCK_ID: 55562:2:4:2 ENGINE_TRANSACTION_ID: 55562 THREAD_ID: 54 # 持有鎖線程內部ID EVENT_ID: 85 OBJECT_SCHEMA: xiaoboluo # 庫名 OBJECT_NAME: t_luoxiaobo #表名 PARTITION_NAME: NULL SUBPARTITION_NAME: NULL INDEX_NAME: PRIMARY # 索引為主鍵 OBJECT_INSTANCE_BEGIN: 140439793474104 LOCK_TYPE: RECORD # 記錄鎖 LOCK_MODE: X # 排它鎖 LOCK_STATUS: GRANTED # 被授予狀態 LOCK_DATA: 2 # 被鎖定的數據記錄，這里的記錄對應的是 INDEX_NAME: PRIMARY 的value 2 rows in set (0.00 sec)
從查詢結果中我們可以看到，有兩行鎖記錄，第一行是對表t_luoxiaobo的IX鎖，狀態為GRANTED，第二行為使用主鍵索引的X鎖記錄鎖，狀態為GRANTED 。
現在，我們模擬兩個DML發生鎖等待的場景。我們新開一個會話（會話3），在會話1中的事務未提交的情況下，會話3對表t_luoxiaobo執行同樣的操作。
root@localhost : (none) 09:34:49> use xiaoboluo Database changed root@localhost : xiaoboluo 09:34:54> begin; Query OK, 0 rows affected (0.00 sec) root@localhost : xiaoboluo 09:34:55> update t_luoxiaobo set datet_time=now() where id=2; # 被阻塞
回到會話2中查詢data_locks表，可以發現有4行鎖記錄了
root@localhost : (none) 09:35:18> select * from performance_schema.data_locks\G; *************************** 1. row *************************** ...... THREAD_ID: 55 ...... LOCK_TYPE: TABLE LOCK_MODE: IX LOCK_STATUS: GRANTED LOCK_DATA: NULL *************************** 2. row *************************** ENGINE: INNODB ENGINE_LOCK_ID: 55563:2:4:2 ENGINE_TRANSACTION_ID: 55563 THREAD_ID: 55 # 內部線程ID EVENT_ID: 8 OBJECT_SCHEMA: xiaoboluo OBJECT_NAME: t_luoxiaobo PARTITION_NAME: NULL SUBPARTITION_NAME: NULL INDEX_NAME: PRIMARY # 發生鎖的索引名稱 OBJECT_INSTANCE_BEGIN: 140439793480168 LOCK_TYPE: RECORD # 記錄鎖 LOCK_MODE: X # 排它鎖 LOCK_STATUS: WAITING # 正在等待鎖被授予 LOCK_DATA: 2 # 鎖定的索引value，這里與內部ID為54線程持有的主鍵值為2的X鎖完全一樣，說明這里就是被內部ID為54線程阻塞了 *************************** 3. row *************************** ...... THREAD_ID: 54 ....... LOCK_TYPE: TABLE LOCK_MODE: IX LOCK_STATUS: GRANTED LOCK_DATA: NULL *************************** 4. row *************************** ...... THREAD_ID: 54 EVENT_ID: 85 OBJECT_SCHEMA: xiaoboluo OBJECT_NAME: t_luoxiaobo PARTITION_NAME: NULL SUBPARTITION_NAME: NULL INDEX_NAME: PRIMARY OBJECT_INSTANCE_BEGIN: 140439793474104 LOCK_TYPE: RECORD LOCK_MODE: X LOCK_STATUS: GRANTED LOCK_DATA: 2 4 rows in set (0.00 sec)
從上面的查詢數據可以看到，performance_schema.data_locks表中新增了線程ID為55的兩個鎖記錄，IX鎖狀態為GRANTED，X鎖狀態為WAITING，說明正在等待被授予。但這里并不能很直觀地查看到鎖等待關系，我們可以使用sys.innodb_lock_waits視圖查看。
root@localhost : (none) 09:44:52> select * from sys.innodb_lock_waits\G; *************************** 1. row *************************** wait_started: 2018-01-14 21:51:59 wait_age: 00:00:11 wait_age_secs: 11 locked_table: `xiaoboluo`.`t_luoxiaobo` locked_table_schema: xiaoboluo locked_table_name: t_luoxiaobo locked_table_partition: NULL locked_table_subpartition: NULL locked_index: PRIMARY locked_type: RECORD waiting_trx_id: 55566 waiting_trx_started: 2018-01-14 21:51:59 waiting_trx_age: 00:00:11 waiting_trx_rows_locked: 1 waiting_trx_rows_modified: 0 waiting_pid: 8 waiting_query: update t_luoxiaobo set datet_time=now() where id=2 waiting_lock_id: 55566:2:4:2 waiting_lock_mode: X blocking_trx_id: 55562 blocking_pid: 7 blocking_query: NULL blocking_lock_id: 55562:2:4:2 blocking_lock_mode: X blocking_trx_started: 2018-01-14 21:34:44 blocking_trx_age: 00:17:26 blocking_trx_rows_locked: 1 blocking_trx_rows_modified: 1 sql_kill_blocking_query: KILL QUERY 7 sql_kill_blocking_connection: KILL 7 1 row in set (0.02 sec)
PS：在MySQL 5.7版本中，也可以使用sys.innodb_lock_waits視圖查詢，但是在8.0中，該視圖聯結查詢的表不同(把之前版本中使用的information_schema.innodb_locks和information_schema.innodb_lock_waits表替換為了performance_schema.data_locks和performance_schema.data_lock_waits表)，另外，在MySQL 5.6及其之前的版本中默認情況下并沒有sys庫，我們可以使用如下語句代替：
SELECT r.trx_wait_started AS wait_started,
TIMEDIFF(NOW(), r.trx_wait_started) AS wait_age,
TIMESTAMPDIFF(SECOND, r.trx_wait_started, NOW()) AS wait_age_secs,
rl.lock_table AS locked_table,
rl.lock_index AS locked_index,
rl.lock_type AS locked_type,
r.trx_id AS waiting_trx_id,
r.trx_started as waiting_trx_started,
TIMEDIFF(NOW(), r.trx_started) AS waiting_trx_age,
r.trx_rows_locked AS waiting_trx_rows_locked,
r.trx_rows_modified AS waiting_trx_rows_modified,
r.trx_mysql_thread_id AS waiting_pid,
sys.format_statement(r.trx_query) AS waiting_query,
rl.lock_id AS waiting_lock_id,
rl.lock_mode AS waiting_lock_mode,
b.trx_id AS blocking_trx_id,
b.trx_mysql_thread_id AS blocking_pid,
sys.format_statement(b.trx_query) AS blocking_query,
bl.lock_id AS blocking_lock_id,
bl.lock_mode AS blocking_lock_mode,
b.trx_started AS blocking_trx_started,
TIMEDIFF(NOW(), b.trx_started) AS blocking_trx_age,
b.trx_rows_locked AS blocking_trx_rows_locked,
b.trx_rows_modified AS blocking_trx_rows_modified,
CONCAT('KILL QUERY ', b.trx_mysql_thread_id) AS sql_kill_blocking_query,
CONCAT('KILL ', b.trx_mysql_thread_id) AS sql_kill_blocking_connection
FROM information_schema.innodb_lock_waits w
INNER JOIN information_schema.innodb_trx b ON b.trx_id = w.blocking_trx_id
INNER JOIN information_schema.innodb_trx r ON r.trx_id = w.requesting_trx_id
INNER JOIN information_schema.innodb_locks bl ON bl.lock_id = w.blocking_lock_id
INNER JOIN information_schema.innodb_locks rl ON rl.lock_id = w.requested_lock_id
ORDER BY r.trx_wait_started;
使用performance_schema中的語句當前事件記錄表和語句事件歷史記錄表可以查詢數據庫中最近執行的一些SQL語句，以及語句相關的信息，這里我們以events_statements_history表為例，查詢結果按照語句完成時間倒序排序，如下：
root@localhost : performance_schema 04:33:33> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT),sys.format_time(LOCK_TIME),SQL_TEXT,CURRENT_SCHEMA,MESSAGE_TEXT,ROWS_AFFECTED,ROWS_SENT,ROWS_EXAMINED from events_statements_history where CURRENT_SCHEMA!='performance_schema' order by TIMER_WAIT desc limit 10\G; *************************** 1. row *************************** THREAD_ID: 114 EVENT_NAME: statement/sql/update SOURCE: socket_connection.cc:101 sys.format_time(TIMER_WAIT): 24.93 m sys.format_time(LOCK_TIME): 24.93 m SQL_TEXT: update sbtest1 set pad='xxx' where id=1 CURRENT_SCHEMA: sbtest MESSAGE_TEXT: Rows matched: 0 Changed: 0 Warnings: 0 ROWS_AFFECTED: 0 ROWS_SENT: 0 ROWS_EXAMINED: 0 *************************** 2. row *************************** THREAD_ID: 114 EVENT_NAME: statement/sql/update SOURCE: socket_connection.cc:101 sys.format_time(TIMER_WAIT): 7.84 m sys.format_time(LOCK_TIME): 7.84 m SQL_TEXT: update sbtest1 set pad='xxx' where id=1 CURRENT_SCHEMA: sbtest MESSAGE_TEXT: Rows matched: 0 Changed: 0 Warnings: 0 ROWS_AFFECTED: 0 ROWS_SENT: 0 ROWS_EXAMINED: 0 ...... 10 rows in set (0.00 sec)
按照我們通常優化慢SQL的原則，優先優化執行次數最多的，然后是執行時間最長的，以上的查詢結果并不是我們通常說的top sql，我們可以使用events_statements_summary_by_digest表來查詢經過統計之后的top sql。
root@localhost : performance_schema 05:04:41> select SCHEMA_NAME,DIGEST_TEXT,COUNT_STAR,sys.format_time(SUM_TIMER_WAIT) as sum_time,sys.format_time(MIN_TIMER_WAIT) as min_time,sys.format_time(AVG_TIMER_WAIT) as avg_time,sys.format_time(MAX_TIMER_WAIT) as max_time,sys.format_time(SUM_LOCK_TIME) as sum_lock_time,SUM_ROWS_AFFECTED,SUM_ROWS_SENT,SUM_ROWS_EXAMINED from events_statements_summary_by_digest where SCHEMA_NAME is not null order by COUNT_STAR desc limit 10\G *************************** 1. row *************************** SCHEMA_NAME: sbtest DIGEST_TEXT: UPDATE `sbtest1` SET `pad` = ? WHERE `id` = ? COUNT_STAR: 10 sum_time: 2.19 h min_time: 216.90 us avg_time: 13.15 m max_time: 1.50 h sum_lock_time: 2.04 h SUM_ROWS_AFFECTED: 3 SUM_ROWS_SENT: 0 SUM_ROWS_EXAMINED: 4 *************************** 2. row *************************** SCHEMA_NAME: sbtest DIGEST_TEXT: SHOW WARNINGS COUNT_STAR: 9 sum_time: 397.62 us min_time: 16.50 us avg_time: 44.18 us max_time: 122.58 us sum_lock_time: 0 ps SUM_ROWS_AFFECTED: 0 SUM_ROWS_SENT: 0 SUM_ROWS_EXAMINED: 0 ...... *************************** 5. row *************************** SCHEMA_NAME: sbtest DIGEST_TEXT: SELECT * FROM `sbtest1` LIMIT ? COUNT_STAR: 5 sum_time: 138.93 ms min_time: 145.77 us avg_time: 27.79 ms max_time: 112.29 ms sum_lock_time: 95.53 ms SUM_ROWS_AFFECTED: 0 SUM_ROWS_SENT: 104 SUM_ROWS_EXAMINED: 104 ...... 10 rows in set (0.00 sec)
PS： events_statements_summary_by_digest 表中記錄的SQL語句文本并不完整，默認情況下只截取了1024個字節，且也是使用這1024個字節的SQL文本進行hash計算，把hashcode相同的累計計算在一起，performance_schema提供的數據只能算作慢日志分析的一個補充，如果需要完整的SQL語句文本還得依賴慢查詢日志分析
曾經有同事問，代碼對數據庫的某些操作(比如：python的ORM模塊操作數據庫)報了語法錯誤，但是代碼并沒有記錄SQL語句文本的功能，問在MySQL數據庫層能否查看到具體的SQL文本，看看是否有哪里寫錯了。這個時候，大多數人首先想到的就是去查看錯誤日志。很遺憾，對于SQL語句的語法錯誤，錯誤日志并不會記錄。如果你沒有完全了解performance_schema，那么你很可能就會給同事回復說：MySQL層面也并沒有記錄語法錯誤的信息
實際上，performance_schema的語句事件記錄表中針對每一個語句的執行狀態都記錄了較為詳細的信息，例如：events_statements_ 表和events_statements_summary_by_digest表(events_statements_ 表記錄的語句所有的執行錯誤信息，但events_statements_summary_by_digest表只記錄了語句在執行過程中發生的錯誤的語句記錄統計，具體的錯誤類型不記錄，例如：語法錯誤類的不記錄)，下面我們分別演示如何使用這兩個表查詢語句發生錯誤的語句信息
首先，我們模擬一個語法錯誤的SQL，使用events_statements_history_long或者events_statements_history表查詢發生語法錯誤的SQL語句，開啟一個會話(會話1)
root@localhost : performance_schema 05:18:09> select * from; ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '' at line 1
然后，我們查詢events_statements_history_long表中錯誤號為1064的記錄，開啟另一個會話（會話2）
root@localhost : sbtest 05:32:55> use performance_schema Database changed root@localhost : performance_schema 05:33:03> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,sys.format_time(LOCK_TIME) as lock_time,SQL_TEXT,CURRENT_SCHEMA,MESSAGE_TEXT,ROWS_AFFECTED,ROWS_SENT,ROWS_EXAMINED,MYSQL_ERRNO from events_statements_history where MYSQL_ERRNO=1064\G; *************************** 1. row *************************** THREAD_ID: 119 EVENT_NAME: statement/sql/error SOURCE: socket_connection.cc:101 exec_time: 71.72 us lock_time: 0 ps SQL_TEXT: select * from CURRENT_SCHEMA: sbtest MESSAGE_TEXT: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use ROWS_AFFECTED: 0 ROWS_SENT: 0 ROWS_EXAMINED: 0 MYSQL_ERRNO: 1064 1 row in set (0.01 sec)
可能你不知道錯誤號是多少，可以查詢發生錯誤次數不為0的語句記錄，在里邊找到MESSAGE_TEXT字段提示信息為語法錯誤的就是它了。
root@localhost : performance_schema 05:34:00> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,sys.format_time(LOCK_TIME) as lock_time,SQL_TEXT,CURRENT_SCHEMA,MESSAGE_TEXT,ROWS_AFFECTED,ROWS_SENT,ROWS_EXAMINED,MYSQL_ERRNO,errors from events_statements_history where errors>0\G; *************************** 1. row *************************** THREAD_ID: 119 EVENT_NAME: statement/sql/error SOURCE: socket_connection.cc:101 exec_time: 71.72 us lock_time: 0 ps SQL_TEXT: select * from CURRENT_SCHEMA: sbtest MESSAGE_TEXT: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use ROWS_AFFECTED: 0 ROWS_SENT: 0 ROWS_EXAMINED: 0 MYSQL_ERRNO: 1064 errors: 1 1 row in set (0.00 sec)
使用events_statements_summary_by_digest表查詢發生語句執行錯誤的SQL語句記錄，首先，我們在會話1制造一兩個語句執行一定會發生錯誤的語句。
root@localhost : sbtest 05:32:34> select * ; ERROR 1096 (HY000): No tables used root@localhost : sbtest 05:40:57> select * from sbtest4 where id between 100 and 2000 and xx=1; ERROR 1054 (42S22): Unknown column 'xx' in 'where clause'
然后，我們在events_statements_summary_by_digest表中查詢發生錯誤次數大于0的記錄，在會話2執行。
root@localhost : performance_schema 05:34:03> select SCHEMA_NAME,DIGEST_TEXT,COUNT_STAR,sys.format_time(AVG_TIMER_WAIT) as avg_time,sys.format_time(MAX_TIMER_WAIT) as max_time,sys.format_time(SUM_LOCK_TIME) as sum_lock_time,SUM_ERRORS,FIRST_SEEN,LAST_SEEN from events_statements_summary_by_digest where SUM_ERRORS!=0\G; *************************** 1. row *************************** ...... *************************** 10. row *************************** SCHEMA_NAME: sbtest DIGEST_TEXT: SELECT * # 這里就是第一個執行錯誤的語句 COUNT_STAR: 1 avg_time: 55.14 us max_time: 55.14 us sum_lock_time: 0 ps SUM_ERRORS: 1 FIRST_SEEN: 2018-06-25 17:40:57 LAST_SEEN: 2018-06-25 17:40:57 *************************** 11. row *************************** SCHEMA_NAME: sbtest DIGEST_TEXT: SELECT * FROM `sbtest4` WHERE `id` BETWEEN ? AND ? AND `xx` = ? # 這里就是第二個執行錯誤的語句 COUNT_STAR: 1 avg_time: 101.68 us max_time: 101.68 us sum_lock_time: 0 ps SUM_ERRORS: 1 FIRST_SEEN: 2018-06-25 17:41:03 LAST_SEEN: 2018-06-25 17:41:03 11 rows in set (0.00 sec)
PS：我們前面說過，events_statements_summary_by_digest表中不記錄具體的錯誤信息，只做錯誤語句統計，所以，如果需要查詢到具體的錯誤信息（如：具體的錯誤代碼，具體的錯誤提示信息以及具體的錯誤SQL文本等），還需要查詢events_statements_history或者events_statements_history_long表。
root@localhost : performance_schema 05:45:03> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,sys.format_time(LOCK_TIME) as lock_time,SQL_TEXT,CURRENT_SCHEMA,MESSAGE_TEXT,ROWS_AFFECTED,ROWS_SENT,ROWS_EXAMINED,MYSQL_ERRNO from events_statements_history where MYSQL_ERRNO!=0\G; *************************** 1. row *************************** ...... *************************** 2. row *************************** THREAD_ID: 119 EVENT_NAME: statement/sql/select SOURCE: socket_connection.cc:101 exec_time: 55.14 us lock_time: 0 ps SQL_TEXT: select * CURRENT_SCHEMA: sbtest MESSAGE_TEXT: No tables used ROWS_AFFECTED: 0 ROWS_SENT: 0 ROWS_EXAMINED: 0 MYSQL_ERRNO: 1096 *************************** 3. row *************************** THREAD_ID: 119 EVENT_NAME: statement/sql/select SOURCE: socket_connection.cc:101 exec_time: 101.68 us lock_time: 0 ps SQL_TEXT: select * from sbtest4 where id between 100 and 2000 and xx=1 CURRENT_SCHEMA: sbtest MESSAGE_TEXT: Unknown column 'xx' in 'where clause' ROWS_AFFECTED: 0 ROWS_SENT: 0 ROWS_EXAMINED: 0 MYSQL_ERRNO: 1054 3 rows in set (0.00 sec)
MariaDB分支支持一個不依賴于performance_schema性能數據的進度展示功能，我們通過show processlist語句返回結果的最后一列就是進度信息。
root@localhost Sun Jan 14 14:08:29 2018 14:08:29 [(none)]>show processlist; +----+------+-----------+-----------+---------+------+----------------+-------------------------------------------------+----------+ | Id | User | Host | db | Command | Time | State | Info | Progress | +----+------+-----------+-----------+---------+------+----------------+-------------------------------------------------+----------+ | 4 | root | localhost | employees | Query | 6 | altering table | alter table salaries add index i_salary(salary) | 93.939 | | 5 | root | localhost | NULL | Query | 0 | init | show processlist | 0.000 | +----+------+-----------+-----------+---------+------+----------------+-------------------------------------------------+----------+ 2 rows in set (0.00 sec)
在MySQL中也提供了類似的功能，通過階段事件中具有可預估工作量的階段事件進行記錄與計算，就可以得到一個語句的執行的階段信息和進度信息，下面我們分別舉例介紹如何查看
首先， 我們需要進行配置啟用，階段事件默認并未啟用，開啟一個會話（會話1）
root@localhost : performance_schema 05:59:26> use performance_schema Database changed root@localhost : performance_schema 05:59:45> update setup_instruments set enabled='yes',timed='yes' where name like 'stage/%'; Query OK, 120 rows affected (0.00 sec) Rows matched: 129 Changed: 120 Warnings: 0 root@localhost : performance_schema 05:59:47> update setup_consumers set enabled='yes' where name like '%stage%'; Query OK, 3 rows affected (0.00 sec) Rows matched: 3 Changed: 3 Warnings: 0
開啟第二個會話（會話2），查詢thread_id
root@localhost : sbtest 06:02:22> select sys.ps_thread_id(connection_id()); +-----------------------------------+ | sys.ps_thread_id(connection_id()) | +-----------------------------------+ | 119 | +-----------------------------------+ 1 row in set (0.00 sec)
先對之前舊的信息進行清理，避免干擾（會話1）
# 先關閉其他線程的事件記錄功能，使用前面步驟查詢到的thread_id root@localhost : performance_schema 06:05:38> update performance_schema.threads set INSTRUMENTED='NO' where THREAD_ID!=119; Query OK, 101 rows affected (0.00 sec) Rows matched: 101 Changed: 101 Warnings: 0 # 清空階段事件的3張表 root@localhost : performance_schema 05:59:52> truncate events_stages_current;truncate events_stages_history;truncate events_stages_history_long; Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.02 sec)
現在，回到會話2執行DML語句
root@localhost : sbtest 06:06:37> select count(*) from sbtest.sbtest4 where id between 100 and 200; +----------+ | count(*) | +----------+ | 50 | +----------+ 1 row in set (0.00 sec)
在會話1中查詢events_stages_history_long表
root@localhost : performance_schema 06:10:37> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,WORK_COMPLETED,WORK_ESTIMATED from events_stages_history_long; +-----------+--------------------------------+--------------------------+-----------+----------------+----------------+ | THREAD_ID | EVENT_NAME | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED | +-----------+--------------------------------+--------------------------+-----------+----------------+----------------+ | 119 | stage/sql/starting | socket_connection.cc:107 | 54.19 us | NULL | NULL | | 119 | stage/sql/checking permissions | sql_authorization.cc:810 | 3.62 us | NULL | NULL | | 119 | stage/sql/Opening tables | sql_base.cc:5650 | 10.54 us | NULL | NULL | | 119 | stage/sql/init | sql_select.cc:121 | 16.73 us | NULL | NULL | | 119 | stage/sql/System lock | lock.cc:323 | 4.77 us | NULL | NULL | | 119 | stage/sql/optimizing | sql_optimizer.cc:151 | 4.78 us | NULL | NULL | | 119 | stage/sql/statistics | sql_optimizer.cc:367 | 50.54 us | NULL | NULL | | 119 | stage/sql/preparing | sql_optimizer.cc:475 | 7.79 us | NULL | NULL | | 119 | stage/sql/executing | sql_executor.cc:119 | 381.00 ns | NULL | NULL | | 119 | stage/sql/Sending data | sql_executor.cc:195 | 36.75 us | NULL | NULL | | 119 | stage/sql/end | sql_select.cc:199 | 931.00 ns | NULL | NULL | | 119 | stage/sql/query end | sql_parse.cc:4968 | 5.31 us | NULL | NULL | | 119 | stage/sql/closing tables | sql_parse.cc:5020 | 2.26 us | NULL | NULL | | 119 | stage/sql/freeing items | sql_parse.cc:5596 | 8.71 us | NULL | NULL | | 119 | stage/sql/cleaning up | sql_parse.cc:1902 | 449.00 ns | NULL | NULL | +-----------+--------------------------------+--------------------------+-----------+----------------+----------------+ 15 rows in set (0.01 sec)
通過以上的查詢數據可以清晰地看到一個select語句的執行全過程，以及每一個過程的時間開銷等信息，那DDL語句的執行階段又是怎樣的呢？
先對之前舊的信息進行清理，避免干擾（會話1）
root@localhost : performance_schema 06:10:48> truncate events_stages_current;truncate events_stages_history;truncate events_stages_history_long; Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.02 sec)
然后，執行DDL語句(會話2)
root@localhost : sbtest 03:37:32> alter table sbtest1 add index i_c(c);
此時，在會話1中查詢階段事件信息(此時DDL語句并未執行完成，從最后一行記錄信息中可以看到，WORK_COMPLETED 和WORK_ESTIMATED 列值不為NULL，表示該階段事件是一個可以度量的事件)
root@localhost : performance_schema 06:30:04> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,WORK_COMPLETED,WORK_ESTIMATED from events_stages_history_long; +-----------+------------------------------------------------------+--------------------------+-----------+----------------+----------------+ | THREAD_ID | EVENT_NAME | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED | +-----------+------------------------------------------------------+--------------------------+-----------+----------------+----------------+ | 119 | stage/sql/starting | socket_connection.cc:107 | 44.17 us | NULL | NULL | | 119 | stage/sql/checking permissions | sql_authorization.cc:810 | 1.46 us | NULL | NULL | | 119 | stage/sql/checking permissions | sql_authorization.cc:810 | 2.29 us | NULL | NULL | | 119 | stage/sql/init | sql_table.cc:9031 | 2.16 us | NULL | NULL | | 119 | stage/sql/Opening tables | sql_base.cc:5650 | 107.57 us | NULL | NULL | | 119 | stage/sql/setup | sql_table.cc:9271 | 19.19 us | NULL | NULL | | 119 | stage/sql/creating table | sql_table.cc:5222 | 1.06 ms | NULL | NULL | | 119 | stage/sql/After create | sql_table.cc:5355 | 76.22 us | NULL | NULL | | 119 | stage/sql/System lock | lock.cc:323 | 4.38 us | NULL | NULL | | 119 | stage/sql/preparing for alter table | sql_table.cc:7454 | 28.63 ms | NULL | NULL | | 119 | stage/sql/altering table | sql_table.cc:7508 | 3.91 us | NULL | NULL | | 119 | stage/innodb/alter table (read PK and internal sort) | ut0stage.h:241 | 27.09 s | 230040 | 470155 | +-----------+------------------------------------------------------+--------------------------+-----------+----------------+----------------+ 12 rows in set (0.01 sec)
待到DDL語句執行完成之后，我們再次查看階段事件信息（會話1）
root@localhost : performance_schema 06:31:07> select THREAD_ID,EVENT_NAME,SOURCE,sys.format_time(TIMER_WAIT) as exec_time,WORK_COMPLETED,WORK_ESTIMATED from events_stages_history_long; +-----------+------------------------------------------------------+--------------------------+-----------+----------------+----------------+ | THREAD_ID | EVENT_NAME | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED | +-----------+------------------------------------------------------+--------------------------+-----------+----------------+----------------+ ...... | 119 | stage/innodb/alter table (read PK and internal sort) | ut0stage.h:241 | 27.09 s | 230040 | 470155 | | 119 | stage/innodb/alter table (merge sort) | ut0stage.h:501 | 1.15 m | 345060 | 512319 | | 119 | stage/innodb/alter table (insert) | ut0stage.h:501 | 11.83 s | 460146 | 523733 | | 119 | stage/innodb/alter table (flush) | ut0stage.h:501 | 18.35 s | 523658 | 523733 | | 119 | stage/innodb/alter table (log apply index) | ut0stage.h:501 | 54.63 ms | 524042 | 524042 | | 119 | stage/innodb/alter table (flush) | ut0stage.h:501 | 21.18 us | 524042 | 524042 | | 119 | stage/sql/committing alter table to storage engine | sql_table.cc:7535 | 5.12 us | NULL | NULL | | 119 | stage/innodb/alter table (end) | ut0stage.h:501 | 233.52 ms | 524042 | 524042 | ...... +-----------+------------------------------------------------------+--------------------------+-----------+----------------+----------------+ 24 rows in set (0.01 sec)
通過以上的查詢數據可以清晰地看到一個alter語句添加索引的執行全過程，以及每一個過程的時間開銷等信息，執行時間最長的是stage/innodb/alter table (merge sort)，其次是stage/innodb/alter table (read PK and internal sort)，說明在本示例中創建索引主要的時間開銷在于內部的數據排序和排序合并操作
PS：階段事件長歷史記錄表中的數據產生較快，默認的10000行配額可能很快就被打滿了，可在配置文件中把配額調整為一個較大值，以便完整查看DDL語句執行階段(例如：performance_schema_events_stages_history_long_size=1000000，同時要注意關掉其他不相干的任務)
在官方MySQL 版本中，performance_schema下并沒有很直觀地查詢整個語句執行進度的方法，但是可以借助后續章節中介紹的sys.session視圖進行查看。
root@localhost : performance_schema 04:16:38> select * from sys.session where conn_id!=connection_id()\G; *************************** 1. row *************************** thd_id: 45 conn_id: 4 ...... state: alter table (merge sort) time: 30 current_statement: alter table sbtest1 add index i_c(c) statement_latency: 29.42 s progress: 46.40 # 進度百分比在這里 lock_latency: 2.19 ms rows_examined: 0 rows_sent: 0 rows_affected: 0 tmp_tables: 0 tmp_disk_tables: 0 full_scan: NO ...... program_name: mysql 1 row in set (0.33 sec)
雖然，我們可以通過慢查詢日志查詢到一個語句的執行總時長，但，如果數據庫中存在著一些大事務執行過程中回滾了，或者說執行過程中異常終止，這個時候慢查詢日志就愛莫能助了，這個時候我們可以借助performance_schema的events_transactions_*表進行查看事務相關的記錄，這些表中詳細記錄了是否有事務被回滾、活躍(長事件未提交的事務也屬于活躍事件)或已提交等，下面我們分別模擬幾種事務情況，并查看事務事件記錄表。
首先，我們需要進行配置啟用，事務事件默認并未啟用（會話1）。
root@localhost : performance_schema 04:16:59> update setup_instruments set enabled='yes',timed='yes' where name like 'transaction'; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 root@localhost : performance_schema 04:23:12> update setup_consumers set enabled='yes' where name like '%transaction%'; Query OK, 3 rows affected (0.00 sec) Rows matched: 3 Changed: 3 Warnings: 0
執行清理，避免其他事務干擾（會話1）
root@localhost : performance_schema 04:30:25> truncate events_transactions_current;truncate events_transactions_history;truncate events_transactions_history_long; Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec) Query OK, 0 rows affected (0.00 sec)
然后，開啟一個新會話（會話2）用于執行事務，并模擬事務回滾
root@localhost : sbtest 04:18:34> use sbtest Database changed root@localhost : sbtest 04:24:27> begin; Query OK, 0 rows affected (0.00 sec) root@localhost : sbtest 04:25:02> update sbtest1 set pad='yyy' where id=1; Query OK, 1 row affected (0.01 sec) Rows matched: 1 Changed: 1 Warnings: 0
會話1查詢活躍事務，活躍事務表示當前正在執行的事務事件，需要從events_transactions_current表查詢。
root@localhost : performance_schema 04:33:44> select THREAD_ID,EVENT_NAME,STATE,TRX_ID,GTID,SOURCE,TIMER_WAIT,ACCESS_MODE,ISOLATION_LEVEL,AUTOCOMMIT,NESTING_EVENT_ID,NESTING_EVENT_TYPE from events_transactions_current\G; *************************** 1. row *************************** THREAD_ID: 47 EVENT_NAME: transaction STATE: ACTIVE TRX_ID: NULL GTID: AUTOMATIC SOURCE: transaction.cc:209 TIMER_WAIT: 21582764879000 ACCESS_MODE: READ WRITE ISOLATION_LEVEL: READ COMMITTED AUTOCOMMIT: NO NESTING_EVENT_ID: 30 NESTING_EVENT_TYPE: STATEMENT 1 row in set (0.00 sec)
會話2，回滾事務，被回滾完成的事務不再活躍
root@localhost : sbtest 04:25:08> rollback; Query OK, 0 rows affected (0.01 sec)
會話1，查詢事務事件歷史記錄表events_transactions_history_long
root@localhost : performance_schema 04:27:34> select THREAD_ID,EVENT_NAME,STATE,TRX_ID,GTID,SOURCE,TIMER_WAIT,ACCESS_MODE,ISOLATION_LEVEL,AUTOCOMMIT,NESTING_EVENT_ID,NESTING_EVENT_TYPE from events_transactions_history_long\G; *************************** 1. row *************************** THREAD_ID: 45 EVENT_NAME: transaction STATE: ROLLED BACK TRX_ID: NULL GTID: AUTOMATIC SOURCE: transaction.cc:209 TIMER_WAIT: 39922043951000 ACCESS_MODE: READ WRITE ISOLATION_LEVEL: READ COMMITTED AUTOCOMMIT: NO NESTING_EVENT_ID: 194 NESTING_EVENT_TYPE: STATEMENT 1 row in set (0.00 sec)
可以看到在事務事件表中記錄了一行事務事件信息，線程ID為45的線程執行了一個事務，事務狀態為ROLLED BACK，現在，我們來模擬事務正常提交。
# 會話2 root@localhost : sbtest 04:40:27> begin; Query OK, 0 rows affected (0.00 sec) root@localhost : sbtest 04:40:29> update sbtest1 set pad='yyy' where id=1; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 root@localhost : sbtest 04:40:31> commit; Query OK, 0 rows affected (0.01 sec) # 會話1 root@localhost : performance_schema 04:38:32> select THREAD_ID,EVENT_NAME,STATE,TRX_ID,GTID,SOURCE,TIMER_WAIT,ACCESS_MODE,ISOLATION_LEVEL,AUTOCOMMIT,NESTING_EVENT_ID,NESTING_EVENT_TYPE from events_transactions_current\G; *************************** 1. row *************************** THREAD_ID: 44 EVENT_NAME: transaction STATE: COMMITTED TRX_ID: 421759004106352 GTID: AUTOMATIC SOURCE: handler.cc:1421 TIMER_WAIT: 87595486000 ACCESS_MODE: READ WRITE ISOLATION_LEVEL: READ COMMITTED AUTOCOMMIT: YES NESTING_EVENT_ID: 24003703 NESTING_EVENT_TYPE: STATEMENT *************************** 2. row *************************** THREAD_ID: 47 EVENT_NAME: transaction STATE: COMMITTED TRX_ID: NULL GTID: ec123678-5e26-11e7-9d38-000c295e08a0:181879 SOURCE: transaction.cc:209 TIMER_WAIT: 7247256746000 ACCESS_MODE: READ WRITE ISOLATION_LEVEL: READ COMMITTED AUTOCOMMIT: NO NESTING_EVENT_ID: 55 NESTING_EVENT_TYPE: STATEMENT 2 rows in set (0.00 sec)
從上面的查詢數據可以看到，第二行事務事件記錄中的事務事件為COMMITTED狀態，表示事務已經提交成功
PS：如果一個事務長時間未提交(長事件處于ACTIVE狀態)，這種情況雖然我們從events_transactions_current表中可以查詢到未提交事務事件信息，但是并不能很直觀地看到事務是什么時間點開始的，我們可以借助于information_schema.innodb_trx表來進行輔助判斷。
root@localhost : performance_schema 04:57:50> select * from information_schema.innodb_trx\G; *************************** 1. row *************************** trx_id: 2454336 trx_state: RUNNING trx_started: 2018-01-14 16:43:29 trx_requested_lock_id: NULL trx_wait_started: NULL trx_weight: 3 trx_mysql_thread_id: 6 ...... 1 row in set (0.00 sec)
官方MySQL 從5.6版本開始支持基于庫級別的并行復制，在MySQL 5.7版本中支持基于事務的并行復制，在我們啟用了并行復制之后，如果一旦發生復制報錯，通常通過show slave status語句無法查看到具體的報錯詳情(show slave status語句只能查看到SQL線程的報錯信息，而在多線程復制下，SQL線程的報錯信息是根據worker線程的報錯信息的一個匯總信息)，類似如下：
admin@localhost : (none) 12:45:19> show slave status\G; ............ Last_Errno: 1062 Last_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction '23fb5832-e4bc-11e7-8ea4-525400a4b2e1:2553990' at master log mysql-bin.000034, end_log_pos 98797. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any. ............ Last_SQL_Errno: 1062 Last_SQL_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction '23fb5832-e4bc-11e7-8ea4-525400a4b2e1:2553990' at master log mysql-bin.000034, end_log_pos 98797. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any. ............ 1 row in set (0.00 sec)
根據報錯提示查看performance_schema.replication_applier_status_by_worker表，該表中詳細記錄了每一個worker線程的詳細信息，從這里我們就可以找到發生報錯的worker線程具體的報錯原因。
admin@localhost : (none) 12:51:53> select * from performance_schema.replication_applier_status_by_worker where LAST_ERROR_MESSAGE!=''\G; *************************** 1. row *************************** CHANNEL_NAME: WORKER_ID: 2 THREAD_ID: NULL SERVICE_STATE: OFF LAST_SEEN_TRANSACTION: 23fb5832-e4bc-11e7-8ea4-525400a4b2e1:2553991 LAST_ERROR_NUMBER: 1062 LAST_ERROR_MESSAGE: Worker 2 failed executing transaction '23fb5832-e4bc-11e7-8ea4-525400a4b2e1:2553991' at master log mysql-bin.000034, end_log_pos 99514; Could not execute Write_rows event on table sbtest.sbtest4; Duplicate entry '833353' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 99514 LAST_ERROR_TIMESTAMP: 2018-01-02 14:08:58 1 row in set (0.00 sec)
從查詢performance_schema.replication_applier_status_by_worker表可以發現，具體的復制報錯信息是因為主鍵沖突了
PS：由于歷史原因，performance_schema中的復制信息記錄表只記錄跟GTID相關的信息，而在mysql系統字典庫下的slave_master_info、slave_relay_log_info、slave_worker_info表記錄的是跟binlog position相關的信息。另外，如果選擇相關的復制信息記錄到文件，那么磁盤上還存在著master.info、relay_log.info等文件記錄binlog position相關的信息。
羅小波·沃趣科技高級數據庫技術專家
IT從業多年，歷任運維工程師，高級運維工程師，運維經理，數據庫工程師，曾參與版本發布系統，輕量級監控系統，運維管理平臺，數據庫管理平臺的設計與編寫，熟悉MySQL的體系結構時，InnoDB存儲引擎，喜好專研開源技術，追求完美。
免責聲明：本站發布的內容（圖片、視頻和文字）以原創、轉載和分享為主，文章觀點不代表本網站立場，如果涉及侵權請聯系站長郵箱：is@yisu.com進行舉報，并提供相關證據，一經查實，將立刻刪除涉嫌侵權內容。
