性能分析之单条 SQL 查询案例分析（mysql）

一、引言

本文将以一个案例详细展开介绍如何针对单条 SQL 进行性能分析。

二、背景

在定位到需要优化的单条查询 SQL 后，我们可以针对此查询“钻取”更多信息，分析为什么会花费怎么长的时间执行，以及如何去优化的大致方向。

三、准备工作

1、环境准备

• 操作系统：window/linux

• 数据库: MySQL 5.7

2、数据准备

创建一个数据库表

CREATE TABLE emp(empno  MEDIUMINT UNSIGNED  NOT NULL  DEFAULT 0 COMMENT '编号',ename VARCHAR(20) NOT NULL DEFAULT "" COMMENT '名字',job VARCHAR(9) NOT NULL DEFAULT "" COMMENT '工作',mgr MEDIUMINT UNSIGNED NOT NULL DEFAULT 0 COMMENT '上级编号',hiredate DATE NOT NULL COMMENT '入职时间',sal DECIMAL(7,2)  NOT NULL COMMENT '薪水',comm DECIMAL(7,2) NOT NULL COMMENT '红利',deptno MEDIUMINT UNSIGNED NOT NULL DEFAULT 0 COMMENT '部门编号')ENGINE=InnoDB DEFAULT CHARSET=utf8;

构建一个存储函数，这个存储函数会返回一个长度为参数 n 的随机字符串

delimiter $$ create function rand_string(n INT)returns varchar(255) #该函数会返回一个字符串begin    declare chars_str varchar(100) default 'abcdefghijklmnopqrstuvwxyzABCDEFJHIJKLMNOPQRSTUVWXYZ';    declare return_str varchar(255) default '';    declare i int default 0;    while i < n do        set return_str =concat(return_str,substring(chars_str,floor(1+rand()*52),1));        set i = i + 1;    end while;    return return_str;end $$ delimiter ;

接下来我们再创建一个存储函数，该存储函数会返回一个随机 int 值

delimiter $$ create function rand_num( )returns int(5)begin declare i int default 0; set i = floor(10+rand()*500);return i;  end $$ delimiter ;

然后我们利用刚刚创建的两个存储函数创建一个存储过程，该存储过程包含一个参数，该参数表示插入数据表 emp 的数据条数

elimiter $$ create procedure insert_emp(in max_num int(10))begindeclare i int default 0; set autocommit = 0;  repeat set i = i + 1; insert into emp values (i ,rand_string(6),'SALESMAN',0001,curdate(),2000,400,rand_num());  until i = max_num end repeat;   commit; end $$ delimiter ;

我们调用创建的存储过程，对 emp 表插入 1000w 条数据

call insert_emp(10000000);

最后，统计表数据

四、案例分析

1、查询 SQL

现在我们运行一个查询时间超过 1s 的查询语句

2、Explain 执行计划

MySQL 提供了一个 EXPLAIN 命令, 它可以对 SELECT 语句进行分析, 并输出 SELECT 执行的详细信息, 以供开发/测试人员针对性优化

EXPLAIN 命令的使用十分简单，只需要"EXPLAIN + SQL 语句"即可，如下命令就是对我们刚刚的慢查询语句使用 EXPLAIN 之后的结果

可以看到，EXPLAIN 命令的结果一共有以下几列：

• id: SELECT 查询的标识符. 每个 SELECT 都会自动分配一个唯一的标识符.

• select_type: SELECT 查询的类型

