当前位置:首页 > 编程教程 > mysql技术文章 > Mysql开启慢SQL并分析原因

实例解析Mysql开启慢SQL

  • 发布时间:
  • 作者:码农之家
  • 点击:82

这篇文章主要知识点是关于Mysql、开启慢SQL、慢SQL、MySQL的一条慢SQL查询导致整个网站宕机的解决方法 的内容,如果大家想对相关知识点有系统深入的学习,可以参阅以下电子书

MySQL入门经典
MySQL入门经典完整影印版
  • 类型:MySQL入门大小:313.3 MB格式:PDF作者:王雨竹
立即下载

Mysql开启慢SQL并分析原因

第一步.开启mysql慢查询

方式一:修改配置文件

Windows:Windows 的配置文件为 my.ini,一般在 MySQL 的安装目录下或者 c:\Windows 下。

Linux:Linux 的配置文件为 my.cnf ,一般在 /etc 下

在 my.ini 增加几行:

[mysqlld] 
long_query_time=2 
#5.0、5.1等版本配置如下选项 
log-slow-queries="mysql_slow_query.log" 
#5.5及以上版本配置如下选项 
slow-query-log=On 
slow_query_log_file="mysql_slow_query.log" 
log-query-not-using-indexes 

第一句使用来定义查过多少秒的查询算是慢查询,我这里定义的是2秒

第二句使用来定义慢查询日志的路径(因为是windows,所以不牵涉权限问题)

第三句就是记录下没有使用索引的query

第二步:查看关于慢查询的状态

方式二:通过MySQL数据库开启慢查询

上文的配置需要重启mysql server进程mysqld才会生效。但是很多时候,尤其是产品运营环境,不希望每次修改都需要重新启动mysql服务器,也希望能在某些特定时间记 录。MySQL5.1给我们提供了更为灵活的运行时控制,使得你不必重新启动mysql服务器,也能选择性地记录或者不记录某些slow queries。

MySQL5.1中,提供了全局变量slow_query_logslow_query_log_file可以灵活地控制enable/disable慢查询。同时可以通过long_query_time设置时间

#//启用slow query记录
#注意:设置了slow_query_log全局变量, log_slow_queries也会隐性地跟着改变
mysql>set global slow_query_log=ON

不幸运的是,在MySQL5.0并没有提供类似的全局变量来灵活控制,但是我们可以通过将long_query_time设置得足够大来避免记录某些查询语句。比如

mysql>set global long_query_time = 3600;

mysql>set global log_querise_not_using_indexes = ON;

MySQL5.0, 不关服务的情况下,希望不记录日志的办法是将日志文件成为/dev/null的符号链接(symbolic link)。注意:你只需要在改变后运行FLUSH LOGS以确定MYSQL释放当前的日志文件描述符,重新把日志记录到/dev/null

和MySQL5.0不同,MySQL5.1可以在运行时改变日记行为,将日志记录到数据库表中。只要将mysql全局变量log_output设置为 TABLE即可。MySQL会将日志分别记录到表mysql.gengera_log和mysql.slow_log二张表中。但是,我们推荐将日志记录 在日记文件中。

mysql> show variables like ‘log_output'\G
Variable_name: log_output
Value: FILE
mysql>set global log_output='table';

缺陷与审记

虽然记录了slow query能够帮助你优化产品。但是MySQL目前版本,还有几大蹩足的地方。

  • 1.MySQL5.0版本, long_query_time时间粒度不够细,最小值为1秒。对于高并发性能的网页脚本而言,1秒出现的意义不大。即出现1秒的查询比较少。直到mysql5.1.21才提供更细粒度的long_query_time设定.
  • 2.不能将服务器执行的所有查询记录到慢速日志中。虽然MySQL普通日志记录了所有查询,但是它们是解析查询之前就记录下来了。这意味着普通日志没办法包含诸如执行时间,锁表时间,检查行数等信息。
  • 3.如果开启了log_queries_not_using_indexes选项,slow query日志会充满过多的垃圾日志记录,这些快且高效的全表扫描查询(表小)会冲掉真正有用的slow queries记录。比如select * from category这样的查询也会被记录下来。

