9-1. MySQL 性能分析工具的使用——last_query_cost，慢查询日志

9-1. MySQL 性能分析工具的使用——last_query_cost，慢查询日志

---

1. 数据库服务器的优化步骤

当我们遇到数据库调优问题的时候，该如何思考呢？这里把思考的流程整理成下面这张图。

整个流程划分成了 观察（Show status） 和 行动（Action） 两个部分。字母 S 的部分代表观察（会使 用相应的分析工具），字母 A 代表的部分是行动（对应分析可以采取的行动）。

2. 查看系统性能参数

在MySQL中，可以使用 SHOW STATUS 语句查询一些MySQL数据库服务器的性能参数 、 执行频率。 SHOW STATUS语句语法如下：

SHOW [GLOBAL|SESSION] STATUS LIKE '参数';

一些常用的性能参数如下：

• Connections：连接MySQL服务器的次数。
• Uptime：MySQL服务器的上 线时间。
• Slow_queries：慢查询的次数。
• Innodb_rows_read：Select查询返回的行数
• Innodb_rows_inserted：执行INSERT操作插入的行数
• Innodb_rows_updated：执行UPDATE操作更新的 行数
• Innodb_rows_deleted：执行DELETE操作删除的行数
• Com_select：查询操作的次数。
• Com_insert：插入操作的次数。对于批量插入的 INSERT 操作，只累加一次。
• Com_update：更新操作 的次数。
• Com_delete：删除操作的次数。

举例：

mysql> show status like 'connections';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Connections   | 21    |
+---------------+-------+
1 row in set (0.00 sec)

举例：

mysql> show status like 'uptime';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Uptime        | 28235 |
+---------------+-------+
1 row in set (0.00 sec)

mysql> show status like 'slow_queries';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 0     |
+---------------+-------+
1 row in set (0.00 sec)

mysql> show status like 'innodb_row_%';
+-------------------------------+---------+
| Variable_name                 | Value   |
+-------------------------------+---------+
| Innodb_row_lock_current_waits | 0       |
| Innodb_row_lock_time          | 0       |
| Innodb_row_lock_time_avg      | 0       |
| Innodb_row_lock_time_max      | 0       |
| Innodb_row_lock_waits         | 0       |
| Innodb_rows_deleted           | 0       |
| Innodb_rows_inserted          | 1000901 |
| Innodb_rows_read              | 8001090 |
| Innodb_rows_updated           | 0       |
+-------------------------------+---------+
9 rows in set (0.00 sec)

3. 统计SQL的查询成本：last_query_cost

我们依然使用第8章的 student_info 表为例：

CREATE TABLE `student_info` (
`id` INT(11) NOT NULL AUTO_INCREMENT,
`student_id` INT NOT NULL ,
`name` VARCHAR(20) DEFAULT NULL,
`course_id` INT NOT NULL ,
`class_id` INT(11) DEFAULT NULL,
`create_time` DATETIME DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, PRIMARY KEY (`id`)
) ENGINE=INNODB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8;

如果我们想要查询 id=900001 的记录，然后看下查询成本，我们可以直接在聚簇索引上进行查找：

mysql> SELECT student_id, class_id, NAME, create_time FROM student_info WHERE id = 900001;
+------------+----------+--------+---------------------+
| student_id | class_id | NAME   | create_time         |
+------------+----------+--------+---------------------+
|      46284 |    10136 | gUfQOy | 2025-02-13 12:48:08 |
+------------+----------+--------+---------------------+
1 row in set (0.00 sec)

然后再看下查询优化器的成本，实际上我们只需要检索一个页即可：

mysql> SHOW STATUS LIKE 'last_query_cost';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| Last_query_cost | 1.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

如果我们想要查询 id 在 900001 到 9000100 之间的学生记录呢？

mysql> SELECT student_id, class_id, NAME, create_time FROM student_info WHERE id BETWEEN 900001 AND 900100;

运行结果（100 条记录，运行时间为 0.046s ）：

然后再看下查询优化器的成本，这时我们大概需要进行 20 个页的查询。

mysql> SHOW STATUS LIKE 'last_query_cost';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| Last_query_cost | 20.290412 |
+-----------------+-----------+
1 row in set (0.00 sec)

你能看到页的数量是刚才的 20 倍，但是查询的效率并没有明显的变化，实际上这两个 SQL 查询的时间页基本上一样，就是因为采用了顺序读取的方式将页面一次性加载到缓冲池中，然后再进行查找。虽然 数量（last_query_cost）增加了不少 ，但是通过缓冲池的机制，并 没有增加多少查询时间 。

