Mysql中慢查询日志和show profile进行sql分析-阿里云开发者社区

慢查询日志

MySQL的慢查询日志是MySQL提供的一种日志记录，它用来记录在MySQL中响应时间超过阀值的语句，具体指运行时间超过long_query_time值的SQL，则会被记录到慢查询日志中。

慢查询sql具体指运行时间超过long_query_time（阀值）值的SQL，则会被记录到慢查询日志中。long_query_time的默认值为10，意思是运行10秒以上的语句。

由他来查看哪些SQL超出了我们的最大忍耐时间值，比如一条sql执行超过5秒钟，我们就算慢SQL，希望能收集超过5秒的sql，结合之前explain进行全面分析。

如何操作

默认情况下，MySQL数据库没有开启慢查询日速，需要我们手动来设置这个参数。

当然，如果不是调优需要的话，一般不建议启动该参数，因为开启慢查询日志会或多或少带来一定的性能影响。慢查询日志支持将日志记录写入文件。

查看是否开启及如何开启

查看是否开启

SHOW VARIABLES LIKE '%slow_query_log%';

在这里插入图片描述

开启慢查询日志，如果MySQL重启后则会失效。

set global slow_query_log=1;

在这里插入图片描述

注意：慢查询日志影响效率，因此不建议一直开启。

永久开启慢查询日志

修改my.cnf文件，[mysqld]下增加修改

slow_query_log =1
slow_query_log_file=/var/lib/mysqatguigu-slow.log

慢查询日志位置

show variables like '%slow_query_log_file%';

在这里插入图片描述

设置慢sql记录的阀值

SHOW VARIABLES LIKE 'long_query_time%';

在这里插入图片描述

set global long_query_time=3;

注意：需要重新开一个bash/cmd，不然阀值还是10

**案例：
模仿慢sql，让慢查询日志记录**

select sleep(5);

在这里插入图片描述

show variables like '%slow_query_log_file%';

在这里插入图片描述
查看慢查询日志文件

可以看到test数据库中，哪一时间，出现了慢sql

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

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

慢查询日志分析工具mysqldumpslow

在生产环境中，可以使用MySQL提供的日志分析工具mysqldumpslow。

查看mysqldumpslow的帮助信息，mysqldumpslow --help。

s：是表示按照何种方式排序
c：访问次数
l：锁定时间
r：返回记录
t：查询时间
al：平均锁定时间
ar：平均返回记录数
at：平均查询时间
t：即为返回前面多少条的数据
g：后边搭配一个正则匹配模式，大小写不敏感的

常用mysqldumpslow命令

linux中慢查询日志文件 /var/lib/mysql/xiaoxuya-slow.log

得到返回记录集最多的10个SQL

mysqldumpslow -s r -t 10 /var/lib/mysql/xiaoxuya-slow.log

得到访问次数最多的10个SQL

mysqldumpslow -s c -t 10 /var/lib/mysql/xiaoxuya-slow.log

得到按照时间排序的前10条里面含有左连接的查询语句

mysqldumpslow -s t -t 10 -g "left join" /var/lib/mysql/xiaoxuya-slow.log

另外建议在使用这些命令时结合│和more 使用，否则有可能出现爆屏情况

mysqldumpslow -s r-t 10 /ar/lib/mysql/xiaoxuya-slow.log | more

注意：提取到慢sql之后，可以使用explain/show profile 对sql进行分析优化

show profile进行sql分析

准备50万数据

1、创建对应库和表

create database bigData;
use bigData;

CREATE TABLE dept(
    id INT UNSIGNED PRIMARY KEY AUTO_INCREMENT,
    deptno MEDIUMINT UNSIGNED NOT NULL DEFAULT 0,
    dname VARCHAR(20)NOT NULL DEFAULT "",
    loc VARCHAR(13) NOT NULL DEFAULT ""
)ENGINE=INNODB DEFAULT CHARSET=utf8;

CREATE TABLE emp(
    id int unsigned primary key auto_increment,
    empno mediumint unsigned not null default 0,
    ename varchar(20) not null default "",
    job varchar(9) not null default "",
    mgr mediumint unsigned not null default 0,
    hiredate date not null,
    sal decimal(7,2) not null,
    comm decimal(7,2) not null,
    deptno mediumint unsigned not null default 0
)ENGINE=INNODB DEFAULT CHARSET=utf8;

2、设置参数log_bin_trust_function_creators

show variables like 'log_bin_trust_function_creators';
set global log_bin_trust_function_creators=1;

