MySQL Performance-Schema(三) 實踐篇

     前一篇文章咱們分析了Performance-Schema中每一個表的用途，以及主要字段的含義，比較側重於理論的介紹。這篇文章我主要從DBA的角度出發，詳細介紹如何經過Performance-Schema獲得DBA關心的數據，好比哪一個SQL執行次數最多，哪一個表訪問最頻繁，哪一個鎖最熱等信息。經過充分利用Performance-Schema表的數據，讓DBA更瞭解DB的運行狀態，也更有助於排查定位問題。本文主要從兩方面展開討論，第一方面是統計信息維度，包括SQL維度，對象維度和等待事件維度三小點；第二方面是定位分析問題維度，結合實際應用場景，利用Performance-Schema蒐集的數據進行分析。

統計信息(SQL維度)
     關於SQL維度的統計信息主要集中在events_statements_summary_by_digest表中，經過將SQL語句抽象出digest，能夠統計某類SQL語句在各個維度的統計信息(好比：執行次數，排序次數，使用臨時表等)
(1).哪類SQL執行最多？

SELECT
DIGEST_TEXT,
COUNT_STAR,
FIRST_SEEN,
LAST_SEEN
FROM events_statements_summary_by_digest
ORDER BY COUNT_STAR DESC limit 1\G
*************************** 1. row ***************************
DIGEST_TEXT: SELECT `pay_order_id` , `total_fee` , `pay_seller_id` , `pay_buyer_id` , `buyer_id` , `seller_id` FROM `pay_order` WHERE `pay_order_id` = ? 
COUNT_STAR: 5282893
FIRST_SEEN: 2015-12-15 18:25:38
LAST_SEEN: 2015-12-18 16:20:59

能夠看到執行次數最多的SQL是「SELECT `pay_order_id` , `total_fee` , `pay_seller_id` , pay_buyer_id , buyer_id , seller_id FROM tc_pay_order WHERE pay_order_id = ?」，FIRST_SEEN和LAST_SEEN分別顯示了語句第一次執行和最後一次執行的時間點。
(2).哪類SQL的平均響應時間最多？
AVG_TIMER_WAIT
(3).哪類SQL排序記錄數最多？
SUM_SORT_ROWS
(4).哪類SQL掃描記錄數最多？
SUM_ROWS_EXAMINED
(5).哪類SQL使用臨時表最多？
SUM_CREATED_TMP_TABLES,SUM_CREATED_TMP_DISK_TABLES
(6).哪類SQL返回結果集最多？
SUM_ROWS_SENT
     經過上述指標咱們能夠間接得到某類SQL的邏輯IO(SUM_ROWS_EXAMINED)，CPU消耗(SUM_SORT_ROWS)，網絡帶寬(SUM_ROWS_SENT)的對比，但還沒法獲得某類SQL的物理IO消耗，以及某類SQL訪問數據的buffer命中率。

統計信息(對象維度)
(1).哪一個表物理IO最多？

SELECT
file_name,
event_name,
SUM_NUMBER_OF_BYTES_READ,
SUM_NUMBER_OF_BYTES_WRITE
FROM file_summary_by_instance
ORDER BY SUM_NUMBER_OF_BYTES_READ + SUM_NUMBER_OF_BYTES_WRITE DESC LIMIT 1\G
*************************** 1. row ***************************
file_name: /u01/my3306/data/chuck/test_01.ibd
event_name: wait/io/file/innodb/innodb_data_file
SUM_NUMBER_OF_BYTES_READ: 2168078336
SUM_NUMBER_OF_BYTES_WRITE: 1390761934848

經過file_summary_by_instance表，能夠得到系統運行到如今，哪一個文件(表)物理IO最多，這可能意味着這個表常常須要訪問磁盤IO，從結果來看chuck庫裏面的test_01的數據文件訪問最多。

(2).哪一個表邏輯IO最多?

SELECT
object_name,
COUNT_READ,
COUNT_WRITE,
COUNT_FETCH,
SUM_TIMER_WAIT
FROM table_io_waits_summary_by_table
ORDER BY sum_timer_wait DESC limit 1\G
*************************** 1. row ***************************
object_name: test_slow
COUNT_READ: 1986130
COUNT_WRITE: 393222
COUNT_FETCH: 1986130
SUM_TIMER_WAIT: 925309746633072

