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

本文涉及的产品
云数据库 RDS MySQL Serverless,0.5-2RCU 50GB
云数据库 RDS MySQL Serverless,价值2615元额度,1个月
简介: MySQL的慢查询日志是MySQL提供的一种日志记录,它用来记录在MySQL中响应时间超过阀值的语句,具体指运行时间超过long_query_time值的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进行分析优化

[Mysql中索引失效常见原因和解决方案
](https://blog.csdn.net/qq_44787816/article/details/119352081)
[Mysql中explain优化分析详解
](https://blog.csdn.net/qq_44787816/article/details/119345507)

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

相关实践学习
基于CentOS快速搭建LAMP环境
本教程介绍如何搭建LAMP环境,其中LAMP分别代表Linux、Apache、MySQL和PHP。
全面了解阿里云能为你做什么
阿里云在全球各地部署高效节能的绿色数据中心,利用清洁计算为万物互联的新世界提供源源不断的能源动力,目前开服的区域包括中国(华北、华东、华南、香港)、新加坡、美国(美东、美西)、欧洲、中东、澳大利亚、日本。目前阿里云的产品涵盖弹性计算、数据库、存储与CDN、分析与搜索、云通信、网络、管理与监控、应用服务、互联网中间件、移动服务、视频服务等。通过本课程,来了解阿里云能够为你的业务带来哪些帮助 &nbsp; &nbsp; 相关的阿里云产品:云服务器ECS 云服务器 ECS(Elastic Compute Service)是一种弹性可伸缩的计算服务,助您降低 IT 成本,提升运维效率,使您更专注于核心业务创新。产品详情: https://www.aliyun.com/product/ecs
相关文章
|
11天前
|
SQL 关系型数据库 MySQL
【MySQL系列笔记】常用SQL
常用SQL分为三种类型,分别为DDL,DML和DQL;这三种类型的SQL语句分别用于管理数据库结构、操作数据、以及查询数据,是数据库操作中最常用的语句类型。 在后面学习的多表联查中,SQL是分析业务后业务后能否实现的基础,以及后面如何书写动态SQL,以及完成级联查询的关键。
169 6
|
11天前
|
SQL 关系型数据库 MySQL
【MySQL-4】简述SQLの通用语法及4种基本语句介绍(DDL/DML/DQL/DCL)
【MySQL-4】简述SQLの通用语法及4种基本语句介绍(DDL/DML/DQL/DCL)
|
12天前
|
SQL 存储 关系型数据库
【MySQL系列笔记】SQL优化
SQL优化是通过调整数据库查询、索引、表结构和配置参数等方式,提高SQL查询性能和效率的过程。它旨在减少查询执行时间、减少系统资源消耗,从而提升数据库系统整体性能。优化方法包括索引优化、查询重写、表分区、适当选择和调整数据库引擎等。
189 3
|
13天前
|
SQL 关系型数据库 MySQL
MySQL SQL error: #1271 - Illegal mix of collations for operation ‘UNION‘
MySQL SQL error: #1271 - Illegal mix of collations for operation ‘UNION‘
|
13天前
|
DataWorks 关系型数据库 MySQL
DataWorks产品使用合集之在DataWorks中,如何通过PolarDB for MySQL来查看binlog日志
DataWorks作为一站式的数据开发与治理平台,提供了从数据采集、清洗、开发、调度、服务化、质量监控到安全管理的全套解决方案,帮助企业构建高效、规范、安全的大数据处理体系。以下是对DataWorks产品使用合集的概述,涵盖数据处理的各个环节。
28 1
|
13天前
|
SQL 关系型数据库 MySQL
【MySQL】:探秘主流关系型数据库管理系统及SQL语言
【MySQL】:探秘主流关系型数据库管理系统及SQL语言
26 0
|
13天前
|
SQL 监控 关系型数据库
【MySQL学习】MySQL的慢查询日志和错误日志
【MySQL学习】MySQL的慢查询日志和错误日志
|
16天前
|
SQL 关系型数据库 MySQL
【MySQL】SQL优化
【MySQL】SQL优化
|
17天前
|
SQL 关系型数据库 MySQL
如何将完整的sql打在控制台和日志上
如何将完整的sql打在控制台和日志上
5 0
|
18天前
|
SQL 存储 关系型数据库
MySQL SQL优化
MySQL SQL优化
16 0

推荐镜像

更多