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.logCount: 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语句。 |
|---|
四、使用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 profileQuery 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显示的结果有限。。找了一个结果更多地图片，示例图片如下：
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;
运行如下
原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。
如有侵权，请联系 cloudcommunity@tencent.com 删除。
原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。
如有侵权，请联系 cloudcommunity@tencent.com 删除。
腾讯云开发者
