1 缘起
想起这个题目的起因来自于近期的一次性能优化。要优化的是一个网上在线考试系统，这个系统是用spring框架开发的，部署也是常见的方式。后端是mysql数据库，应用服务器是tomcat，考试人员从互联网上登录进行考试。
这个考试系统上要进行一次规模较大的在线考试，大概有800多人要同在一个考场上进行考试。以前这个考试系统上一次考试最大的人数是200人左右。由于同时考试的人数增长了3倍。因此，开发人员做了一个接口用来测试在800人同时在线时应用的响应，结果在300个并发时就出了问题，测试人员提交了答案后系统在数秒后才能响应，最长的响应时间甚至达到了10秒之上。这个响应时间显然满足不了在线考试的要求，需要对系统进行优化。
2 系统优化
优化的过程不是这篇文章的重点，这里就不详细记述了，这里说一下优化采取的措施和效果。
这次优化采取了两个措施。一个措施是针对数据库的，根据更新语句的两个条件创建联合索引。这个措施取得了立竿见影的效果，系统响应时间马上就降到了2-3秒左右。两三秒的时间对于在线考试来说，时间还是长点，查看数据库，偶尔还能发现比较长的事务。下一个优化的措施是更换了spring应用的日志系统的版本，日志系统版本换了之后，再进行压测，响应时间就在1秒之内了，后来分析问题根源是应用服务器的io较慢。
这个系统的全链路涉及互联网、tomcat服务器、spring应用、MySQL数据库，再加上整个系统是部署在windows操作系统之上。诊断和排查起来比较困难。很长一段时间内，MySQL数据都是重点排查的对象，认为是这个考试系统执行的更新语句执行时间导致了整个系统响应时间过长，直至应用运维对方法的执行时间进行监控，确认方法的执行时都在合理范围之后才转到其他的方向。
从数据库方面怎样确认某个时间段内SQL语句的执行时间有无异常？对Oracle数据库，这不是问题，不但有大量的视图、日志可以采集分析，也有ash、AWR等工具可以快速分析和定位。对于MySQL数据库，在performance schema出现之前，技术手段是相对缺乏的，常用的如慢日志、查看进程列表等，获得的信息相对有限，排查起来难度较大。
不过，从performance schema 出现之后，这种情况的得到了改善，尤其是MySQL 8.0以来，performance schema默认是打开的（很多MySQL数据库的大部分参数都是默认配置），这个dba分析数据库性能提供了很大方便。
3 如何使用performance schema获取SQL语句执行的当前和历史信息
3.1 确认performance schema已打开
从MySQL 8.0开始，performance schema默认是打开的，运行下面命令检查performance schema是否打开。
show variables like 'performance_schema'; Variable_name |Value| ------------------+-----+ performance_schema|ON |
3.2 确认statement instrument已开启
MySQL8.0默认激活了statement事件的instrument，使用下面的语句确认一下：
select * from setup_instruments where name like '%statement%'; NAME |ENABLED|TIMED| ---------------------------------------------+-------+-----+ statement/sql/select |YES |YES | statement/sql/create_table |YES |YES | statement/sql/create_index |YES |YES | statement/sql/alter_table |YES |YES | statement/sql/update |YES |YES | statement/sql/insert |YES |YES | statement/sql/insert_select |YES |YES | statement/sql/delete |YES |YES | statement/sql/truncate |YES |YES | statement/sql/drop_table |YES |YES | statement/sql/drop_index |YES |YES |
可以看到，常见SQL语句类型的instrument都已激活，如果里面没有想要度量的语句类型，对这个表进行更新即可，例如：
update setup_instruments set ENABLED='NO' where name like 'statement/sql/select'--取消select语句的度量 update setup_instruments set ENABLED='YES' where name like 'statement/sql/select'--激活select语句的度量
3.3 确认已开启的statement 消费者
select * from setup_consumers; NAME |ENABLED|--------------------------------+-------+events_stages_current |NO | events_stages_history |NO | events_stages_history_long |NO | events_statements_current |YES | events_statements_history |YES | events_statements_history_long |NO | events_transactions_current |YES | events_transactions_history |YES | events_transactions_history_long|NO | events_waits_current |NO | events_waits_history |NO | events_waits_history_long |NO | global_instrumentation |YES | thread_instrumentation |YES | statements_digest |YES |
statement事件的current和history的消费者都是激活的，通过查询这个消费者对应的表可以获得sql语句的相关信息，history_long消费者则没有激活，如果要查询相关信息，必须先进行激活，同样，更新这个表即可：
update setup_consumers set ENABLED='YES' where name like 'events_transactions_history_long'
检查并确认过instrument和consumer之后，就可以查询相关的SQL语句的当前和历史执行信息进行查询、统计和分析了。在这之前需要了解一下performance schema表是怎样显示时间的。
3.4 performance schema的时间显示
关于时间显示，先看一个示例：
select THREAD_ID,EVENT_NAME ,TIMER_START,TIMER_END,TIMER_WAIT from events_statements_current; THREAD_ID|EVENT_NAME |TIMER_START |TIMER_END |TIMER_WAIT| ---------+------------------------+----------------+----------------+----------+ 47|statement/sql/select | 39387592241000| 39388252268000| 660027000| 48|statement/sql/select |3004210248928000|3004214933894000|4684966000|
这里显示的当前执行的SQL语句，有三个时间列，分别事件的起止时间和等待时间，这些时间值都很大，如果不对这个时间的显示方式进行了解，很难理解其中含义。
performance schema的时间的显示单位是皮秒，时间单位之间的转换如下：
时间的单位：1秒(s) = 1000 毫秒(ms) = 1,000,000 微秒(μs) = 1,000,000,000 纳秒(ns) = 1,000,000,000,000 皮秒(ps)
至于为什么选择这个时间单位，则是基于性能方面的考虑，performance schema在对时间进行采用度量时分别采用cpu周期、纳秒、微秒、毫秒等时间单位。在显示是如果转换cycles或者纳秒到微秒，就要对每一个instrumentation执行除法。除法在很多平台上是比较昂贵的操作，所以采用了皮秒，在转换时进行乘法运算。上面的TIMER_START显示的是从数据库启动时间开始计时的皮秒数，如需显示SQL语句开始和结束的正确时间，需要将它加上数据库的启动时间。
为了方便对时间的显示，MySQL从8.0.16版本提供了format_pico_time 函数，可以把时间转换成可读的时间格式。如：
select format_pico_time(10000000000000) ,format_pico_time(50000000000000000000); format_pico_time(10000000000000)|format_pico_time(50000000000000000000)| --------------------------------+--------------------------------------+ 10.00 s |578.70 d |
3.5 显示当前和历史SQL语句执行信息
3.5.1 显示当前SQL语句执行信息
events_statements_current表里显示的现在正在执行的语句，对于空连接，则显示最后执行的语句。要注意的是，当执行的是存储程序时，每一个连接可能会有多行。要想对数据库当前执行的SQL语句进行全面的了解和分析，只需要查询这个表里非空连接执行的SQL语句相关信息即可。
select THREAD_ID, EVENT_ID, db_start.db_start + INTERVAL events_statements_current.TIMER_START / 1000000000000 second TIMER_START , db_start.db_start + INTERVAL events_statements_current.TIMER_END / 1000000000000 second TIMER_END, format_pico_time(TIMER_WAIT) TIMER_WAIT, format_pico_time(LOCK_TIME) LOCK_TIME, left(SQL_TEXT, 80) SQL_TEXT from events_statements_current inner join ( select now()-INTERVAL VARIABLE_VALUE second + INTERVAL 8 hour db_start from global_status where variable_name = 'Uptime') db_start on 1 = 1 where CURRENT_SCHEMA = 'sysbenchdb' ; THREAD_ID|EVENT_ID|TIMER_START |TIMER_END |TIMER_WAIT|LOCK_TIME|SQL_TEXT | ---------+--------+--------------------------+--------------------------+----------+---------+---------------------------------------+ 50| 897|2024-10-14 09:24:14.246050|2024-10-14 09:24:14.293313|47.26 ms |254.00 us|DELETE FROM sbtest3 WHERE id=50157 | 51| 897|2024-10-14 09:24:14.283466|2024-10-14 09:24:14.293448|9.98 ms |69.00 us |DELETE FROM sbtest4 WHERE id=49790 | 52| 929|2024-10-14 09:24:14.220511|2024-10-14 09:24:14.293462|72.95 ms |63.00 us |UPDATE sbtest1 SET k=k+1 WHERE id=53649| 53| 929|2024-10-14 09:24:14.291142|2024-10-14 09:24:14.293469|2.33 ms |345.00 us|UPDATE sbtest3 SET k=k+1 WHERE id=49856| |
上面的查询显示了MySQL数据库当前正在执行的SQL语句（连接处于活跃状态），以及sleep连接的最后一条执行的sql语句，对于当前正在执行的SQL语句，TIMER_END的值是当前的时间。在这里可以看到语句执行的开始时间，语句的执行时间，也就是这个时间的TIMER_WAIT，以及语句等待表锁的时间，提供了MySQL数据当前正在执行的SQL语句全面准确的时间指标，通过这些时间指标，可以迅速判断SQL语句的执行性能，也有助于迅速定位出MySQL数据库当前执行的慢查询语句。
3.5.2 查询和分析SQL语句执行历史信息
events_statements_history表里可以查询每一个连接最后执行的语句。每个连接保持的语句的数量的上限由performance_schema_events_history_size(缺省值是10)。当连接关闭时，连接执行的语句也被移除。
select THREAD_ID, EVENT_ID, db_start.db_start + INTERVAL events_statements_history .TIMER_START / 1000000000000 second TIMER_START , db_start.db_start + INTERVAL events_statements_history .TIMER_END / 1000000000000 second TIMER_END, format_pico_time(TIMER_WAIT) TIMER_WAIT, format_pico_time(LOCK_TIME) LOCK_TIME, left(SQL_TEXT, 80) SQL_TEXT from events_statements_history inner join ( select now()-INTERVAL VARIABLE_VALUE second + INTERVAL 8 hour db_start from global_status where variable_name = 'Uptime') db_start on 1 = 1 where thread_id=50 ; THREAD_ID|EVENT_ID|TIMER_START |TIMER_END |TIMER_WAIT|LOCK_TIME|SQL_TEXT | ---------+--------+--------------------------+--------------------------+----------+---------+--------------------------------------------------------------------------------+ 50| 37741|2024-10-14 09:28:58.021348|2024-10-14 09:28:58.021436|88.54 us |34.00 us |SELECT c FROM sbtest1 WHERE id=50452 | 50| 37743|2024-10-14 09:28:58.022504|2024-10-14 09:28:58.022656|151.96 us |34.00 us |SELECT c FROM sbtest1 WHERE id=49969 | 50| 37745|2024-10-14 09:28:58.024400|2024-10-14 09:28:58.028273|3.87 ms |39.00 us |SELECT c FROM sbtest1 WHERE id=50001 | 50| 37747|2024-10-14 09:28:58.029995|2024-10-14 09:28:58.030251|255.92 us |37.00 us |SELECT c FROM sbtest1 WHERE id=50318 | 50| 37749|2024-10-14 09:28:58.031132|2024-10-14 09:28:58.031496|364.34 us |35.00 us |SELECT c FROM sbtest2 WHERE id BETWEEN 63885 AND 63984 | 50| 37751|2024-10-14 09:28:58.032481|2024-10-14 09:28:58.032870|389.26 us |38.00 us |SELECT SUM(k) FROM sbtest3 WHERE id BETWEEN 50246 AND 50345 | 50| 37753|2024-10-14 09:28:58.034395|2024-10-14 09:28:58.034696|301.60 us |42.00 us |SELECT c FROM sbtest2 WHERE id BETWEEN 50298 AND 50397 ORDER BY c | 50| 37755|2024-10-14 09:28:58.040730|2024-10-14 09:28:58.041030|299.84 us |52.00 us |SELECT DISTINCT c FROM sbtest3 WHERE id BETWEEN 50067 AND 50166 ORDER BY c | 50| 37757|2024-10-14 09:28:58.042091|2024-10-14 09:28:58.098982|56.89 ms |214.00 us|UPDATE sbtest2 SET k=k+1 WHERE id=61546 | 50| 37759|2024-10-14 09:28:58.101153|2024-10-14 09:28:58.199963|98.81 ms |357.00 us|UPDATE sbtest3 SET c=select60937771154-82278555870-40236015161-45154483438-439808
上面查询的是一个特定的线程执行的sql语句历史信息，由于performance_schema_events_history_size采用的默认值，对于每个线程只能显示10条语句执行历史信息，如果数据库里有比较长的事务，可以根据事务的SQL语句数量调整这个参数值。从这个表里，我们可以准确把我线程执行在一段时间内执行的SQL语句。对应到前面提到的考试系统，可以跟踪到考生的答题到提交答案，进入到下一题执行的所有SQL语句，可以找到执行时间长响应语句进行分析优化。
3.6 SQL语句执行统计汇总信息
events_statemens_summary_by_digest这个表实际上是实例自这个表重置以来（通常是mysql重启）所有查询的报告。这个表上有一个 唯一索引（shema_name,DIGEST)用来分组数据。表的最大行数由performance_schema_digests_size（动态大小，通常是缺省值10000）决定。可以对这个表进行truncate操作，相当于对这个表进行重置了。对于取样的查询信息，取样的查询在满足下面三个条件之一的情况下被替换：
1 查询第一遇到一个给定的缺省模式
2 新出现的查询比现在取样的查询由更高的timer_wait值（其实就是它执行的更慢）
3 如果performance_schema_max_digest_sample_age选项大于0，现在的查询比这个值老（这个值的单位是秒）。这个值默认是60秒，在你的监控周期是1在你的监控周期是1分钟时这个值设置的正好。因为它恰好可以捕捉到每一分钟时间间隔内执行最慢的sql语句。如果你的监控间隔大了，考虑以下增大这个值。
select left(DIGEST_TEXT,80) sql_text,count_star, format_pico_time(MIN_TIMER_WAIT) MIN_TIMER_WAIT , format_pico_time(AVG_TIMER_WAIT) AVG_TIMER_WAIT, format_pico_time(MAX_TIMER_WAIT) MAX_TIMER_WAIT, format_pico_time(QUANTILE_95) QUANTILE_95, format_pico_time(QUANTILE_99) QUANTILE_99, format_pico_time(QUANTILE_999) QUANTILE_999 from events_statements_summary_by_digest where schema_name='sysbenchdb'; sql_text sql_text |count_star|MIN_TIMER_WAIT|AVG_TIMER_WAIT|MAX_TIMER_WAIT|QUANTILE_95|QUANTILE_99|QUANTILE_999| -----------------------------------------------------------------------------+----------+--------------+--------------+--------------+-----------+-----------+------------+ SELECT `c` FROM `sbtest4` WHERE `id` = ? | 11268|60.64 us |329.87 us |76.17 ms |660.69 us |3.47 ms |10.96 ms | SELECT `c` FROM `sbtest3` WHERE `id` = ? | 10000|59.63 us |349.34 us |77.63 ms |660.69 us |3.63 ms |12.02 ms | SELECT `c` FROM `sbtest4` WHERE `id` BETWEEN ? AND ? | 1055|152.94 us |523.77 us |30.97 ms |870.96 us |4.79 ms |19.95 ms | SELECT `c` FROM `sbtest3` WHERE `id` BETWEEN ? AND ? | 1089|144.69 us |492.87 us |22.03 ms |954.99 us |4.57 ms |16.60 ms | SELECT SUM ( `k` ) FROM `sbtest1` WHERE `id` BETWEEN ? AND ? | 1091|126.12 us |551.48 us |45.39 ms |870.96 us |5.50 ms |25.12 ms | SELECT SUM ( `k` ) FROM `sbtest3` WHERE `id` BETWEEN ? AND ? | 1076|119.57 us |443.45 us |15.09 ms |870.96 us |4.17 ms |12.59 ms | SELECT `c` FROM `sbtest3` WHERE `id` BETWEEN ? AND ? ORDER BY `c` | 1017|192.71 us |594.76 us |24.29 ms |1.05 ms |5.75 ms |18.20 ms | SELECT SUM ( `k` ) FROM `sbtest4` WHERE `id` BETWEEN ? AND ? | 1075|133.53 us |442.39 us |30.17 ms |758.58 us |4.37 ms |12.02 ms | SELECT DISTINCTROW `c` FROM `sbtest1` WHERE `id` BETWEEN ? AND ? ORDER BY `c`| 1094|261.42 us |714.68 us |33.61 ms |1.15 ms |6.61 ms |17.38 ms | SELECT `c` FROM `sbtest4` WHERE `id` BETWEEN ? AND ? ORDER BY `c` | 1105|188.01 us |607.64 us |56.86 ms |1.00 ms |3.80 ms |22.91 ms | SELECT DISTINCTROW `c` FROM `sbtest2` WHERE `id` BETWEEN ? AND ? ORDER BY `c`| 1119|250.87 us |757.47 us |47.49 ms |1.38 ms |4.57 ms |34.67 ms |
这个汇总表也很有用，同样，performance_schema_max_digest_sample_age采用的是默认配置（60秒），这个从这里看一看到一条语句在60秒之内的各项统计指标。对应到上面的考试系统，可以把这个值调整到一场考试的时间。在考试开始前truncate一下这张表。考试完毕后，这个表里就有了整个考试时间内执行的SQL语句的统计信息，从里面可以找到执行时间过长的考试相关的SQL语句，对于性能分析和优化是十分有帮助的，也可以迅速判断是不是数据库是不是整个系统响应慢的原因。
4 总结
总结一下，MySQL的performance schema在分析MySQL数据库SQL语句方面是一个强大的工具，提供了十分详细全面SQL语句当前和历史执行信息，使用起来比慢日志和通用日志更加方便。当然，performance schema的功能不仅局限在SQL语句方面，在事务、线程、等待事件的信息度量和统计分析方面也很强大，是MySQL DBA有必要掌握的性能工具。
