MySQL 查看SQL语句执行阶段和进度信息

测试MySQL版本：5.7.31
根据《MySQL性能优化金字塔法则》做的实验，好书推荐！

我们在创建索引时，经常需要等待执行的SQL一段时间，期间可以通过此方法查看SQL的执行进度等信息。

首先要开启收集执行阶段信息的功能，与统计汇总执行阶段信息的功能

# 会话1
update performance_schema.setup_instruments 
set enabled='yes', timed='yes' where name like 'stage/%';

update performance_schema.setup_consumers 
set enabled='yes' where name like '%stage%';

我们需要确定执行的SQL所属的thread_id。这里我们新起一个会话2进行模拟，查询会话2的thread_id

# 会话2
mysql> select sys.ps_thread_id(connection_id());
+-----------------------------------+
| sys.ps_thread_id(connection_id()) |
+-----------------------------------+
|                             93315 |
+-----------------------------------+

一般来说，肯定会有许多线程同时存在，我们只对所希望监控的线程启用监控，将其他线程的收集执行阶段信息的功能关闭

# 会话1
update performance_schema.threads 
set INSTRUMENTED='NO' ,HISTORY='NO' where thread_id != 93315;

performance_schema的相关统计信息表中可能会留有之前的统计信息，清空他们，以免造成干扰。

# 会话1
truncate performance_schema.events_stages_current;
truncate performance_schema.events_stages_history;
truncate performance_schema.events_stages_history_long;

此时，我们在会话2中执行一条DML语句，测试一下

# 会话2
select count(*) from sbtest.sbtest4 where id between 100 and 1000;

在会话1中，查询event_stages_history_long表，，加上where thead_id ='93315'（博主也不熟练，有时候感觉其他线程的信息还是在，加上防止意外）。
通过查询结果，可以详细的看到一条select语句执行到的全过程以及每个过程的时间开销

# 会话1
select 
THREAD_ID,
EVENT_NAME,
SOURCE,
sys.format_time(TIMER_WAIT) as exec_time,
WORK_COMPLETED,
WORK_ESTIMATED 
from performance_schema.events_stages_history_long
where thread_id='93315';

+-----------+--------------------------------+--------+-----------+----------------+----------------+
| THREAD_ID | EVENT_NAME                     | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED |
+-----------+--------------------------------+--------+-----------+----------------+----------------+
|     93315 | stage/sql/starting             |        | 591.62 us |           NULL |           NULL |
|     93315 | stage/sql/checking permissions |        | 23.06 us  |           NULL |           NULL |
|     93315 | stage/sql/Opening tables       |        | 128.12 us |           NULL |           NULL |
|     93315 | stage/sql/init                 |        | 47.36 us  |           NULL |           NULL |
|     93315 | stage/sql/System lock          |        | 22.02 us  |           NULL |           NULL |
|     93315 | stage/sql/optimizing           |        | 15.71 us  |           NULL |           NULL |
|     93315 | stage/sql/statistics           |        | 343.52 us |           NULL |           NULL |
|     93315 | stage/sql/preparing            |        | 17.64 us  |           NULL |           NULL |
|     93315 | stage/sql/executing            |        | 5.65 us   |           NULL |           NULL |
|     93315 | stage/sql/Sending data         |        | 909.67 us |           NULL |           NULL |
|     93315 | stage/sql/end                  |        | 2.11 us   |           NULL |           NULL |
|     93315 | stage/sql/query end            |        | 23.36 us  |           NULL |           NULL |
|     93315 | stage/sql/closing tables       |        | 12.85 us  |           NULL |           NULL |
|     93315 | stage/sql/freeing items        |        | 47.46 us  |           NULL |           NULL |
|     93315 | stage/sql/cleaning up          |        | 1.53 us   |           NULL |           NULL |
+-----------+--------------------------------+--------+-----------+----------------+----------------+

我们再试试DDL语句，先将信息再次清空

# 会话1
truncate performance_schema.events_stages_current;
truncate performance_schema.events_stages_history;
truncate performance_schema.events_stages_history_long;

我们给某张表加一个索引，表数据量比较大，应该需要执行一段时间

# 会话2
alter table sbtest.sbtest1 add index i_c(c);

我们在会话1再次查看他的阶段信息

查询结果中，最后两列WORK_COMPLETED与WORK_ESTIMATED不为NULL,表示这个阶段事件是可以度量的事件，也就是可以看执行进度。