經過table_io_waits_summary_by_table表，能夠得到系統運行到如今，哪一個表邏輯IO最多，亦即最「熱」的表，從結果來看chuck庫裏面的test_slow表訪問次數最多。

(3).哪一個索引訪問最多？

SELECT
OBJECT_NAME,
INDEX_NAME,
COUNT_FETCH,
COUNT_INSERT,
COUNT_UPDATE,
COUNT_DELETE
FROM table_io_waits_summary_by_index_usage
ORDER BY SUM_TIMER_WAIT DESC limit 1\G
*************************** 1. row ***************************
OBJECT_NAME: test_slow
INDEX_NAME: PRIMARY
COUNT_FETCH: 393247
COUNT_INSERT: 0
COUNT_UPDATE: 393222
COUNT_DELETE: 0

經過table_io_waits_summary_by_index_usage表，能夠得到系統運行到如今，哪一個表的具體哪一個索引(包括主鍵索引，二級索引)使用最多，從結果來看，咱們知道test_slow表訪問最多，而且都是經過主鍵訪問。

(4).哪一個索引歷來沒有使用過？

SELECT
OBJECT_SCHEMA,
OBJECT_NAME,
INDEX_NAME
FROM table_io_waits_summary_by_index_usage
WHERE INDEX_NAME IS NOT NULL
AND COUNT_STAR = 0
AND OBJECT_SCHEMA <> 'mysql'
ORDER BY OBJECT_SCHEMA,OBJECT_NAME;
*************************** 1. row ***************************
OBJECT_SCHEMA: chuck
OBJECT_NAME: test_icp
INDEX_NAME: idx_y_z

經過table_io_waits_summary_by_index_usage表，咱們還能夠得到系統運行到如今，哪些索引歷來沒有被用過。因爲索引也會佔用大量的空間，咱們能夠利用這個統計信息，結合必定的時間策略將無用的索引刪除。上面的結果顯示，chuck庫test_icp表的idx_y_z歷來沒有被使用過。

統計信息(等待事件維度)
(1).哪一個等待事件消耗的時間最多？

SELECT
EVENT_NAME,
COUNT_STAR,
SUM_TIMER_WAIT,
AVG_TIMER_WAIT
FROM events_waits_summary_global_by_event_name
WHERE event_name != 'idle'
ORDER BY SUM_TIMER_WAIT DESC LIMIT 1;
*************************** 1. row ***************************
EVENT_NAME: wait/synch/cond/threadpool/worker_cond
COUNT_STAR: 26369820
SUM_TIMER_WAIT: 1604134685750586132
AVG_TIMER_WAIT: 60832219664

經過events_waits_summary_global_by_event_name表，能夠獲取到系統運行到如今，消耗時間最多的事件，固然還能夠根據其它維度排序，好比平均等待時間，從結果來看wait/synch/cond/threadpool/worker_cond這個事件消耗的累計時間最長。

具體場景分析
      前面咱們討論的基本都是彙總信息，有點相似與ORACLE-AWR(Automatic Workload Repository)的味道，那麼咱們如何利用peformance schema來定位問題呢？或者對於的發生的問題，好比抖動，咱們是否有辦法知道當時發生了什麼？
(1).剖析某條SQL的執行狀況，包括statement信息，stage信息和wait信息。
     有時候咱們須要分析具體某條SQL，該SQL在執行各個階段的時間消耗，經過events_statements_xxx表和events_stages_xxx表，就能夠達到目的。兩個表經過event_id與nesting_event_id關聯，stages表的nesting_event_id爲對應statements表的event_id。好比分析包含count(*)的某條SQL語句，具體以下：

SELECT EVENT_ID, sql_text FROM events_statements_history WHERE sql_text LIKE '%count(*)%'; +----------+--------------------------------------+
| EVENT_ID | sql_text |
+----------+--------------------------------------+
| 1690 | select count(*) from chuck.test_slow |
+----------+--------------------------------------+

首先獲得了語句的event_id爲1690，經過查找events_stages_xxx中nesting_event_id爲1690的記錄，能夠達到目的。
a.查看每一個階段的時間消耗

