暂无图片
暂无图片
暂无图片
暂无图片
暂无图片
首页 / 记一次MySQL慢查询与清理的探索

记一次MySQL慢查询与清理的探索

IT敢客 2018-08-07
134

之前给公司的 grafana 上配置了各种监控图表，发现有一个 Mysql slow query 的监控项下，有一台 AliSQL 的 Slow query 比较大，其他都很小，如下图所示：

       再加上之前这台机器也确实报警过几次 CPU over load 的警告，想必和这个脱不了干系，于是就准备摸索一番这个东东！

从一些文章资料中了解到 Mysql 慢查询的相关记录：

general log&slow query log

对于 MySQL 的一般查询日志和慢查询日志，开启比较简单，其中公用的一个参数是 log_output，log_output 控制着慢查询和一般查询日志的输出方向可以是表（mysql.general_log,mysql.slow_log）或者文件（有参数 general_log_file 和 slow_query_log_file 配置决定）或者同时输出到表和文件；log_output：日志存储方式。log_output=’FILE’表示将日志存入文件，默认值是’FILE’。log_output=’TABLE’表示将日志存入数据库，这样日志信息就会被写入到 mysql.slow_log 表中。MySQL 数据库支持同时两种日志存储方式，配置的时候以逗号隔开即可，如：log_output=’FILE,TABLE’。日志记录到系统的专用日志表中，要比记录到文件耗费更多的系统资源，因此对于需要启用慢查询日志，又需要能够获得更高的系统性能，那么建议优先记录到文件。

但是两者受 log_output 参数影响，输出的目标总是一致的，也就是要么都写入表，或者要么都写入文件，不会一个输出到表，一个输出到文件。这是因为他们都受 log_output 参数控制，这个参数只能是一个值！

  1. --slow log 相关参数
  2. select * from performance_schema.global_variables where variable_name in ('slow_query_log','log_output','slow_query_log_file','long_query_time')
  3.  
  4. --general log 相关参数
  5. select * from performance_schema.global_variables where variable_name in ('general_log','log_output','general_log_file')
复制

对于上述两种日志，系统默认不会清理，因此在开启了相关日志之后，需要人为清理。

如何清理历史 general log&slow query log

1，当输出目标为表的时候

无法直接删除，如果直接删除的话，会出现“ERROR 1556 (HY000): You can’t use locks with log tables.”的错误提示

以 general log 为例，需要先关闭 general_log，然后重命名 general_log 这个表，

在对重命名之后的表执行删除，最后在重命名回来，最后开启 general_log（如果有必要的话）

  1. SET GLOBAL general_log = 'OFF';
  2. RENAME TABLE general_log TO general_log_temp;
  3. DELETE FROM general_log_temp WHERE event_time < DATE(NOW());
  4. RENAME TABLE general_log_temp TO general_log;
  5. SET GLOBAL general_log = 'ON';
  6.  
  7. --slow log 同理
  8. SET GLOBAL slow_query_log = 'OFF';
  9. RENAME TABLE slow_log TO slow_log_temp;
  10. DELETE FROM slow_log_temp WHERE start_time < DATE(NOW());
  11. RENAME TABLE slow_log_temp TO slow_log;
  12. SET GLOBAL slow_query_log = 'ON';
复制

如果对重命名之后的表（general_log 或者是 slow_log）没有再次重命名回来，会发生什么？

参考如下截图，如果没有找到对应的表（general_log 或者是 slow_log），在输出目标为表的情况下，会提示无法找到对应的表，将无法开启对应的日志

2，当输出目标为文件的时候

当输出目标为文件的时候，在 linux 下，直接使用 rm 命名删除即可，如果在开启了一般查询日志或者是慢查询日志，删除对应的日志文件，并不影响数据库的正常使用。网上有说需要停止 MySQL 服务然后重命名文件然后在创建新的文件啥的，在 Linux 下并不是必须的，不知道在 windows 下是什么情况，没兴趣试。