由于开启过慢查询日志，因为我们开启了bin-log，我们就必须为我们的function指定一个参数。不然会报This function has none of DETERMINISTIC

3、创建函数和存储过程
3.1、随机字符串函数

delimiter $$ 
create function rand_string(n int) returns varchar(255)
begin
    declare chars_str varchar(100) default 'abcdefghijklmnopqrstuvwxyz';
    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 $$ 意为设置界限符，以 $ $结束的意思

3.2 随机产生部门编号函数

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

函数记得要先执行，因为存储过程需要使用

3.3、创建往emp表中插入数据的存储过程

delimiter $$
create procedure insert_emp(in start int(10),in max_num int(10))
begin
    declare i int default 0;
    set autocommit = 0;
    repeat
        set i = i+1;
        insert into emp(empno,ename,job,mgr,hiredate,sal,comm,deptno) values((start+i),rand_string(6),'salesman',0001,curdate(),2000,400,rand_num());
        until i=max_num
        end repeat;
    commit;
end $$

3.4、创建往dept表中插入数据的存储过程

delimiter $$
create procedure insert_dept(in start int(10),in max_num int(10))
begin
    declare i int default 0;
    set autocommit = 0;
    repeat
        set i = i+1;
        insert into dept(deptno,dname,loc) values((start+i),rand_string(10),rand_string(8));
        until i=max_num
        end repeat;
    commit;
end $$

4、插入数据，调用存储过程

往部门表插入10条数据

mysql> CALL insert_dept(100, 10);

往员工表插入50万条数据

mysql> CALL insert_emp(100001, 500000);

注意：不要使用可视化软件插入数据，慢！

6、结果

在这里插入图片描述

show profile 分析步骤

1、查看当前mysql版本是否支持profile分析，

mysql> show variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | OFF   |
+---------------+-------+
1 row in set, 1 warning (0.00 sec)

2、开启profiling

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

mysql> show variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | ON    |
+---------------+-------+
1 row in set, 1 warning (0.00 sec)

3、执行sql

select count(e.deptno) number , e.deptno from emp e 
left join dept d 
on e.deptno = d.deptno  
group by e.deptno 
order by e.deptno;

结果：

mysql> select count(e.deptno) number , e.deptno from emp e left join dept d on e.deptno = d.deptno  group by e.deptno order by e.deptno;
+--------+--------+
| number | deptno |
+--------+--------+
|  50113 |    100 |
|  50433 |    101 |
|  50018 |    102 |
|  49803 |    103 |
|  49803 |    104 |
|  50106 |    105 |
|  49949 |    106 |
|  49855 |    107 |
|  50005 |    108 |
|  49915 |    109 |
+--------+--------+
10 rows in set (0.47 sec)

explain结果分析

mysql> explain  select count(e.deptno) number , e.deptno from emp e left join dept d on e.deptno = d.deptno  group by e.deptno order by e.deptno;
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+----------------------------------------------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows   | filtered | Extra                                              |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+----------------------------------------------------+
|  1 | SIMPLE      | e     | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 498620 |   100.00 | Using temporary; Using filesort                    |
|  1 | SIMPLE      | d     | NULL       | ALL  | NULL          | NULL | NULL    | NULL |     10 |   100.00 | Using where; Using join buffer (Block Nested Loop) |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+----------------------------------------------------+
2 rows in set, 1 warning (0.00 sec)

产生了临时表，文件内排序

4、 show profiles获取sql列表

mysql> show profiles;
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                                                                     |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------+
|        8 | 0.00013875 | set long_query_time = 2                                                                                                                   |
|        9 | 0.00244625 | show variables like 'long_query_time'                                                                                                     |
|       10 | 0.00184675 | show variables like 'profiling'                                                                                                           |
|       11 | 0.00035400 | explain select * from emp group by id%10 limit 150000                                                                                     |
|       12 | 0.00042575 | explain select id from emp group by id%10 limit 150000                                                                                    |
|       13 | 0.00050400 | select * from emp limit 10                                                                                                                |
|       14 | 0.16561600 | select deptno from emp group by deptno                                                                                                    |
|       15 | 0.00079050 | explain select deptno from emp group by deptno                                                                                            |
|       16 | 0.31239600 | select count(deptno) number  , deptno from emp group by deptno                                                                            |
|       17 | 0.00035800 | explain select count(deptno) number  , deptno from emp group by deptno                                                                    |
|       18 | 0.00059450 | select * from emp limit 10                                                                                                                |
|       19 | 0.00127075 | select * from dept limit 10                                                                                                               |
|       20 | 0.00418550 | select * from emp e left join dept d on e.deptno = d.deptno  limit 20                                                                     |
|       21 | 0.47500125 | select count(e.deptno) number , e.deptno from emp e left join dept d on e.deptno = d.deptno  group by e.deptno order by e.deptno          |
|       22 | 0.00038550 | explain  select count(e.deptno) number , e.deptno from emp e left join dept d on e.deptno = d.deptno  group by e.deptno order by e.deptno |
+----------+------------+-------------------------------------------------------------------------------------------------------------------------------------------+
15 rows in set, 1 warning (0.00 sec)