SELECT event_id, EVENT_NAME, SOURCE, TIMER_END - TIMER_START FROM events_stages_history_long WHERE NESTING_EVENT_ID = 1690;
+----------+--------------------------------+----------------------+-----------------------+
| event_id | EVENT_NAME | SOURCE | TIMER_END-TIMER_START |
+----------+--------------------------------+----------------------+-----------------------+
| 1691 | stage/sql/init | mysqld.cc:990 | 316945000 |
| 1693 | stage/sql/checking permissions | sql_parse.cc:5776 | 26774000 |
| 1695 | stage/sql/Opening tables | sql_base.cc:4970 | 41436934000 |
| 2638 | stage/sql/init | sql_select.cc:1050 | 85757000 |
| 2639 | stage/sql/System lock | lock.cc:303 | 40017000 |
| 2643 | stage/sql/optimizing | sql_optimizer.cc:138 | 38562000 |
| 2644 | stage/sql/statistics | sql_optimizer.cc:362 | 52845000 |
| 2645 | stage/sql/preparing | sql_optimizer.cc:485 | 53196000 |
| 2646 | stage/sql/executing | sql_executor.cc:112 | 3153000 |
| 2647 | stage/sql/Sending data | sql_executor.cc:192 | 7369072089000 |
| 4304138 | stage/sql/end | sql_select.cc:1105 | 19920000 |
| 4304139 | stage/sql/query end | sql_parse.cc:5463 | 44721000 |
| 4304145 | stage/sql/closing tables | sql_parse.cc:5524 | 61723000 |
| 4304152 | stage/sql/freeing items | sql_parse.cc:6838 | 455678000 |
| 4304155 | stage/sql/logging slow query | sql_parse.cc:2258 | 83348000 |
| 4304159 | stage/sql/cleaning up | sql_parse.cc:2163 | 4433000 |
+----------+--------------------------------+----------------------+-----------------------+

經過間接關聯，咱們能分析獲得SQL語句在每一個階段的時間消耗，時間單位以皮秒錶示。這裏展現的結果很相似profiling功能，有了performance schema，就再也不須要profiling這個功能了。另外須要注意的是，因爲默認狀況下events_stages_history表中只爲每一個鏈接記錄了最近10條記錄，爲了確保獲取全部記錄，須要訪問events_stages_history_long表。

b.查看某個階段的鎖等待狀況
      針對每一個stage可能出現的鎖等待，一個stage會對應一個或多個wait，events_waits_history_long這個表容易爆滿[默認閥值10000]。因爲select count(*)須要IO(邏輯IO或者物理IO)，因此在stage/sql/Sending data階段會有io等待的統計。經過stage_xxx表的event_id字段與waits_xxx表的nesting_event_id進行關聯。

SELECT
event_id,
event_name,
source,
timer_wait,
object_name,
index_name,
operation,
nesting_event_id
FROM events_waits_history_long
WHERE nesting_event_id = 2647;
+----------+---------------------------+-----------------+------------+-------------+------------+-----------+------------------+
| event_id | event_name | source | timer_wait | object_name | index_name | operation | nesting_event_id |
+----------+---------------------------+-----------------+------------+-------------+------------+-----------+------------------+
| 190607 | wait/io/table/sql/handler | handler.cc:2842 | 1845888 | test_slow | idx_c1 | fetch | 2647 |
| 190608 | wait/io/table/sql/handler | handler.cc:2842 | 1955328 | test_slow | idx_c1 | fetch | 2647 |
| 190609 | wait/io/table/sql/handler | handler.cc:2842 | 1929792 | test_slow | idx_c1 | fetch | 2647 | 
| 190610 | wait/io/table/sql/handler | handler.cc:2842 | 1869600 | test_slow | idx_c1 | fetch | 2647 |
| 190611 | wait/io/table/sql/handler | handler.cc:2842 | 1922496 | test_slow | idx_c1 | fetch | 2647 |
+----------+---------------------------+-----------------+------------+-------------+------------+-----------+------------------+

經過上面的實驗，咱們知道了statement,stage,wait的三級結構，經過nesting_event_id進行關聯，它表示某個事件的父event_id。

