mysql中的慢查询日志

本篇博文的mysql版本:5.7.26

操作系统版本:CentOS Linux release 7.7.1908 (Core)

一、什么是慢查询日志?

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


long_query_time的默认值为10,意思是运行10s(秒)以上的语句,就会被认作为是慢查询SQL语句。默认情况下,Mysql数据库并不启动慢查询日志,需要我们手动来设置这个参数。如果不是调优需要的话,一般不建议启动该参数,因为开启慢查询日志会或多或少带来一定的性能影响。慢查询日志支持将日志记录写入文件,也支持将日志记录写入数据库表。

二、慢查询日志相关参数

2.1、查看是否开启慢查询日志

mysql> show variables like '%slow_query_log%';
+---------------------+----------------------------------------+
| Variable_name       | Value                                  |
+---------------------+----------------------------------------+
| slow_query_log      | OFF                                    |
| slow_query_log_file | /usr/local/mysql/var/ecs-abcf-slow.log |
+---------------------+----------------------------------------+
2 rows in set (0.00 sec)

mysql>

可以看到slow_query_log的值目前是OFF 表示没有开启慢查询日志。slow_query_log_file表示的是慢查询日志文件的存放位置。

2.2、开启慢查询日志

①、只对当前数据库生效,如果mysql重启服务后,则会失效。 

set global slow_query_log = on;


②、如果需要永久生效,则mysql的配置文件必须增加如下配置

slow_query_log = 1

slow_query_log_file = 慢查询文件地址

2.3、开启了慢查询日志后,什么样的SQL才会记录到慢查询日志里面?

①、查看慢查询默认的阀值,超出次设定值的SQL就会被记录到慢查询日志中

mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

mysql> 

-- SQL执行的时间超过了上面默认设置的10秒钟,才会将该条SQL语句记录到慢查询日志里面


、修改慢查询默认的阀值(默认的10秒钟太扯淡了。。根本不可能忍受执行时间这么长的SQL语句。。)

set global long_query_time = 4;

-- 注意:要断开当前的mysql连接后,再次登录后 才能生效。


-- 重新连接mysql后 再次查看慢查询日志的阀值就是上面设置的4秒钟了,示例如下:

mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 4.000000 |
+-----------------+----------+
1 row in set (0.01 sec)

mysql>


③、模拟慢查询,并查看慢查询日志记录的慢查询sql

-- 模拟慢查询SQL:

mysql> select sleep(5);
+----------+
| sleep(5) |
+----------+
|        0 |
+----------+
1 row in set (5.00 sec)


-- 查看慢查询日志中记录的慢查询sql,可以自己直接去对应的慢查询日志文件中去看,也就是slow_query_log_file这个变量所显示的日志文件的路径。


-- 也可以通过show global status like '%slow_queries%';显示慢查询日志记录的数量,使用示例如下:

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

mysql>

三、慢查询日志分析工具(mysqldumpslow)

mysqldumpslow是官方提供的慢查询日志分析工具,所以你也不用去费劲巴拉的安装了,只要有mysql的环境基本就自带了(Linux操作系统中默认mysql是自带的,windows上默认是没有该工具的,如果想在windows上用,需要在windows上单独安装该工具,windows上安装该工具比较麻烦,所以一般都在Linux上使用该工具)。本文中该工具的路径是:/usr/local/mysql/bin/mysqldumpslow 

3.1、mysqldumpslow常用选项参数

-s 按照那种方式排序
    c:访问计数
    l:锁定时间
    r:返回记录
    al:平均锁定时间
    ar:平均访问记录数
    at:平均查询时间
    
-t 是top n的意思,意思是返回多少条数据。
-g 可以跟上正则匹配模式,大小写不敏感。

-- hlep 查看mysqldumpslow工具的更多命令行相关使用说明。

3.2、mysqldumpslow工具的使用示例

/usr/local/mysql/bin/mysqldumpslow -s r -t 10 /usr/local/mysql/var/ecs-abcf-slow.log  -- 获取返回记录集最多的10条SQL

