《高性能MySQL》学习笔记——第三章 服务器性能剖析

第三章 服务器性能剖析

(1)性能剖析(profiling):用于测试服务器的时间花费在哪里。

本书对数据库性能的定义:是指完成某件任务所需要的时间度量,即响应时间,每个SQL语句的查询话费的时间。

完成一项任务所需要的时间可以分成两部分:执行时间和等待时间(如IO等待)。

(2)性能剖析有两个步骤:

  • 测量任务所花费的时间;

  • 对结果进行统计分析,均值、方差、分布、计算特定的指标分析等。

(3)性能剖析本身会导致服务器变慢吗?

当然会,因为要做额外的工作付出额外的开销。但是如果性能剖析可以帮助应用程序运行得更快,那么性能剖析就使值得的。

(4)慢查询日志和通用日志

慢查询日志是指捕获所有查询时间超过long_query_time的查询,将其SQL语句和消耗时间记录到日志中。可以设置long_query_time = 0来捕获所有SQL。慢查询日志是开销最低、精度最高的测量查询时间的工具。

通用日志是指查询请求到服务器时记录,不包含响应时间和执行计划等重要信息。

将慢查询日志生成剖析报告的工具:pt-query-digest(十年前给力,2020年需根据实际情况使用更好的工具)。

(5)SHOW PROFILES

SHOW PROFILES 命令可以对每条SQL进行性能剖析,默认是禁用的,使用set profiling = 1打开对当前线程的SQL进行剖析。

SHOW PROFILE FOR QUERY N 命令可以展示记录的id为N的查询每个执行步骤的详细时间记录。

也可以查询每个查询的所有详细步骤信息:SELECT * FROM INFORMATION_SCHEMA.FROFILING;

mysql> set profiling = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> select 1;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

mysql> show profiles;
+----------+------------+----------+
| Query_ID | Duration   | Query    |
+----------+------------+----------+
|        1 | 0.00043725 | select 1 |
+----------+------------+----------+
1 row in set, 1 warning (0.00 sec)

mysql> select 2;
+---+
| 2 |
+---+
| 2 |
+---+
1 row in set (0.00 sec)

mysql> show profiles;
+----------+------------+----------+
| Query_ID | Duration   | Query    |
+----------+------------+----------+
|        1 | 0.00043725 | select 1 |
|        2 | 0.00042800 | select 2 |
+----------+------------+----------+
2 rows in set, 1 warning (0.00 sec)

mysql> set profiling = 0;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> select 3;
+---+
| 3 |
+---+
| 3 |
+---+
1 row in set (0.00 sec)

mysql> show profiles;
+----------+------------+----------+
| Query_ID | Duration   | Query    |
+----------+------------+----------+
|        1 | 0.00043725 | select 1 |
|        2 | 0.00042800 | select 2 |
+----------+------------+----------+
2 rows in set, 1 warning (0.00 sec)

mysql> show profile for query 1;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000116 |
| checking permissions | 0.000007 |
| Opening tables       | 0.000013 |
| init                 | 0.000005 |
| optimizing           | 0.000008 |
| executing            | 0.000051 |
| end                  | 0.000004 |
| query end            | 0.000005 |
| closing tables       | 0.000002 |
| freeing items        | 0.000043 |
| cleaning up          | 0.000186 |
+----------------------+----------+
11 rows in set, 1 warning (0.00 sec)