(2).模擬innodb行鎖等待的例子
      會話A執行語句update test_icp set y=y+1 where x=1(x爲primary key)，不commit；會話B執行一樣的語句update test_icp set y=y+1 where x=1，會話B堵塞，並最終報錯。經過鏈接鏈接查詢events_statements_history_long和events_stages_history_long，能夠看到在updating階段花了大約60s的時間。這主要由於實例上的innodb_lock_wait_timeout設置爲60，等待60s後超時報錯了。

SELECT
statement.EVENT_ID,
stages.event_id,
statement.sql_text,
stages.event_name,
stages.timer_wait
FROM events_statements_history_long statement 
join events_stages_history_long stages 
on statement.event_id=stages.nesting_event_id 
WHERE statement.sql_text = 'update test_icp set y=y+1 where x=1';
+----------+----------+-------------------------------------+--------------------------------+----------------+
| EVENT_ID | event_id | sql_text | event_name | timer_wait |
+----------+----------+-------------------------------------+--------------------------------+----------------+
| 5816 | 5817 | update test_icp set y=y+1 where x=1 | stage/sql/init | 195543000 |
| 5816 | 5819 | update test_icp set y=y+1 where x=1 | stage/sql/checking permissions | 22730000 |
| 5816 | 5821 | update test_icp set y=y+1 where x=1 | stage/sql/Opening tables | 66079000 |
| 5816 | 5827 | update test_icp set y=y+1 where x=1 | stage/sql/init | 89116000 |
| 5816 | 5828 | update test_icp set y=y+1 where x=1 | stage/sql/System lock | 218744000 |
| 5816 | 5832 | update test_icp set y=y+1 where x=1 | stage/sql/updating | 6001362045000 |
| 5816 | 5968 | update test_icp set y=y+1 where x=1 | stage/sql/end | 10435000 |
| 5816 | 5969 | update test_icp set y=y+1 where x=1 | stage/sql/query end | 85979000 |
| 5816 | 5983 | update test_icp set y=y+1 where x=1 | stage/sql/closing tables | 56562000 |
| 5816 | 5990 | update test_icp set y=y+1 where x=1 | stage/sql/freeing items | 83563000 |
| 5816 | 5992 | update test_icp set y=y+1 where x=1 | stage/sql/cleaning up | 4589000 |
+----------+----------+-------------------------------------+--------------------------------+----------------+

查看wait事件

SELECT
event_id,
event_name,
source,
timer_wait,
object_name,
index_name,
operation,
nesting_event_id
FROM events_waits_history_long
WHERE nesting_event_id = 5832;
*************************** 1. row ***************************
event_id: 5832
event_name: wait/io/table/sql/handler
source: handler.cc:2782
timer_wait: 6005946156624
object_name: test_icp
index_name: PRIMARY
operation: fetch

從結果來看，waits表中記錄了一個fetch等待事件，但並無更細的innodb行鎖等待事件統計。

(3).模擬MDL鎖等待的例子
      會話A執行一個大查詢select count(*) from test_slow，會話B執行表結構變動alter table test_slow modify c2 varchar(152);經過以下語句能夠獲得alter語句的執行過程，重點關注「stage/sql/Waiting for table metadata lock」階段。