当然也不是说就建议始终这种暴力的方式清理日志文件，在 Linux 下，删除了默认的日志文件（或者重命名了原日志文件），要想再次生成日志文件

  • 可以使用 mysqladmin flush-logs

  • 使用 SQL 命令 flush slow logs;flush general logs;

  • 重启 MySQL 服务

均可重新生成对应的日志文件。

注意：当对应的文件是存在的时候，上述命名执行之后是没有影响的（也不会清理对应的日志文件）

当输出目标为表的时候的解析

　　不管是 general_log 或者是 slow_log，对应的 SQL 语句都是二进制格式的，需要使用 convert(sql_text using UTF8)做一个转换，才变得具有可读性。

 

开启慢查询功能 
slow_query_log_file 慢查询日志文件路径 
slow_query_log 用于指定是否打开慢查询日志 
long_query_time 超过多少秒的查询就写入日志 
log_output=file 必须指定 file 或者是 table 如果是 table 则慢查询信息会保存到 mysql 库下的 slow_log 表中。这点要清楚。默认值是 file
打开 my.cnf 配置文件，加入以下代码： 

  1. log_output=file
  2. slow_query_log=on ;
  3. slow_query_log_file = /tmp/mysql-slow.log
  4. long_query_time = 2
复制

保存退出，重启 MySQL 即可。 

long_query_time = 1 #定义超过 1 秒的查询计数到变量 Slow_queries。 
slow_query_log_file  = usr/local/mysql/data/slow.log #定义慢查询日志路径。 
log_queries_not_using_indexes #未使用索引的查询也被记录到慢查询日志中（可选）。尽量少使用。 
mysql 自带了一个查看慢日志的工具 mysqldumpslow。 

执行 mysqldumpslow –h 可以查看帮助信息。 

主要介绍两个参数-s 和-t 
-s 这个是排序参数，可选的有： 
al: 平均锁定时间 
ar: 平均返回记录数 
at: 平均查询时间 
c: 计数 
l: 锁定时间 
r: 返回记录 
t: 查询时间 
-t n 显示头 n 条记录。 
实例： 
mysqldumpslow -s c -t 20 host-slow.log 
mysqldumpslow -s r -t 20 host-slow.log 
上述命令可以看出访问次数最多的 20 个 sql 语句和返回记录集最多的 20 个 sql。 
mysqldumpslow -t 10 -s t -g “left join” host-slow.log 
这个是按照时间返回前 10 条里面含有左连接的 sql 语句。 
用了这个工具就可以查询出来那些 sql 语句是性能的瓶颈，进行优化，比如加索引，该应用的实现方式等。

开启 general log 会将所有到达 MySQL Server 的 SQL 语句记录下来。一般不会开启开功能，因为 log 的量会非常庞大。但个别情况下可能会临时的开一会儿 general log 以供排障使用。 
相关参数一共有 3：general_log、log_output、general_log_file

show variables like ‘general_log’; — 查看日志是否开启
show variables like ‘log_output’; — 看看日志输出类型 table 或 file
show variables like ‘general_log_file’; — 看看日志文件保存位置
set global general_log_file=’tmp/general.lg’; — 设置日志文件保存位置
set global general_log=on; — 开启日志功能

set global log_output=’table’; — 设置输出类型为 table
set global log_output=’file’; — 设置输出类型为 file

set global long_query_time=2;          //设置成 2 秒，加上 global,下次进 mysql 已然生效  

好了以上是整理的慢查询和普通查询日志的知识点！那么运用到自己的服务器上实践一下！