• PRIMARY(子查询中最外层查询）

• SUBQUERY（子查询内层第一个 SELECT）

• UNION（ UNION 语句中第二个 SELECT 开始后面所有 SELECT）

• SIMPLE（除了子查询或者 UNION 之外的其他查询）

• table: 查询的是哪个表

• partitions: 匹配的分区

• type: join 类型，性能关系：ALL < index < range ~ index_merge < ref < eq_ref < const < system

• all(全表扫描)

• index（全索引扫描）

• rang（索引范围扫描）

• ref（join 语句中被驱动表索引引用查询）

• eq_ref（通过主键或唯一索引访问，最多只会有一条结果）

• const（读常量，只需读一次）

• system（系统表，表中只有一条数据）

• null（速度最快）

• possible_keys: 此次查询中可能选用的索引

• key: 此次查询中确切使用到的索引

• key_len：使用索引的最大长度；

• ref: 哪个字段或常数与 key 一起被使用

• rows: 显示此查询一共扫描了多少行. 这个是一个估计值.

• filtered: 表示此查询条件所过滤的数据的百分比

• extra: 额外的信息

• distinct

• using filesort（order by 操作）

• using index（所查数据只需要在 index 中即可获取）

• using temporary（使用临时表）

• using where（如果包含 where，且不是仅通过索引即可获取内容，就会包含此信息）

这样，通过执行计划我们就可以清楚的看到，这条查询语句是一个全表扫描语句，查询时没有用到任何索引，所以它的查询时间肯定会很慢。

3、Show Profiling

Show Profiling 命令是在 MySQL5.1 以后引入的，来源于开源社区中的 Jeremy Cole 的贡献。在 MySQL 数据库中默认是禁用的，可以通过服务器变量在会话（连接）级别动态地修改。然后，在服务器上执行的所有语句，都会测量其耗费的时间和其它一些查询执行状态变更相关数据。

接下来我们执行一条查询命令

在开启了Query Profiler 功能之后,MySQL 就会自动记录所有执行的 Query 的 Profiling 信息。 然后我们通过以下命令获取系统中保存的所有 Query 的 profile 概要信息

然后我们可以通过以下命令查看具体的某一次查询的 Profiling 信息

Profiling 剖析报告给出了执行查询的每个步骤及其花费的时间，看结果可以快速的确定是那个步骤花费的时间最多。

以上各字段含义：

• starting：开始

• checking permissions：鉴权

• Opening tables ：打开表

• init：初始化

• System lock：系统锁

• optimizing：优化

• statistics：统计

• preparing：准备

• executing：执行

• Sending data：发送数据

• end：结束

• query end：查询结果

• closing tables：关闭表

• freeing items：释放 items

• cleaning up：清理

type 参数可以指定以显示特定的其他类型的信息：

• ALL：显示所有信息

• BLOCK IO： 显示块输入和输出操作的计数

• CONTEXT SWITCHES： 显示自愿和非自愿上下文切换的计数

• CPU： 显示用户和系统 CPU 使用时间

• IPC： 显示发送和接收的消息的计数

• MEMORY： 目前尚未实施

• PAGE FAULTS： 显示主要和次要页面错误的计数

• SOURCE： 显示源代码中的函数名称，以及函数发生的文件的名称和行号

• SWAPS： 显示交换计数

通过这个结果可以很容易看到，由于这是一次全表扫描，这里耗时最大是在 sending data（发送数据）上。除了这种情况，以下几种情况也可能耗费大量时间：

• converting HEAP to MyISAM (查询结果太大时,把结果放在磁盘)

• create tmp table (创建临时表,如 group 时储存中间结果)

• Copying to tmp table on disk (把内存临时表复制到磁盘)

• locked (被其他查询锁住)

• logging slow query (记录慢查询)

4、HOW STATUS

SHOW STATUS 命令返回一些计数器，既有服务器级别的全局计时器，也有基于某个连接的会话级别的计数器。例如其中的 Queries 在会话开始时为 0，每提交一次查询增加 1。如果执行 SHOW GLOBAL STATUS，则可以查看服务器级别（从服务器启动时开始计算的查询次数统计）。不同的计数器可见范围不一样，全局计数器也会出现在SHOW STATUS 的结果中，这样容易被误认为会话级，所以一定不能搞迷糊了。SHOW STATUS是一个很有用的工具，但并不是一款剖析工具。虽然无法提供基于时间的统计，但是执行查询完后观察某些计数器的值还是很有帮助的。

从结果可以看出该查询有很多的没有用到索引的 Handler_read_rnd_next（读操作）以及Key_blocks_unused（未使用的缓存簇(blocks)数）。假设我们不知道这条 SQL 具体的定义仅从结果来推测，这个查询有可能是全表扫描，没有合适的索引。我们可能注意到通过 Explain 执行计划也可以获得大部分相同的信息，但是 Explain 是通过估计得到的结果，而通过计数器则是实际的测量结果。

各参数详解参考官方资料：https://dev.mysql.com/doc/refman/5.6/en/server-status-variables.html

5、慢查询日志

我们可以用以下命令查看慢查询次数

使用该命令只能查看慢查询次数，但是我们没有办法知道是哪些查询产生了慢查询，如果想要知道是哪些查询导致的慢查询，那么我们必须修改 mysql 的配置文件。打开 mysql 的配置文件（windows 系统是 my.ini，linux 系统是 my.cnf），在 [mysqld] 下面加上以下代码

# General and Slow logging.log-output=FILEgeneral-log=0general_log_file="DESKTOP-MLD0KTS.log"slow-query-log=1slow_query_log_file="DESKTOP-MLD0KTS-slow.log"long_query_time=1

此时我们在 mysql 中运行以下命令，可以看到 slow_query_log 是 ON 状态，log_file 也是我们指定的文件

运行以下命令我们可以看到我们设定的慢查询时间也生效了，此时只要查询时间大于 1s，查询语句都将存入日志文件

现在我们运行一个查询时间超过 1s 的查询语句,然后查看 mysql 安装目录下的 data 目录，该目录会产生一个慢查询日志文件：mysql_slow.log，该文件内容如下

在该日志文件中，我们可以知道慢查询产生的时间，最终产生了几行结果，测试了几行结果，以及运行语句是什么。在这里我们可以看到，这条语句产生一个结果，但是检测了 1000w 行记录，是一个全表扫描语句。

参考资料：

• [1] Vadim Tkacbenko 著.高性能 MySQL.北京:电子工业出版社,2013.