SELECT
statement.EVENT_ID,
stages.event_id,
statement.sql_text,
stages.event_name as stage_name,
stages.timer_wait as stage_time
FROM events_statements_history_long statement 
left join events_stages_history_long stages 
on statement.event_id=stages.nesting_event_id
WHERE statement.sql_text = 'alter table test_slow modify c2 varchar(152)';
+-----------+-----------+----------------------------------------------+----------------------------------------------------+---------------+
| EVENT_ID | event_id | sql_text | stage_name | stage_time |
+-----------+-----------+----------------------------------------------+----------------------------------------------------+---------------+
| 326526744 | 326526745 | alter table test_slow modify c2 varchar(152) | stage/sql/init | 216662000 |
| 326526744 | 326526747 | alter table test_slow modify c2 varchar(152) | stage/sql/checking permissions | 18183000 |
| 326526744 | 326526748 | alter table test_slow modify c2 varchar(152) | stage/sql/checking permissions | 10294000 |
| 326526744 | 326526750 | alter table test_slow modify c2 varchar(152) | stage/sql/init | 4783000 |
| 326526744 | 326526751 | alter table test_slow modify c2 varchar(152) | stage/sql/Opening tables | 140172000 |
| 326526744 | 326526760 | alter table test_slow modify c2 varchar(152) | stage/sql/setup | 157643000 |
| 326526744 | 326526769 | alter table test_slow modify c2 varchar(152) | stage/sql/creating table | 8723217000 |
| 326526744 | 326526803 | alter table test_slow modify c2 varchar(152) | stage/sql/After create | 257332000 |
| 326526744 | 326526832 | alter table test_slow modify c2 varchar(152) | stage/sql/Waiting for table metadata lock | 1000181831000 |
| 326526744 | 326526835 | alter table test_slow modify c2 varchar(152) | stage/sql/After create | 33483000 |
| 326526744 | 326526838 | alter table test_slow modify c2 varchar(152) | stage/sql/Waiting for table metadata lock | 1000091810000 |
| 326526744 | 326526841 | alter table test_slow modify c2 varchar(152) | stage/sql/After create | 17187000 |
| 326526744 | 326526844 | alter table test_slow modify c2 varchar(152) | stage/sql/Waiting for table metadata lock | 1000126464000 |
| 326526744 | 326526847 | alter table test_slow modify c2 varchar(152) | stage/sql/After create | 27472000 |
| 326526744 | 326526850 | alter table test_slow modify c2 varchar(152) | stage/sql/Waiting for table metadata lock | 561996133000 |
| 326526744 | 326526853 | alter table test_slow modify c2 varchar(152) | stage/sql/After create | 124876000 |
| 326526744 | 326526877 | alter table test_slow modify c2 varchar(152) | stage/sql/System lock | 30659000 |
| 326526744 | 326526881 | alter table test_slow modify c2 varchar(152) | stage/sql/preparing for alter table | 40246000 |
| 326526744 | 326526889 | alter table test_slow modify c2 varchar(152) | stage/sql/altering table | 36628000 |
| 326526744 | 326526912 | alter table test_slow modify c2 varchar(152) | stage/sql/committing alter table to storage engine | 11846511000 |
| 326526744 | 326528280 | alter table test_slow modify c2 varchar(152) | stage/sql/end | 43824000 |
| 326526744 | 326528281 | alter table test_slow modify c2 varchar(152) | stage/sql/query end | 112557000 |
| 326526744 | 326528299 | alter table test_slow modify c2 varchar(152) | stage/sql/closing tables | 27707000 |
| 326526744 | 326528305 | alter table test_slow modify c2 varchar(152) | stage/sql/freeing items | 201614000 |
| 326526744 | 326528308 | alter table test_slow modify c2 varchar(152) | stage/sql/cleaning up | 3584000 |
+-----------+-----------+----------------------------------------------+----------------------------------------------------+---------------+

從結果能夠看到，出現了屢次stage/sql/Waiting for table metadata lock階段，而且間隔1s，說明每隔1s鍾會重試判斷。找一個該階段的event_id,經過nesting_event_id關聯，肯定到底在等待哪一個wait事件。

SELECT
event_id,
event_name,
source,
timer_wait,
object_name,
index_name,
operation,
nesting_event_id
FROM events_waits_history_long
WHERE nesting_event_id = 326526850;
+-----------+---------------------------------------------------+------------------+--------------+-------------+------------+------------+------------------+
| event_id | event_name | source | timer_wait | object_name | index_name | operation | nesting_event_id |
+-----------+---------------------------------------------------+------------------+--------------+-------------+------------+------------+------------------+
| 326526851 | wait/synch/cond/sql/MDL_context::COND_wait_status | mdl.cc:1327 | 562417991328 | NULL | NULL | timed_wait | 326526850 |
| 326526852 | wait/synch/mutex/mysys/my_thread_var::mutex | sql_class.h:3481 | 733248 | NULL | NULL | lock | 326526850 |
+-----------+---------------------------------------------------+------------------+--------------+-------------+------------+------------+------------------+

經過結果能夠知道，產生阻塞的是條件變量MDL_context::COND_wait_status，而且顯示了代碼的位置。

小結
     本文簡單舉例說明了如何經過Performance Schema獲得數據庫運行的統計信息，以及如何利用這些統計信息分析定位問題。經過Performance Schema，DBA能夠能深刻的理解系統，也能進一步定位問題的源頭和本質。