使用场景： 它对于比较开销是非常有用的，特别是我们有好几种查询方式可选的时候。

4. 定位执行慢的 SQL：慢查询日志

4.1 开启慢查询日志参数

1. 开启slow_query_log

set global slow_query_log='ON';

mysql> show variables like '%slow_query_log%';

你能看到这时慢查询分析已经开启，同时文件保存在 /var/lib/mysql/RainbowSea-slow.log 文件 中。

2. 修改long_query_time阈值

接下来我们来看下慢查询的时间阈值设置，使用如下命令：

mysql> show variables like '%long_query_time%';

这里如果我们想把时间缩短，比如设置为 1 秒，可以这样设置：

#测试发现：设置global的方式对当前session的long_query_time失效。对新连接的客户端有效。所以可以一并 执行下述语句
mysql > set global long_query_time = 1;
mysql> show global variables like '%long_query_time%';mysql> set long_query_time=1;
mysql> show variables like '%long_query_time%';

4.2 查看慢查询数目

查询当前系统中有多少条慢查询记录

mysql> SHOW GLOBAL STATUS LIKE '%Slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 0     |
+---------------+-------+
1 row in set (0.00 sec)

4.3 案例演示

步骤1. 建表

CREATE TABLE `student` (
`id` INT(11) NOT NULL AUTO_INCREMENT,
`stuno` INT NOT NULL ,
`name` VARCHAR(20) DEFAULT NULL,
`age` INT(3) DEFAULT NULL,
`classId` INT(11) DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=INNODB AUTO_INCREMENT=1 DEFAULT CHARSET=utf8;

步骤2：设置参数 log_bin_trust_function_creators

创建函数，假如报错：

This function has none of DETERMINISTIC......

命令开启：允许创建函数设置：

set global log_bin_trust_function_creators=1;    # 不加global只是当前窗口有效。

第2步：创建模拟数据必需的存储函数

说明： 创建函数，假如报错：

This function has none of DETERMINISTIC, NO SQL, or READS SQL DATA in its declaration and binary logging is enabled (you *might* want to use the less safe log_bin_trust_function_creators variable)

由于开启过慢查询日志bin-log, 我们就必须为我们的 function 指定一个参数。

主从复制，主机会将写操作记录在bin-log日志中。从机读取bin-log日志，执行语句来同步数据。如果使 用函数来操作数据，会导致从机和主键操作时间不一致。所以，默认情况下，mysql不开启创建函数设 置。

• 查看mysql是否允许创建函数：

SHOW VARIABLES LIKE 'log_bin_trust_function_creators';

• 命令开启：允许创建函数设置：

set global log_bin_trust_function_creators=1;    # 不加global只是当前窗口有效。

• mysqld重启，上述参数又会消失。永久方法：

  • windows下：my.ini[mysqld]加上：

  log_bin_trust_function_creators=1 # 1 表示真-开启，0 表示假-关闭
  

  • linux下：/etc/my.cnf 下my.cnf[mysqld]加上：

  log_bin_trust_function_creators=1 # 1 表示真-开启，0 表示假-关闭
  

#函数1：创建随机产生字符串函数
DELIMITER //
CREATE FUNCTION rand_string(n INT)RETURNS VARCHAR(255) #该函数会返回一个字符串
BEGINDECLARE chars_str VARCHAR(100) DEFAULT'abcdefghijklmnopqrstuvwxyzABCDEFJHIJKLMNOPQRSTUVWXYZ';DECLARE return_str VARCHAR(255) DEFAULT '';DECLARE i INT DEFAULT 0;WHILE i < n DOSET return_str =CONCAT(return_str,SUBSTRING(chars_str,FLOOR(1+RAND()*52),1));SET i = i + 1;END WHILE;RETURN return_str;
END //
DELIMITER ;

#函数2：创建随机数函数
DELIMITER //
CREATE FUNCTION rand_num (from_num INT ,to_num INT) RETURNS INT(11)
BEGIN
DECLARE i INT DEFAULT 0;
SET i = FLOOR(from_num +RAND() * (to_num - from_num+1)); 
RETURN i;
END // 
DELIMITER;

第3步：创建插入模拟数据的存储过程

# 存储过程1：创建插入课程表存储过程
DELIMITER //
CREATE PROCEDURE insert_course( max_num INT ) 
BEGIN
DECLARE i INT DEFAULT 0;SET autocommit = 0; #设置手动提交事务 REPEAT #循环SET i = i + 1; #赋值INSERT INTO course (course_id, course_name ) VALUES (rand_num(10000,10100),rand_string(6));UNTIL i = max_numEND REPEAT; COMMIT; #提交事务
END // 
DELIMITER;

# 存储过程2：创建插入学生信息表存储过程
DELIMITER //
CREATE PROCEDURE insert_stu1(START INT,max_num INT)
BEGIN
DECLARE i INT DEFAULT 0;SET autocommit = 0; #设置手动提交事务REPEAT #循环SET i = i + 1; # 赋值INSERT INTO student (stuno, NAME ,age ,classId )VALUES ((START+i),rand_string(6),rand_num(10,100),rand_num(10,1000));UNTIL i = max_numEND REPEAT;COMMIT; # 提交事务END //
DELIMITER ;

第4步：调用存储过程

#调用刚刚写好的函数, 4000000条记录,从100001号开始 
CALL insert_stu1(100001,4000000);

第5步：查看是否含有这么多数据，数据是否插入成功

SELECT COUNT(*) FROM student; 

4.4 测试及分析

1. 测试

mysql> SELECT * FROM student WHERE stuno = 3455655;
+---------+---------+--------+------+---------+
| id      | stuno   | name   | age  | classId |
+---------+---------+--------+------+---------+
| 3523633 | 3455655 | oQmLUr |   19 |      39 |
+---------+---------+--------+------+---------+ 
1 row in set (2.09 sec)
mysql> SELECT * FROM student WHERE name = 'oQmLUr';
+---------+---------+--------+------+---------+
| id     | stuno   | name   | age | classId | 
+---------+---------+--------+------+---------+ | 
1154002 | 1243200 | OQMlUR |  266 |      28 | 
| 1405708 | 1437740 | OQMlUR |  245 |     439 |
| 1748070 | 1680092 | OQMlUR |  240 |     414 | 
| 2119892 | 2051914 | oQmLUr |   17 |      32 | 
| 2893154 | 2825176 | OQMlUR |  245 |     435 | 
| 3523633 | 3455655 | oQmLUr |   19 |      39 |
+---------+---------+--------+------+---------+6 rows in set (2.39 sec)

从上面的结果可以看出来，查询学生编号为“3455655”的学生信息花费时间为2.09秒。查询学生姓名为 “oQmLUr”的学生信息花费时间为2.39秒。已经达到了秒的数量级，说明目前查询效率是比较低的，下面 的小节我们分析一下原因。

2.分析

show status like 'slow_queries';

补充说明：

除了上述变量，控制慢查询日志的还有一个变量：min_examined_row_limit。这个变量的意思是，查询扫描过的最少记录数 。这个变量和查询执行时间，共同组成了判别一个查询是否是慢查询的条件。如果查询扫描过的记录数大于等于这个变量值，并且查询执行时间超过 long_query_time 的值，那么，这个查询就被记录到慢查询日志中；反之，则不被记录到慢查询中。

mysql> show variables like 'min%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| min_examined_row_limit | 0     |
+------------------------+-------+
1 row in set (0.01 sec)

这个值，默认是 0 ，与 long_query_time = 10 合在一起，表示只要查询的执行时间超过10 秒钟，哪怕一个记录也没有扫描过，都要被记录到慢查询日志 中。你也可以根据需要，通过修改 my.ini 文件，来修改查询时长，或者通过 set 指令，用 SQL 语句修改“min_examined_row_limit” 的值。

4.5 慢查询日志分析工具：mysqldumpslow

在生产环境中，如果要手工分析日志，查找、分析SQL，显然是个体力活，MySQL提供了日志分析工具 mysqldumpslow 。

查看 mysqldumpslow 的帮助信息

[root@RainbowSea ~]# mysqldumpslow --help;

mysqldumpslow 命令的具体参数如下：

• -a: 不将数字抽象成N，字符串抽象成S
• -s: 是表示按照何种方式排序：
  • c: 访问次数
  • l: 锁定时间
  • r: 返回记录
  • t: 查询时间
  • al: 平均锁定时间
  • ar: 平均返回记录数
  • at: 平均查询时间 （默认方式）
  • ac: 平均查询次数
• t: 即为返回前面多少条的数据；
• -g: 后边搭配一个正则匹配模式，大小写不敏感的；

举例：我们想要按照查询时间排序，查看前五条 SQL 语句，这样写即可：

mysqldumpslow -s t -t 5 /var/lib/mysql/RainbowSea-slow.log

其中的路径位置是通过如下：show variables like '%slow_query_log%';这条命令查询到的

mysql> show variables like '%slow_query_log%';
+---------------------+------------------------------------+
| Variable_name       | Value                              |
+---------------------+------------------------------------+
| slow_query_log      | ON                                 |
| slow_query_log_file | /var/lib/mysql/RainbowSea-slow.log |
+---------------------+------------------------------------+
2 rows in set (0.01 sec)

[root@RainbowSea ~]# mysqldumpslow -s t -t 5 /var/lib/mysql/RainbowSea-slow.logReading mysql slow query log from /var/lib/mysql/RainbowSea-slow.log
Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts

工作常用参考：

#得到返回记录集最多的10个SQL
mysqldumpslow -s r -t 10 /var/lib/mysql/RainbowSea-slow.log#得到访问次数最多的10个SQL
mysqldumpslow -s c -t 10 /var/lib/mysql/RainbowSea-slow.log#得到按照时间排序的前10条里面含有左连接的查询语句
mysqldumpslow -s t -t 10 -g "left join" /var/lib/mysql/RainbowSea-slow.log#另外建议在使用这些命令时结合  | 和more 使用  ，否则有可能出现爆屏情况
mysqldumpslow -s r -t 10 /var/lib/mysql/RainbowSea-slow.log | more

4.6 关闭慢查询日志

MySQL服务器停止慢查询日志功能有两种方法：

• 方式1：永久性方式 通过 mysql 配置文件etc/my.ini

[mysqld]
slow_query_log=OFF

或者，把slow_query_log一项注释掉 或 删除

[mysqld]
#slow_query_log =OFF

重启MySQL服务，执行如下语句查询慢日志功能。

SHOW VARIABLES LIKE '%slow%';  #查询慢查询日志所在目录 
SHOW VARIABLES LIKE '%long_query_time%';  #查询超时时长

• 方式2：临时性方式

使用SET语句来设置。 （1）停止MySQL慢查询日志功能，具体SQL语句如下。

SET GLOBAL slow_query_log=off;

（2）重启MySQL服务，使用SHOW语句查询慢查询日志功能信息，具体SQL语句如下

SHOW VARIABLES LIKE '%slow%';
#以及
SHOW VARIABLES LIKE '%long_query_time%';

4.7 删除慢查询日志

进入到我们的日志文件的目录当中，找到对于的日志文件，然后，直接删除就可以了。

通过如下指令：找到日志文件的所在位置

mysql> show variables like '%slow_query_log%';
+---------------------+------------------------------------+
| Variable_name       | Value                              |
+---------------------+------------------------------------+
| slow_query_log      | ON                                 |
| slow_query_log_file | /var/lib/mysql/RainbowSea-slow.log |
+---------------------+------------------------------------+
2 rows in set (0.01 sec)

从执行结果可以看出，慢查询日志的目录默认为 MySQL 的数据目录，在该目录下手动删除慢查询日志文件 即可。使用命令mysqladmin flush-logs 来重新生成查询日志文件，具体命令如下，执行完毕会在数据目录下重新生成慢查询日志文件。

mysqladmin -uroot -p flush-logs slow

提示：

慢查询日志都是使用 mysqladmin flush-logs 命令来删除重建的。使用时一定要主键，一旦执行了这个命令，慢查询日志都只存在新的日志文件中，如果需要旧的查询日志，就必须事先备份。

5. 查看 SQL 执行成本：SHOW PROFILE

mysql > show variables like 'profiling';

通过设置 profiling='ON’ 来开启 show profile：

mysql > set profiling = 'ON';

然后执行相关的查询语句。接着看下当前会话都有哪些 profiles，使用下面这条命令：

mysql > show profiles;

你能看到当前会话一共有 2 个查询。如果我们想要查看最近一次查询的开销，可以使用：

mysql > show profile;

mysql> show profile cpu,block io for query 2;

show profile的常用查询参数：

1. ALL：显示所有的开销信息。
2. BLOCK IO：显示块IO开销。
3. CONTEXT SWITCHES：上下文切换开 销。
4. CPU：显示CPU开销信息。
5. IPC：显示发送和接收开销信息。
6. MEMORY：显示内存开销信息。
7. PAGE FAULTS：显示页面错误开销信息。
8. SOURCE：显示和Source_function，Source_file，Source_line相关的开销信息。
9. SWAPS： 显示交换次数开销信息。

6. 最后：

“在这个最后的篇章中，我要表达我对每一位读者的感激之情。你们的关注和回复是我创作的动力源泉，我从你们身上吸取了无尽的灵感与勇气。我会将你们的鼓励留在心底，继续在其他的领域奋斗。感谢你们，我们总会在某个时刻再次相遇。”