/usr/local/mysql/bin/mysqldumpslow -s c -t 10 /usr/local/mysql/var/ecs-abcf-slow.log  -- 获取访问次数最多的10条SQL

/usr/local/mysql/bin/mysqldumpslow -s t -t 10 -g "left join" /usr/local/mysql/var/ecs-abcf-slow.log  -- 获取按照时间排序的前10条里面含有左连接的查询语句

/usr/local/mysql/bin/mysqldumpslow -s r -t 20 /usr/local/mysql/var/ecs-abcf-slow.log | more  -- 建议在使用这些命令时结合| 和 more 使用,否则有可能出现刷屏的情况


-- mysqldumpslow工具返回的查询结果示例如下:
[root@ecs-abcf ~]# /usr/local/mysql/bin/mysqldumpslow -s r -t 10 /usr/local/mysql/var/ecs-abcf-slow.log 

Reading mysql slow query log from /usr/local/mysql/var/ecs-abcf-slow.log
Count: 1  Time=5.00s (5s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select sleep(N)

Died at /usr/local/mysql/bin/mysqldumpslow line 161, <> chunk 1.

-- count:执行次数
-- time:执行时间
-- lock:锁定时间
-- rows:返回条数
-- root[root]@localhost:通过那个用户(这里也就是root)执行的
Count: 1  Time=5.00s (5s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost



-- 注意:mysqldumpslow工具的所在路径和慢查询日志文件(即:ecs-abcf-slow.log)换成你自己的实际路径。另外,该工具所得到的结果并不是真正的sql语句,上面中我们也看到了返回的确实不是真正的慢查询的sql语句。


mysqldumpslow慢查询分析命令详解

四、使用Show Profile进行分析

Show Profile是mysql提供的可以用来分析当前会话中sql语句执行的资源消耗情况的工具,可用于sql调优的测量。它会把一条sql在mysql当中每一个环节耗费的时间都记录下来。默认情况下处于关闭状态,并保存最近15次的运行结果。使用前需要先开启。

4.1、查看show profile是处于开启还是关闭

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

mysql> 

-- 处于OFF的状态,也就是关闭的状态

4.2、开启show profile

mysql> set profiling = on;  -- 开启show profile
Query OK, 0 rows affected, 1 warning (0.00 sec)


-- 再次查看show profile的状态 已经是ON的状态了,也就是开启的状态了

mysql> Show variables like 'profiling';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| profiling     | ON    |
+---------------+-------+
1 row in set (0.01 sec)

mysql>

4.3、查看show profile中记录的最近15条语句的执行结果

mysql> show profiles; -- 查看show profile记录的最近15条sql语句的执行结果耗时
+----------+------------+-----------------------------------------------+
| Query_ID | Duration   | Query                                         |
+----------+------------+-----------------------------------------------+
|        1 | 0.00139000 | Show variables like 'profiling'               |
|        2 | 0.00028000 | show databases                                |
|        3 | 0.00012575 | SELECT DATABASE()                             |
|        4 | 0.00022700 | show tables                                   |
|        5 | 0.00013125 | SELECT DATABASE()                             |
|        6 | 0.00006125 | show tabels                                   |
|        7 | 0.00022125 | show tables                                   |
|        8 | 3.28068025 | select * from emp                             |
|        9 | 0.00024800 | select * from emp where id = 666              |
|       10 | 0.00021600 | select * from emp where id = 888              |
|       11 | 0.03337025 | select * from emp where id > 3000000 limit 10 |
|       12 | 8.41861775 | select * from emp where id != 30000000        |
+----------+------------+-----------------------------------------------+
12 rows in set, 1 warning (0.00 sec)

mysql> 

-- 以上显示的就是最近15条sql的执行记录,有一些是系统的 无需关心 直接看你自己关心的sql即可,上面显示了每一条执行的sql,也显示了每一条sql的执行耗时,根据结果对相关sql进行优化即可。

-- 当然了,可以使用以下语句进行分析sql具体的消耗时间。比如说上面记录中Query_ID为12的sql语句执行耗时长达8秒,那我们下面分析该条sql的具体消耗时间(也就是下面的 4.4、诊断sql)。

4.4、诊断sql(查看某条sql的cpu、io等具体消耗时间)

mysql> show profile cpu,block io for query 12; -- 这个就是诊断profile里面记录的sql,你只需把最后一个12替换成你想诊断sql的Query_ID对应的数值即可。 
+----------------------+----------+----------+------------+--------------+---------------+
| Status               | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000059 | 0.000054 |   0.000000 |            0 |             0 |
| checking permissions | 0.000006 | 0.000005 |   0.000000 |            0 |             0 |
| Opening tables       | 0.000015 | 0.000015 |   0.000000 |            0 |             0 |
| init                 | 0.000020 | 0.000020 |   0.000000 |            0 |             0 |
| System lock          | 0.000008 | 0.000008 |   0.000000 |            0 |             0 |
| optimizing           | 0.000007 | 0.000007 |   0.000000 |            0 |             0 |
| statistics           | 0.020482 | 0.000414 |   0.000000 |          192 |             0 |
| preparing            | 0.000027 | 0.000021 |   0.000000 |            0 |             0 |
| executing            | 0.000003 | 0.000003 |   0.000000 |            0 |             0 |
| Sending data         | 8.392550 | 5.540109 |   0.000000 |       179456 |             0 |
| end                  | 0.000016 | 0.000010 |   0.000000 |            0 |             0 |
| query end            | 0.000015 | 0.000016 |   0.000000 |            0 |             0 |
| closing tables       | 0.000014 | 0.000013 |   0.000000 |            0 |             0 |
| freeing items        | 0.000021 | 0.000021 |   0.000000 |            0 |             0 |
| logging slow query   | 0.005349 | 0.000093 |   0.000000 |            8 |             8 |
| cleaning up          | 0.000026 | 0.000021 |   0.000000 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
16 rows in set, 1 warning (0.00 sec)

mysql>

-- Status:sql 语句执行的状态
-- Duration:sql 执行过程中每一个步骤的耗时
-- CPU_user:当前用户占有的cpu
-- CPU_system:系统占有的cpu
-- Block_ops_in:I/O 输入
-- Block_ops_out:I/O 输出


-- 注意:这就是一条sql语句在mysql里面完整的执行过程,而且每一步都能看到耗时耗了多久。


= = 上面那个诊断sql显示的结果有限。。找了一个结果更多地图片,示例图片如下:

m1.png

4.5、当诊断结果出现以下选项时, 需要进行优化

  • converting HEAP to MyIsAM    查询结果太大,导致内存都不够用了(内存装不下该结果),mysql往磁盘上存(搬)了。

  • Creating tmp table    创建临时表。copy数据到临时表,用完再进行删除。

  • Copying to tmp table on disk    把内存中临时表复制到磁盘,危险操作!!

  • Locked    被锁定。

注:以上四个中若出现一个或多个,表示sql语句必须优化。

五、全局查询日志

把所有执行的sql,全部都放在一个表里面,全部给记录了下来。全局查询日志只允许在测试环境用,不能在生产环境使用。在测试时,可以把所有执行的sql抓取出来查看。

5.1、设置并启用

set global general_log = on; -- 打开所有命令执行记录功能general_log, 所有语句: 成功和未成功的


set global log_output = 'TABLE'; -- 设置输出的目标,这里我们设置的输出的一个地址是输出(记录)到表里面去。


-- 此后所编写的sql语句将会记录到mysql库里的general_log表中

5.2、去表里面查看所有记录的执行sql(select * from mysql.general_log)

select * from mysql.general_log;

示例截图如下:

m2.png



二三十岁的时候,是最艰苦的一段岁月,承担着渐重的责任,拿着与工作量不匹配的薪水,艰难地权衡事业和感情......但你总得学着坚强,毕竟你不扬帆,没人替你起航。不要只因一次挫败,就迷失了最初想抵达的远方。



声明:禁止任何非法用途使用,凡因违规使用而引起的任何法律纠纷,本站概不负责。

扫码支持
扫码打赏,你说多少就多少

打开支付宝扫一扫,即可进行扫码打赏哦

精彩评论

全部回复12人评论7,777人参与