5、诊断SQL，show profile cpu,block io for query sqlQuery_ID;

我们选取执行时间最长的sql，查看其执行步骤

mysql> show profile cpu,block io for query 21;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status                         | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting                       | 0.000078 | 0.000000 |   0.000000 |         NULL |          NULL |
| Executing hook on transaction  | 0.000003 | 0.000000 |   0.000000 |         NULL |          NULL |
| starting                       | 0.000004 | 0.000000 |   0.000000 |         NULL |          NULL |
| checking permissions           | 0.000002 | 0.000000 |   0.000000 |         NULL |          NULL |
| checking permissions           | 0.000003 | 0.000000 |   0.000000 |         NULL |          NULL |
| Opening tables                 | 0.000037 | 0.000000 |   0.000000 |         NULL |          NULL |
| init                           | 0.000004 | 0.000000 |   0.000000 |         NULL |          NULL |
| System lock                    | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| optimizing                     | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| statistics                     | 0.000017 | 0.000000 |   0.000000 |         NULL |          NULL |
| preparing                      | 0.000028 | 0.000000 |   0.000000 |         NULL |          NULL |
| Creating tmp table             | 0.000058 | 0.000000 |   0.000000 |         NULL |          NULL |
| Sorting result                 | 0.000012 | 0.000000 |   0.000000 |         NULL |          NULL |
| executing                      | 0.000002 | 0.000000 |   0.000000 |         NULL |          NULL |
| Sending data                   | 0.474489 | 0.484375 |   0.000000 |         NULL |          NULL |
| Creating sort index            | 0.000108 | 0.000000 |   0.000000 |         NULL |          NULL |
| end                            | 0.000004 | 0.000000 |   0.000000 |         NULL |          NULL |
| query end                      | 0.000003 | 0.000000 |   0.000000 |         NULL |          NULL |
| waiting for handler commit     | 0.000013 | 0.000000 |   0.000000 |         NULL |          NULL |
| removing tmp table             | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| waiting for handler commit     | 0.000003 | 0.000000 |   0.000000 |         NULL |          NULL |
| closing tables                 | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| freeing items                  | 0.000087 | 0.000000 |   0.000000 |         NULL |          NULL |
| cleaning up                    | 0.000019 | 0.000000 |   0.000000 |         NULL |          NULL |
+--------------------------------+----------+----------+------------+--------------+---------------+
24 rows in set, 1 warning (0.00 sec)

在这里插入图片描述
可以看到，创建临时表（create tmp table ），发送数据（send data），创建排序索引，以及释放空间，最耗时，特别是数据量特别大的情况下

这也是为什么，我们要创建索引，一旦为group by ， order by 对应列创建索引，可以免去创建临时表，和文件内排序（filesort）

我们在来看一个例子：

mysql> select  e.deptno from emp e group by e.deptno  order by e.deptno ;
+--------+
| deptno |
+--------+
|    100 |
|    101 |
|    102 |
|    103 |
|    104 |
|    105 |
|    106 |
|    107 |
|    108 |
|    109 |
+--------+
10 rows in set (0.16 sec)

mysql> explain  select  e.deptno from emp e group by e.deptno  order by e.deptno ;
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+---------------------------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows   | filtered | Extra                           |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+---------------------------------+
|  1 | SIMPLE      | e     | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 498620 |   100.00 | Using temporary; Using filesort |
+----+-------------+-------+------------+------+---------------+------+---------+------+--------+----------+---------------------------------+
1 row in set, 1 warning (0.00 sec)

产生了filesort，temporary

sql诊断分析