通过microslow-patch补丁可使用更细的时间粒度,和记录所有执行过的sql语句。不过,使用这个补订不得不自己编译MySQL,出于稳定性考滤,我们推荐在开发测试环境,可以打上这个补丁,享受这个补丁带来的便利。在运营环境尽量不要这么做…

第二步.验证慢查询是否开启

执行如下SQL语句来查看mysql慢查询的状态

执行结果会把是否开启慢查询、慢查询的秒数、慢查询日志等信息打印在屏幕上。

/*查看慢查询时间 */ 
show variables like "long_query_time";默认10s 
/*查看慢查询配置情况 */ 
show status like "%slow_queries%"; 
/*查看慢查询日志路径 */ 
 show variables like "%slow%"; 

第三步:执行一次慢查询操作

其实想要执行一次有实际意义的慢查询比较困难,因为在自己测试的时候,就算查询有20万条数据的海量表,也只需要0.几秒。我们可以通过如下语句代替:

SELECT SLEEP(10);

第四步:查看慢查询的数量

通过如下sql语句,来查看一共执行过几次慢查询:

show global status like '%slow%';

mysql日志的配置:

注意:这些日文件在mysql重启的时候才会生成 
#记录所有sql语句 
log=E:/mysqllog/mysql.log 
#记录数据库启动关闭信息,以及运行过程中产生的错误信息 
log-error=E:/mysqllog/myerror.log 
# 记录除select语句之外的所有sql语句到日志中,可以用来恢复数据文件 
log-bin=E:/mysqllog/bin 
#记录查询慢的sql语句 
log-slow-queries=E:/mysqllog/slow.log  
#慢查询时间 
long_query_time=2 

第四步:分析慢查询日志

方式一:通过工具分析