首先登陆 Mysql 查询 slow_query_log 的设置信息

  1. mysql> show variables where Variable_name in ("slow_query_log","slow_query_log_file","log_slow_slave_statements","log_slow_admin_statements","long_query_time","log_queries_not_using_indexes","log_throttle_queries_not_using_indexes","log_output"); 
  2. +----------------------------------------+-------------------------------------------+
  3. | Variable_name                          | Value                                     |
  4. +----------------------------------------+-------------------------------------------+
  5. | log_output                             | FILE                                      |
  6. | log_queries_not_using_indexes          | OFF                                       |
  7. | log_slow_admin_statements              | OFF                                       |
  8. | log_slow_slave_statements              | OFF                                       |
  9. | log_throttle_queries_not_using_indexes | 0                                         |
  10. | long_query_time                        | 1.000000                                  |
  11. | slow_query_log                         | OFF                                       |
  12. | slow_query_log_file                    | /home/data/mysqldb/AliSQLServer7-slow.log |
  13. +----------------------------------------+-------------------------------------------+
  14. 8 rows in set (0.00 sec)
  15.  
  16. mysql> 
复制

从以上设置上看，慢查询日志是关闭了的，查询一下慢查询的状态

注意：这时候 slow_query_log=off;虽然设置了 slow_query_log_file=/home/data/mysqldb/AliSQLServer7-slow.log;但是这个文件这时候是不存在的，因为没有开启慢查询记录导致的，只有 slow_query_log=on 这个文件才生成！

  1. mysql> show global status like '%Slow_queries%';
  2. +---------------+--------+
  3. | Variable_name | Value  |
  4. +---------------+--------+
  5. | Slow_queries  | 904021 |
  6. +---------------+--------+
  7. 1 row in set (0.00 sec)
  8.  
  9. mysql> 
复制

查询出这个 Slow_queries 的值确实有 900 多 K，这也就是 grafana 上显示的值。

这时候临时开启一下慢查询日志。

  1. mysql> set global slow_query_log =on;
  2. Query OK, 0 rows affected (0.01 sec)
  3. mysql> show variables like '%slow_query_log%';
  4. +---------------------+-------------------------------------------+
  5. | Variable_name       | Value                                     |
  6. +---------------------+-------------------------------------------+
  7. | slow_query_log      | ON                                        |
  8. | slow_query_log_file | /home/data/mysqldb/AliSQLServer7-slow.log |
  9. +---------------------+-------------------------------------------+
  10. 2 rows in set (0.00 sec)
复制

然后继续观察/home/data/mysqldb/AliSQLServer7-slow.log 文件的内容

  1. [root@AliSQLServer7 mysqldb]# tailf AliSQLServer7-slow.log
  2. # User@Host: bems[bems] @  [172.16.0.158]  Id: 1525727
  3. # Query_time: 2.229743  Lock_time: 0.000062 Rows_sent: 1  Rows_examined: 54839
  4. use goodcms;
  5. SET timestamp=1533521721;
  6. SELECT count(0) FROM item WHERE `status` = '1' AND title LIKE '%袜子%' ESCAPE '^';
  7. # Time: 180806 10:15:34
  8. # User@Host: bems[bems] @  [172.16.0.162]  Id: 1525724
  9. # Query_time: 2.224943  Lock_time: 0.000066 Rows_sent: 1  Rows_examined: 54840
  10. SET timestamp=1533521734;
  11. SELECT count(0) FROM item WHERE `status` = '1' AND title LIKE '%袜子%' ESCAPE '^';
  12. # Time: 180806 10:16:40
  13. # User@Host: bems[bems] @  [172.16.0.158]  Id: 1525727
  14. # Query_time: 2.234996  Lock_time: 0.000073 Rows_sent: 1  Rows_examined: 54847
  15. SET timestamp=1533521800;
  16. SELECT count(0) FROM item WHERE `status` = '1' AND title LIKE '%吉列剃须刀%' ESCAPE '^';
  17. # Time: 180806 10:16:53
  18. # User@Host: bems[bems] @  [172.16.0.158]  Id: 1525727
  19. # Query_time: 2.224175  Lock_time: 0.000094 Rows_sent: 1  Rows_examined: 54848
  20. SET timestamp=1533521813;
  21. SELECT count(0) FROM item WHERE `status` = '1' AND title LIKE '%剃须刀%' ESCAPE '^';
  22. # Time: 180806 10:17:08
  23. # User@Host: bems[bems] @  [172.16.0.158]  Id: 1525727
  24. # Query_time: 2.258084  Lock_time: 0.000117 Rows_sent: 30  Rows_examined: 55358
