MySQL Performance-Schema(三) 实践篇

前一篇文章我们分析了Performance-Schema中每个表的用途，以及主要字段的含义，比较侧重于理论的介绍。这篇文章我主要从DBA的角度出发，详细介绍如何通过Performance-Schema得到DBA关心的数据，比如哪个SQL执行次数最多，哪个表访问最频繁，哪个锁最热等信息。通过充分利用Performance-Schema表的数据，让DBA更了解DB的运行状态，也更有助于排查定位问题。本文主要从两方面展开讨论，第一方面是统计信息维度，包括SQL维度，对象维度和等待事件维度三小点；第二方面是定位分析问题维度，结合实际应用场景，利用Performance-Schema搜集的数据进行分析。

 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 

 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从来没有被使用过。

 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这个事件消耗的累计时间最长。

 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 | +----------+--------------------------------------+ 

 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表。

 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。

 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行锁等待事件统计。

 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，并且显示了代码的位置。