mysql> select * from information_schema.profiling;
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| QUERY_ID | SEQ | STATE                | DURATION | CPU_USER | CPU_SYSTEM | CONTEXT_VOLUNTARY | CONTEXT_INVOLUNTARY | BLOCK_OPS_IN | BLOCK_OPS_OUT | MESSAGES_SENT | MESSAGES_RECEIVED | PAGE_FAULTS_MAJOR | PAGE_FAULTS_MINOR | SWAPS | SOURCE_FUNCTION       | SOURCE_FILE          | SOURCE_LINE |
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
|        1 |   2 | starting             | 0.000116 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | NULL                  | NULL                 |        NULL |
|        1 |   3 | checking permissions | 0.000007 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | check_access          | sql_authorization.cc |        2203 |
|        1 |   4 | Opening tables       | 0.000013 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | open_tables           | sql_base.cc          |        5590 |
|        1 |   5 | init                 | 0.000005 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | Sql_cmd_dml::execute  | sql_select.cc        |         662 |
|        1 |   6 | optimizing           | 0.000008 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | JOIN::optimize        | sql_optimizer.cc     |         217 |
|        1 |   7 | executing            | 0.000051 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | JOIN::exec            | sql_executor.cc      |         227 |
|        1 |   8 | end                  | 0.000004 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | Sql_cmd_dml::execute  | sql_select.cc        |         715 |
|        1 |   9 | query end            | 0.000005 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | mysql_execute_command | sql_parse.cc         |        4547 |
|        1 |  10 | closing tables       | 0.000002 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | mysql_execute_command | sql_parse.cc         |        4593 |
|        1 |  11 | freeing items        | 0.000043 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | mysql_parse           | sql_parse.cc         |        5264 |
|        1 |  12 | cleaning up          | 0.000186 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | dispatch_command      | sql_parse.cc         |        2159 |
|        2 |   2 | starting             | 0.000130 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | NULL                  | NULL                 |        NULL |
|        2 |   3 | checking permissions | 0.000011 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | check_access          | sql_authorization.cc |        2203 |
|        2 |   4 | Opening tables       | 0.000023 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | open_tables           | sql_base.cc          |        5590 |
|        2 |   5 | init                 | 0.000009 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | Sql_cmd_dml::execute  | sql_select.cc        |         662 |
|        2 |   6 | optimizing           | 0.000009 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | JOIN::optimize        | sql_optimizer.cc     |         217 |
|        2 |   7 | executing            | 0.000012 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | JOIN::exec            | sql_executor.cc      |         227 |
|        2 |   8 | end                  | 0.000004 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | Sql_cmd_dml::execute  | sql_select.cc        |         715 |
|        2 |   9 | query end            | 0.000006 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | mysql_execute_command | sql_parse.cc         |        4547 |
|        2 |  10 | closing tables       | 0.000094 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | mysql_execute_command | sql_parse.cc         |        4593 |
|        2 |  11 | freeing items        | 0.000112 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | mysql_parse           | sql_parse.cc         |        5264 |
|        2 |  12 | cleaning up          | 0.000019 | 0.000000 |   0.000000 |              NULL |                NULL |         NULL |          NULL |          NULL |              NULL |              NULL |              NULL |  NULL | dispatch_command      | sql_parse.cc         |        2159 |
+----------+-----+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
22 rows in set, 1 warning (0.00 sec)

(6)SHOW STATUS

SHOW STATUS 命令可以查看计数器统计到的值,如统计了查询的次数、使用某个索引的次数。虽然无法展示使用时间,但还是可以通过观察哪些操作执行的更频繁。最有用的计数器有:句柄计数器(handler counter)、临时文件和表计数器等。

mysql> SHOW STATUS WHERE VARIABLE_NAME LIKE 'Handler%' OR VARIABLE_NAME LIKE 'Created%';
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| Created_tmp_disk_tables    | 0     |
| Created_tmp_files          | 5     |
| Created_tmp_tables         | 3     |
| Handler_commit             | 3     |
| Handler_delete             | 0     |
| Handler_discover           | 0     |
| Handler_external_lock      | 90    |
| Handler_mrr_init           | 0     |
| Handler_prepare            | 0     |
| Handler_read_first         | 0     |
| Handler_read_key           | 3     |
| Handler_read_last          | 0     |
| Handler_read_next          | 0     |
| Handler_read_prev          | 0     |
| Handler_read_rnd           | 0     |
| Handler_read_rnd_next      | 58    |
| Handler_rollback           | 0     |
| Handler_savepoint          | 0     |
| Handler_savepoint_rollback | 0     |
| Handler_update             | 0     |
| Handler_write              | 55    |
+----------------------------+-------+
21 rows in set (0.00 sec)

FLASH STATUS; -- 该命令作用是重置计数器

通过重置计数器,并测试一条SQL,就可以获取这条SQL的执行时各个计数器的值。EXPLAIN 得到的是估计的结果,而通过 SHOW STATUS 统计计数器的值测量到的是实际发生的结果。

(7)间歇性问题

举例:一个SQL查询正常情况下很快,但是有几次不合理的特别慢,手工执行下也很快,EXPLAIN 和 SHOW STATUS 中都正确使用了索引,尝试修改WHERE 条件排除缓存命中的可能,也没有什么问题,这种情况下很难查出来是什么原因导致这几次SQL执行很慢,可能是正在备份,或某种类型的锁,或争用阻塞了SQL的进度等,这种问题就是间歇性问题。书中对间歇性问题的建议是不要花费太多时间去找出问题所在,更不能用试错的方式来解决问题,可以通过以下思路进行尝试:

  • 先确定到底是服务器问题还是单条SQL的问题

    • 使用SHOW GLOBAL STATUS

    • 使用SHOW PROCESSLIST

    • 使用慢查询日志

    以上两个方法都是通过不停的捕获命令的输出,观察异常值等其他特征,来进行诊断。第三个方法是查看慢查询日志中吞吐量突然下降时间段结束后的那一部分日志,再具体分析哪个SQL导致缓慢。以上三个方法在书中都有具体例子,有需要可以自行看书。书中建议从第1、2两种方法开始查找问题,这两个方法开销最低。

  • 有必要再捕获诊断数据

    • 触发器:根据实际情况设计触发指标和触发条件,使用合理工具(如pt-talk和pt-collect)收集数据给触发器去判断。

(8)一个诊断案例

略,有需要可以自行看书。

(9)使用information_schema

稍后整理一个information_schema库的专题讲解。

posted @ 2020-11-08 10:27  yury757  阅读(127)  评论(0)    收藏  举报