复制

从以上看出，这些 sql 查询都用 2 秒多钟，所以记录为慢查询了！

这里我继续把 long_query_time 设置为 3 秒，继续观察，发现还是有一些 SQL 的查询是用了更多时间，5 秒多

  1. [root@AliSQLServer7 ~]# tailf /home/data/mysqldb/AliSQLServer7-slow.log
  2. # Time: 180806 12:06:04
  3. # User@Host: bems[bems] @  [172.16.0.158]  Id: 1536900
  4. # Query_time: 2.204217  Lock_time: 0.000061 Rows_sent: 1  Rows_examined: 54556
  5. SET timestamp=1533528364;
  6. SELECT count(0) FROM item WHERE `status` = '1' AND title LIKE '%篮球鞋%' ESCAPE '^';
  7. # Time: 180806 12:06:10
  8. # User@Host: bems[bems] @  [172.16.0.158]  Id: 1536900
  9. # Query_time: 5.572363  Lock_time: 0.000092 Rows_sent: 9  Rows_examined: 356490
  10. SET timestamp=1533528370;
  11. SELECT * FROM item WHERE `status` = '1' AND title LIKE '%篮球鞋%' ESCAPE '^'  ORDER BY soft_num DESC LIMIT 10;
复制

所以主要原因还是开发写的 SQL 上这个 like 用的太多了！

然后 grafana 上显示 900 多 k 的值其实是慢查询的总条数，也就是 show variables like ‘%slow_query_log%’;查询出来的值。

然后我继续用 mysqldumpslow 命令来看看具体的慢查询最高的一些记录

查看查询时间最高的 5 条记录

  1. [root@AliSQLServer7 ~]# mysqldumpslow -s at -t 5 /home/data/mysqldb/AliSQLServer7-slow.log
  2.  
  3. Reading mysql slow query log from /home/data/mysqldb/AliSQLServer7-slow.log
  4. Count: 1  Time=8.21s (8s)  Lock=0.00s (0s)  Rows=10.0 (10), bems[bems]@[172.16.0.162]
  5.   SELECT * FROM item WHERE `status` = 'S' AND title LIKE 'S' ESCAPE 'S'  ORDER BY current_sales ASC LIMIT N
  6.  
  7. Count: 3  Time=4.29s (12s)  Lock=0.00s (0s)  Rows=9.3 (28), bems[bems]@2hosts
  8.   SELECT * FROM item WHERE `status` = 'S' AND title LIKE 'S' ESCAPE 'S'  ORDER BY soft_num DESC LIMIT N
  9.  
  10. Count: 1  Time=4.17s (4s)  Lock=0.00s (0s)  Rows=10.0 (10), bems[bems]@[172.16.0.158]
  11.   SELECT * FROM item WHERE `status` = 'S' AND title LIKE 'S' ESCAPE 'S'  ORDER BY current_sales DESC LIMIT N
  12.  
  13. Count: 10  Time=3.75s (37s)  Lock=0.00s (0s)  Rows=9.9 (99), bems[bems]@2hosts
  14.   SELECT * FROM item WHERE `status` = 'S' AND title LIKE 'S' ESCAPE 'S'  ORDER BY soft_num DESC LIMIT N, N
  15.  
  16. Count: 1  Time=3.58s (3s)  Lock=0.00s (0s)  Rows=29.0 (29), bems[bems]@[172.16.0.162]
  17.   SELECT id,title,item_id,monitor,stick,soft_num FROM item WHERE `status` = 'S' AND ( end_time < (unix_timestamp()*N) OR item_id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N) )
复制

发现这些 SQL 中都带有 like。好了，拿这些证据去找开发麻烦了  ，他们不得不承认了！


mysql
文章转载自IT敢客，如果涉嫌侵权，请发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

评论