mysql> show profile cpu , block io for query 41;
+--------------------------------+----------+----------+------------+--------------+---------------+
| Status                         | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+--------------------------------+----------+----------+------------+--------------+---------------+
| starting                       | 0.000055 | 0.000000 |   0.000000 |         NULL |          NULL |
| Executing hook on transaction  | 0.000003 | 0.000000 |   0.000000 |         NULL |          NULL |
| starting                       | 0.000005 | 0.000000 |   0.000000 |         NULL |          NULL |
| checking permissions           | 0.000003 | 0.000000 |   0.000000 |         NULL |          NULL |
| Opening tables                 | 0.000042 | 0.000000 |   0.000000 |         NULL |          NULL |
| init                           | 0.000004 | 0.000000 |   0.000000 |         NULL |          NULL |
| System lock                    | 0.000006 | 0.000000 |   0.000000 |         NULL |          NULL |
| optimizing                     | 0.000038 | 0.000000 |   0.000000 |         NULL |          NULL |
| statistics                     | 0.000013 | 0.000000 |   0.000000 |         NULL |          NULL |
| preparing                      | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| Creating tmp table             | 0.000056 | 0.000000 |   0.000000 |         NULL |          NULL |
| Sorting result                 | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| executing                      | 0.000001 | 0.000000 |   0.000000 |         NULL |          NULL |
| Sending data                   | 0.000005 | 0.000000 |   0.000000 |         NULL |          NULL |
| Creating sort index            | 0.158347 | 0.156250 |   0.000000 |         NULL |          NULL |
| end                            | 0.000009 | 0.000000 |   0.000000 |         NULL |          NULL |
| query end                      | 0.000003 | 0.000000 |   0.000000 |         NULL |          NULL |
| waiting for handler commit     | 0.000009 | 0.000000 |   0.000000 |         NULL |          NULL |
| removing tmp table             | 0.000008 | 0.000000 |   0.000000 |         NULL |          NULL |
| waiting for handler commit     | 0.000002 | 0.000000 |   0.000000 |         NULL |          NULL |
| closing tables                 | 0.000007 | 0.000000 |   0.000000 |         NULL |          NULL |
| freeing items                  | 0.000067 | 0.000000 |   0.000000 |         NULL |          NULL |
| cleaning up                    | 0.000037 | 0.000000 |   0.000000 |         NULL |          NULL |
+--------------------------------+----------+----------+------------+--------------+---------------+
23 rows in set, 1 warning (0.00 sec)

sql优化

mysql> create index idx_emp_deptno on emp(deptno);
Query OK, 0 rows affected (3.17 sec)
Records: 0  Duplicates: 0  Warnings: 0

explain分析优化后的sql

mysql> explain  select  e.deptno from emp e group by e.deptno  order by e.deptno ;
+----+-------------+-------+------------+-------+----------------+----------------+---------+------+------+----------+--------------------------+
| id | select_type | table | partitions | type  | possible_keys  | key            | key_len | ref  | rows | filtered | Extra                    |
+----+-------------+-------+------------+-------+----------------+----------------+---------+------+------+----------+--------------------------+
|  1 | SIMPLE      | e     | NULL       | range | idx_emp_deptno | idx_emp_deptno | 3       | NULL |   10 |   100.00 | Using index for group-by |
+----+-------------+-------+------------+-------+----------------+----------------+---------+------+------+----------+--------------------------+
1 row in set, 1 warning (0.00 sec)

show profile分析优化后的sql
在这里插入图片描述

在这里插入图片描述
可以看到产生临时表，和filesort没有了，取而代之的index，执行时间也变快了。

show profile参数备注

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

日常开发需要注意的结论

converting HEAP to MyISAM 查询结果太大，内存都不够用了往磁盘上搬了。
Creating tmp table 创建临时表，拷贝数据到临时表，用完再删除
Copying to tmp table on disk 把内存中临时表复制到磁盘，危险!

locked

Mysql中慢查询日志和show profile进行sql分析

慢查询日志

慢查询日志分析工具mysqldumpslow

show profile进行sql分析

show profile 分析步骤

show profile参数备注

热门文章

最新文章

相关课程

相关电子书

推荐镜像

探索云世界

热门

云计算

大数据

云原生

人工智能

数据库

开发与运维

活动广场

任务中心

训练营

直播

乘风者计划

下载

镜像站

技术资料

Mysql中 慢查询日志和show profile进行sql分析

慢查询日志

慢查询日志分析工具mysqldumpslow

show profile进行sql分析

show profile 分析步骤

show profile参数备注

热门文章

最新文章

相关课程

相关电子书

推荐镜像

Mysql中慢查询日志和show profile进行sql分析