MySQL自带了mysqldumpslow工具用来分析slow query日志,除此之外,还有一些好用的开源工具。比如MyProfi(下载地址:http://sourceforge.net/projects/myprofi/)、mysql-log-filter,当然还有mysqlsla

以下是mysqldumpslow常用参数说明,详细的可应用mysqldumpslow -help查询。

  • -s,是表示按照何种方式排序,c、t、l、r分别是按照记录次数、时间、查询时间、返回的记录数来排序(从大到小),ac、at、al、ar表示相应的倒叙。
  • -t,是top n的意思,即为返回前面多少条数据。
  • -g,后边可以写一个正则匹配模式,大小写不敏感。

接下来就是用mysql自带的慢查询工具mysqldumpslow分析了(mysql的bin目录下),我这里的日志文件名字是host-slow.log。

列出记录次数最多的10个sql语句

mysqldumpslow -s c -t 10 host-slow.log

列出返回记录集最多的10个sql语句

mysqldumpslow -s r -t 10 host-slow.log

按照时间返回前10条里面含有左连接的sql语句

mysqldumpslow -s t -t 10 -g "left join" host-slow.log

使用mysqldumpslow命令可以非常明确的得到各种我们需要的查询语句,对MySQL查询语句的监控、分析、优化起到非常大的帮助。

方式二:直接分析mysql慢查询日志

日志部分内容如下:

# Time: 121017 17:38:54 
# User@Host: root[root] @ localhost [127.0.0.1] 
# Query_time: 3.794217 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 4194304 
SET timestamp=1350466734; 
select * from wei where text='orange'; 
# Time: 121017 17:46:22 
# User@Host: root[root] @ localhost [127.0.0.1] 
# Query_time: 3.819219 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 4194304 
SET timestamp=1350467182; 
select * from wei where text='xishizhaohua'; 

其实定位到了慢查询语句就已经完成了一大不了,执行explain或者desc命令查看慢查询语句,如下图:

Mysql开启慢SQL并分析原因

问题很明显,解决方式也很明显,建索引了。

mysql> create index text_index on wei(text);  
Query OK, 4194304 rows affected (1 min 58.07 sec)  
Records: 4194304 Duplicates: 0 Warnings: 0 

然后在执行查询操作,用时明显少了很多。

mysql> select * from wei where text='orange'; 
+---------+--------+ 
| id   | text  | 
+---------+--------+ 
| 4103519 | orange | 
+---------+--------+ 
1 row in set (0.33 sec) 

Slow Query日志,虽然帮助你记录了那些执行过了的SQL语句。但它不是万能的,意义可能没有你想象的那么大。它只告诉了你哪些语句慢,但是为什么慢?具体 原因,还是需要你自己去分析,不断的调试。也许,你只需要换一条更有效的sql语句,也许你只需简单地增加一个索引,但也有可能你需要调整你应用程序的设 计方案。比如,上面那条语句是很明显,它检查了600多万行数据。不幸的是,并不是每条语句都这么明显。也许还有别的原因,比如:

  • *锁表了,导致查询处于等态状态。lock_time显示了查询等待锁被翻译的时间
  • *数据或索引没有被缓存。常见于第一次启动服务器或者服务器没有调优
  • *备份数据库,I/O变慢
  • *也许同时运行了其它的查询,减少了当前查询

所以,不要过于紧张日志文件某条记录,而应该理性地审记,找出真正的原因。如果经常出现的slow query需要特别注意。如果个别出现,则做一些常规检查即可。我们建议,统计并且形成基准报告,进行比较排除,比胡乱瞎撞有用。希望大家不要在这部分过于浪费时间与精力。

总结

以上就是这篇文章的全部内容了,希望本文的内容对大家的学习或者工作具有一定的参考学习价值,谢谢大家对码农之家的支持。如果你想了解更多相关内容请查看下面相关链接

MySQL的一条慢SQL查询导致整个网站宕机的解决方法

直接切入正题吧:

通常来说,我们看到的慢查询一般还不致于导致挂站,顶多就是应用响应变慢
不过这个恰好今天被我撞见了,一个慢查询把整个网站搞挂了
先看看这个SQL张撒样子:

# Query_time: 70.472013 Lock_time: 0.000078 Rows_sent: 7915203 Rows_examined: 15984089 Rows_affected: 0
# Bytes_sent: 1258414478
use js_sku;
SET timestamp=1465850117;
SELECT 
ss_id, ss_sa_id, ss_si_id, ss_av_zid, ss_av_fid, ss_artno,
ss_av_zvalue, ss_av_fvalue, ss_av_zpic, ss_av_fpic, ss_number,
ss_sales, ss_cprice, ss_price, ss_stock, ss_orderid, ss_status,
ss_add_time, ss_lastmodify
FROM js_sgoods_sku
WHERE ss_si_id = 0 AND ss_status > 0
ORDER BY
ss_orderid DESC, ss_av_fid ASC;
这里贴出来的就是 mysql slow log 的信息,查询时间用了高达 70s!!
看到慢查询我们一般第一反应是这个 语句没有用到索引? 或者是索引不合理么? 那我们会去看看执行计划:

mysql> explain SELECT 
-> ss_id, ss_sa_id, ss_si_id, ss_av_zid, ss_av_fid, ss_artno,
-> ss_av_zvalue, ss_av_fvalue, ss_av_zpic, ss_av_fpic, ss_number,
-> ss_sales, ss_cprice, ss_price, ss_stock, ss_orderid, ss_status,
-> ss_add_time, ss_lastmodify
-> FROM js_sgoods_sku
-> WHERE ss_si_id = 0 AND ss_status > 0
-> ORDER BY
-> ss_orderid DESC, ss_av_fid ASC;
+----+-------------+---------------+------+---------------+----------+---------+-------+---------+-----------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+---------------+------+---------------+----------+---------+-------+---------+-----------------------------+
| 1 | SIMPLE | js_sgoods_sku | ref | ss_si_id | ss_si_id | 4 | const | 9516091 | Using where; Using filesort |
+----+-------------+---------------+------+---------------+----------+---------+-------+---------+-----------------------------+
1 row in set (0.00 sec)

这个看起来似乎用到了索引,可是为什么扫描到行还是这么多呢? 那我们就去看看表结构了,期望能从中找到点有价值的东西:
我们看到如下可用信息:
KEY `ss_si_id` (`ss_si_id`,`ss_av_zid`,`ss_av_fid`) USING BTREE,
`ss_si_id` int(11) unsigned NOT NULL DEFAULT '0' COMMENT '对应js_sgoods_info.si_id',

我们看到 索引似乎还能比较能够接受,但是我们看到 这个 ss_si_id 这个字段实际上是 goods_info 表的主键,也就是说它的离散程度应该是很大的,也就是区分度很大。
其实到这一步我们基本上可以认为 是由于我们这个表里边有很多 ss_si_id=0 导致,不过我们可以进一步的来证实我们的猜想:

1. 首先我们可以先确定我们的统计信息没有问题
2. 其次我们再count ss_si_id=0 的这个值有多少数据,来进一步验证我们的猜想。

那么我们先查看以下这个索引的统计信息:
xiean@localhost:js_sku 03:27:42>show index from js_sgoods_sku;
+---------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+---------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| js_sgoods_sku | 0 | PRIMARY | 1 | ss_id      | A | 18115773 | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | ss_si_id | 1 | ss_si_id   | A  | 1811577  | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | ss_si_id | 2 | ss_av_zid | A | 6038591  | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | ss_si_id | 3 | ss_av_fid | A | 18115773 | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | IDX_001 | 1 | ss_sa_id | A | 3623154   | NULL | NULL | | BTREE | | |
+---------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+

那么可以看到以下问题:
我们的ss_si_id 这个字段并没有我们表面上看到的 因为关联了某个表的主键,它的Cardinality 值就应该接近于 PRIMARY 的值。而是差别比较大的,难道是 索引的统计信息不准确? 那我们尝试重新收集下索引的统计信息:
xiean@localhost:js_sku 03:27:47>analyze table js_sgoods_sku;
+----------------------+---------+----------+----------+
| Table | Op | Msg_type | Msg_text |
+----------------------+---------+----------+----------+
| js_sku.js_sgoods_sku | analyze | status | OK |
+----------------------+---------+----------+----------+

but ,我们再次查看 这些索引的统计信息:
xiean@localhost:js_sku 03:28:14>show index from js_sgoods_sku;
+---------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+---------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| js_sgoods_sku | 0 | PRIMARY | 1 | ss_id      | A | 18621349 | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | ss_si_id | 1 | ss_si_id    | A | 1551779  | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | ss_si_id | 2 | ss_av_zid | A | 6207116   | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | ss_si_id | 3 | ss_av_fid | A | 18621349 | NULL | NULL | | BTREE | | |
| js_sgoods_sku | 1 | IDX_001 | 1 | ss_sa_id | A | 3724269   | NULL | NULL | | BTREE | | |
+---------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+

我们可以看到 ss_si_id 的离散程度(Cardinality) 没有增加反而有向下波动的趋势,因为这个信息是采集部分页的来的,而每个页上边数据分布是不一样的,导致我们这个索引收集的统计信息就回有所变化。

好吧,到这里我们可以认为我们的 统计信息没有失效,那么我们就看数据的分别情况咯:

+--------------++----------++------------------+
| ss_si_id=0; || count(*) || 7994788/19048617 |
+--------------++----------++------------------+
| 7994788     || 19048617 ||    0.4197           |
+--------------++----------++------------------+

额,不看不知道,一看吓一跳:我们这个表里边 存在有大量的 ss_si_id=0 的情况,占了整个表数据量的 41% !!!


好吧问题找到了,那么接下来我们需要知道,为什么这个SQL语句会导致挂站呢?

我们通过观看应用程序服务器的监控看到一些信息:我们的 goods_service 这个服务异常:异常情况如下:

1. cpu 长期占用100% + 
2. jstatck pid 无法dump 内存堆栈信息,必须强制dump -F
3. dump 出来的内存信息发现,这个进程里边所有线程 均处于 BLOCKED 状态
4. 通过jstat -gcutil 看到 FGC 相当频繁,10s左右就FGC一次
5. 内存占用超过了分配的内存

那么最终的原因就是因为上边的慢查询 查询了大量数据(最多有700w行数据),导致goods_service 内存暴涨,出现服务无法响应,进一步的恶化就是挂占


OK,知道了为什么会挂占,那么我们是如何解决这个问题的呢?
既然我们知道是由于查询了 ss_si_id=0 导致的,那么我们屏蔽掉这个SQL不就好了么。屏蔽的办法可以有多种:
1. 我们程序逻辑判断一下这类型的 查询 如果 有查询 ss_si_id=0 的一律封杀掉
2. 我们改改SQL配置文件,修改SQL语句

我们发现DB服务器上存在大量的 这个慢查询,而且DB服务器负载已经从 0.xx 飙升到了 50+ 了,随之而来的连接数也飙升的厉害, 如果再不及时处理,估计DB服务器也挂掉了

 

那么我们最终采取以下处理办法:
1.运维配合研发修改SQL语句 我们在这个WHERE 条件中添加了一个条件: AND ss_si_id <> 0 ,在MySQL之行计划层屏蔽掉此SQL;
2.DBA 开启kill 掉这个查询语句,避免DB服务器出现down机的情况,当然这个就用到了我们的 pt-kill 工具,不得不说这个工具相当好用


总结(经验与教训):
1.类似这种查询 default 值的 SQL ,我们应该从源头上杜绝这类查询
2.限制查询结果集大小,避免因查询结果集太大导致服务死掉

以上就是本次给大家分享的关于java的全部知识点内容总结,大家还可以在下方相关文章里找到相关文章进一步学习,感谢大家的阅读和支持。

Mysql开启慢SQL 相关电子书
学习笔记
网友NO.970373

MySQL的一条慢SQL查询导致整个网站宕机的解决方法

直接切入正题吧: 通常来说,我们看到的慢查询一般还不致于导致挂站,顶多就是应用响应变慢 不过这个恰好今天被我撞见了,一个慢查询把整个网站搞挂了 先看看这个SQL张撒样子: # Query_time:70.472013Lock_time: 0.000078 Rows_sent: 7915203 Rows_examined: 15984089 Rows_affected: 0 # Bytes_sent: 1258414478 use js_sku; SET timestamp=1465850117; SELECT ss_id, ss_sa_id, ss_si_id, ss_av_zid, ss_av_fid, ss_artno, ss_av_zvalue, ss_av_fvalue, ss_av_zpic, ss_av_fpic, ss_number, ss_sales, ss_cprice, ss_price, ss_stock, ss_orderid, ss_status, ss_add_time, ss_lastmodify FROM js_sgoods_sku WHERE ss_si_id = 0 AND ss_status 0 ORDER BY ss_orderid DESC, ss_av_fid ASC; 这里贴出来的就是 mysql slow log 的信息,查询时间用了高达 70s!! 看到慢查询我们一般第一反应是这个 语句没有用到索引? 或者是索引不合理么? 那我们会去看看执行计划: mysql explain SELECT - ss_id, ss_sa_id, ss_si_……

网友NO.139622

MySQL利用profile分析慢sql详解(group left join效率高于子查询)

使用profile来分析慢sql mysql 的 sql 性能分析器主要用途是显示 sql 执行的整个过程中各项资源的使用情况。分析器可以更好的展示出不良 SQL 的性能问题所在。 最近遇到一个查询比较慢的sql语句,用了子查询,大概需要0.8秒左右,这个消耗时间比较长,严重影响了性能,所以需要进行优化。单独查询单表或者子查询记录都很快,下面来看看详细的介绍。 开启profile mysql show profiles; -- 查看是否开启Empty set, 1 warning (0.00 sec)mysql set profiling=1; -- 开启profileQuery OK, 0 rows affected, 1 warning (0.00 sec)mysql show profiles;Empty set, 1 warning (0.00 sec)mysql 执行查询,方便profile跟踪记录 mysql SELECT SQL_NO_CACHE - t1.amount, - t1.count, - t1.date , - (SELECT (CONCAT(t2.APPROVE_ID,'|' ,t2.PATH)) AS RECEIPT FROM TB_BIS_MERCHANT_SETTLEMENT t2 WHERE t2.`MERCHANT_ID` = t1.`MERCHANT_ID` AND t2.`DATE`=t1.DATE AND t2.APPROVE_STATUS=5) AS receipts - FROM……

<
1
>

Copyright 2018-2020 www.xz577.com 码农之家

投诉 / 推广 / 赞助:QQ:520161757