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

本文涉及的产品
云数据库 RDS MySQL,集群系列 2核4GB
推荐场景:
搭建个人博客
RDS MySQL Serverless 基础系列,0.5-2RCU 50GB
云数据库 RDS MySQL,高可用系列 2核4GB
简介: 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进行分析优化

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数据库
开始实验后,系统会自动创建一台自建MySQL的 源数据库 ECS 实例和一台 目标数据库 RDS。
全面了解阿里云能为你做什么
阿里云在全球各地部署高效节能的绿色数据中心,利用清洁计算为万物互联的新世界提供源源不断的能源动力,目前开服的区域包括中国(华北、华东、华南、香港)、新加坡、美国(美东、美西)、欧洲、中东、澳大利亚、日本。目前阿里云的产品涵盖弹性计算、数据库、存储与CDN、分析与搜索、云通信、网络、管理与监控、应用服务、互联网中间件、移动服务、视频服务等。通过本课程,来了解阿里云能够为你的业务带来哪些帮助 &nbsp; &nbsp; 相关的阿里云产品:云服务器ECS 云服务器 ECS(Elastic Compute Service)是一种弹性可伸缩的计算服务,助您降低 IT 成本,提升运维效率,使您更专注于核心业务创新。产品详情: https://www.aliyun.com/product/ecs
相关文章
|
25天前
|
存储 关系型数据库 MySQL
基于案例分析 MySQL 权限认证中的具体优先原则
【10月更文挑战第26天】本文通过具体案例分析了MySQL权限认证中的优先原则,包括全局权限、数据库级别权限和表级别权限的设置与优先级。全局权限优先于数据库级别权限,后者又优先于表级别权限。在权限冲突时,更严格的权限将被优先执行,确保数据库的安全性与资源合理分配。
|
30天前
|
SQL 运维 关系型数据库
MySQL 运维 SQL 备忘
MySQL 运维 SQL 备忘录
45 1
|
18天前
|
SQL 关系型数据库 MySQL
MySql5.6版本开启慢SQL功能-本次采用永久生效方式
MySql5.6版本开启慢SQL功能-本次采用永久生效方式
33 0
|
18天前
|
SQL 关系型数据库 MySQL
mysql编写sql脚本:要求表没有主键,但是想查询没有相同值的时候才进行插入
mysql编写sql脚本:要求表没有主键,但是想查询没有相同值的时候才进行插入
30 0
|
12天前
|
XML 安全 Java
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
本文介绍了Java日志框架的基本概念和使用方法,重点讨论了SLF4J、Log4j、Logback和Log4j2之间的关系及其性能对比。SLF4J作为一个日志抽象层,允许开发者使用统一的日志接口,而Log4j、Logback和Log4j2则是具体的日志实现框架。Log4j2在性能上优于Logback,推荐在新项目中使用。文章还详细说明了如何在Spring Boot项目中配置Log4j2和Logback,以及如何使用Lombok简化日志记录。最后,提供了一些日志配置的最佳实践,包括滚动日志、统一日志格式和提高日志性能的方法。
117 30
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
|
1月前
|
XML JSON Java
Logback 与 log4j2 性能对比:谁才是日志框架的性能王者?
【10月更文挑战第5天】在Java开发中,日志框架是不可或缺的工具,它们帮助我们记录系统运行时的信息、警告和错误,对于开发人员来说至关重要。在众多日志框架中,Logback和log4j2以其卓越的性能和丰富的功能脱颖而出,成为开发者们的首选。本文将深入探讨Logback与log4j2在性能方面的对比,通过详细的分析和实例,帮助大家理解两者之间的性能差异,以便在实际项目中做出更明智的选择。
218 3
|
3月前
|
Kubernetes Ubuntu Windows
【Azure K8S | AKS】分享从AKS集群的Node中查看日志的方法(/var/log)
【Azure K8S | AKS】分享从AKS集群的Node中查看日志的方法(/var/log)
131 3
|
1月前
|
存储 缓存 关系型数据库
MySQL事务日志-Redo Log工作原理分析
事务的隔离性和原子性分别通过锁和事务日志实现,而持久性则依赖于事务日志中的`Redo Log`。在MySQL中,`Redo Log`确保已提交事务的数据能持久保存,即使系统崩溃也能通过重做日志恢复数据。其工作原理是记录数据在内存中的更改,待事务提交时写入磁盘。此外,`Redo Log`采用简单的物理日志格式和高效的顺序IO,确保快速提交。通过不同的落盘策略,可在性能和安全性之间做出权衡。
1629 14
|
1月前
|
Python
log日志学习
【10月更文挑战第9天】 python处理log打印模块log的使用和介绍
30 0
|
1月前
|
数据可视化
Tensorboard可视化学习笔记(一):如何可视化通过网页查看log日志
关于如何使用TensorBoard进行数据可视化的教程,包括TensorBoard的安装、配置环境变量、将数据写入TensorBoard、启动TensorBoard以及如何通过网页查看日志文件。
193 0