加上order by TIMER_WAIT desc条件后，可以发现stage/innodb/alter table (insert)阶段，花费时间最长，可以对此进行优化。（还不会，明天研究一下！）

# 会话1
select 
THREAD_ID,
EVENT_NAME,
SOURCE,
sys.format_time(TIMER_WAIT) as exec_time,
WORK_COMPLETED,
WORK_ESTIMATED 
from performance_schema.events_stages_history_long
where thread_id='93315';

+-----------+----------------------------------------------------+--------+-----------+----------------+----------------+
| THREAD_ID | EVENT_NAME                                         | SOURCE | exec_time | WORK_COMPLETED | WORK_ESTIMATED |
+-----------+----------------------------------------------------+--------+-----------+----------------+----------------+
|     93315 | stage/innodb/alter table (merge sort)              |        | 3.28 m    |        2054799 |        3061693 |
|     93315 | stage/innodb/alter table (insert)                  |        | 50.35 s   |        2744982 |        2746811 |
|     93315 | stage/innodb/alter table (flush)                   |        | 3.27 s    |        2752061 |        2752061 |
|     93315 | stage/innodb/alter table (log apply index)         |        | 6.55 ms   |        2752445 |        3082198 |
|     93315 | stage/innodb/alter table (flush)                   |        | 67.68 us  |        2752445 |        3082198 |
|     93315 | stage/sql/committing alter table to storage engine |        | 13.03 us  |           NULL |           NULL |
|     93315 | stage/innodb/alter table (end)                     |        | 70.82 ms  |        3082198 |        3082198 |
|     93315 | stage/sql/end                                      |        | 204.45 us |           NULL |           NULL |
|     93315 | stage/sql/query end                                |        | 1.77 ms   |           NULL |           NULL |
|     93315 | stage/sql/closing tables                           |        | 32.98 us  |           NULL |           NULL |
|     93315 | stage/sql/freeing items                            |        | 91.17 us  |           NULL |           NULL |
|     93315 | stage/sql/cleaning up                              |        | 1.86 us   |           NULL |           NULL |
+-----------+----------------------------------------------------+--------+-----------+----------------+----------------+

如果想看上方的加索引的语句，在执行时（也就是我们等待时），执行进度怎么办？可以通过sys.session表进行查看，如下

# 会话 1
# 如果sys.session 表中的 trx_state字段==null，表示没有performance_schema没有开启对事物状态信息的收集，此时需要开启对performance_schema事务状态信息的收集如下：
update performance_schema.setup_instruments set ENABLEd='YES',TIMED='YES' where name = 'transaction';
update performance_schema.setup_consumers set ENABLED='YES' where NAME='events_transactions_current';

# 会话 2，在执行一个增加索引的语句进行测试
alter table sbtest.sbtest1 add index i_k(k);

# 会话 1
# 查看当前正在执行的语句进度信息，会话2的conn_id=93290(它的thread_id=93315,可以用sys.ps_thread_id()函数进行转换)
select * from sys.session where conn_id = '93290' and trx_state='ACTIVE'G;
*************************** 1. row ***************************
                thd_id: 93315
               conn_id: 93290
                  user: root@localhost
                    db: performance_schema
               command: Query
                 state: alter table (read PK and internal sort)
                  time: 13
     current_statement: alter table sbtest.sbtest1 add index i_k(k)
     statement_latency: 13.23 s
              progress: 8.23   ## 进度！！！，到100就表示完成啦！
          lock_latency: 2.92 ms
         rows_examined: 0
             rows_sent: 0
         rows_affected: 0
            tmp_tables: 0
       tmp_disk_tables: 0
             full_scan: NO
        last_statement: NULL
last_statement_latency: NULL
        current_memory: 0 bytes
             last_wait: wait/io/file/innodb/innodb_data_file
     last_wait_latency: Still Waiting
                source: 
           trx_latency: 13.40 s
             trx_state: ACTIVE
        trx_autocommit: YES
                   pid: 20611
          program_name: mysql
1 row in set (0.19 sec)

# 补充：查看当前事务信息
select * from information_schema.innodb_trxG;

-----------------2020-10-28补充
博主在检测一些查询时间较长的SQL时，此方法返回的时间不完整，只记录了一部分阶段的消耗时间，目前还没找到解决方法