【故障诊断】MySql 慢查询

一般来说,SQL的执行时间在几十毫秒~几百毫秒左右,如果一个简单的sql,操作一个数据量不大的表,执行时间还很长,肯定是不正常的。

Mysql提供了记录慢查询日志的功能,方便我们找出执行时间过长的SQL语句。
我们可以在测试的时候,或出现偶发性问题了,开启慢查询日志,定位出异常的SQL。

开启慢查询日志的记录功能

mysql支持记录两种慢查询日志(只能二选一):

  1. 设置一个时间的阀值,记录执行时间超过阀值的数据的SQL(如:记录执行时间超过1秒的SQL)
  2. 记录没有使用索引的SQL(此配置启用后,时间阀值等配置将失效)

日志的输出
慢查询日志可选择输出到文件数据库表
输出到数据库表,则会在mysql数据库的slow_log表中可以查询到
输出到文件,可以从mysql全局变量slow_query_log_file中获取文件的路径【show VARIABLES like '%slow_query_log_file%'
一般来说,输出到文件的开销更小,性能更好,也更加准确(例如:一个sql执行时间未0.1ms,但输出到table的时间可能就超出了0.1ms),但文件的形式不太适合分析,需要借助一些工具

示例1:记录超过时间阀值的SQL

-- 开启慢查询日志
set GLOBAL slow_query_log ='ON';
-- 输出日志到文件或,【TABLE】为表,【FILE】为文件,【FILE,TABLE】为同时输出表和文件
set GLOBAL log_output = 'FILE';

-- 开启慢查询日志的时间阀值,超过此时间被记录,,0代表记录所有,0.1代表100毫秒
set GLOBAL long_query_time = 0.1;

-- 查看慢查询时间的设置(set之后要重新连接才会看到值的变化)
show VARIABLES like '%long_query_time%';

示例2:记录没有使用索引的SQL(此配置一旦启用,则时间阀值相关失效)
在并发量大的情况下,记录未使用索引的慢查询日志可能给mysql带来更大的负担,因此Mysql提供了参数log_throttle_queries_not_using_indexes来限制每分钟记录到慢查询日志的数量

-- 开启慢查询日志
set GLOBAL slow_query_log ='ON';
-- 输出日志到文件或,【TABLE】为表,【FILE】为文件,【FILE,TABLE】为同时输出表和文件
set GLOBAL log_output = 'FILE';


set GLOBAL log-queries-not-using-indexes= 'ON';
-- 如下配置表示在每分钟最多记录5条慢查询日志,其他日志将被丢弃
set GLOBAL log_throttle_queries_not_using_indexes=5;

-- 查看参数设置
show VARIABLES like 'log-queries-not-using-indexes';

如上的参数设置都是设置到内存,重启后失效,也可以在my.conf文件中设置,重启后依然有效。

虽然一些书籍中提到,慢查询日志对mysql的负担是比较小的,一直开着日志记录影响也不大。
但我仍然建议,在生产环境,排查问题的时候开启,排查完毕后关闭。而开发环境和测试环境,可以一直开启,有问题的SQL应该在开发或测试的时候被发现。当然,如果遇到偶发性的不容易重现的问题,或者每隔一段时间有专人检查日志情况,可以尝试一直开启慢查询日志,但时间的阀值要慎重选择!

慢查询日志的查看与分析

如果log_output参数设置为输出到表,则在mysql.slow_log
关注2个字段,query_time为执行时间,sql_text为sql语句

image.png

SQL特征识别

一般来说,我们需要找出最慢的SQL,优化SQL,或者找到他对应的业务代码,优化业务代码
但是如果出现多条 差不多的SQL,即SQL结构一致,参数不一样,如下
SELECT * FROM test01 where sex=1 and age > 10 and name like '张%'
SELECT * FROM test01 where sex=2 and age > 20 and name like '李%'
这种情况,很可能就是一行业务代码,对于mysql来说,执行计划也是一样的
但在慢查询日志里面,就不好区分出来了,我们将数字、字符串替换为N'S',就可以视为1条SQL了
SELECT * FROM test01 where sex=N and age > N and name like 'S'

此时,就可以分组统计每个sql的执行数量,平均执行时间等信息了

**慢查询分析工具 percona-toolkit **

percona-toolkit是一个Mysql的命令行的工具套件,包含很多数据库操作相关的命令/工具
其中pt-query-digest工具可以很方便的分析慢查询日志

percona-toolkit 如下下载安装失败请参考官网下载

#下载工具(下载不了就去官网找新的下载链接)
wget percona.com/get/percona-toolkit.tar.gz
# 解压
tar zxf percona-toolkit*
# 进入解压文件夹
cd  percona-toolkit*

# 安装依赖
yum install perl-DBD-MySQL perl-Digest-MD5 perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker cpan  'perl(Data::Dumper)'

# 安装perl模块,制定依赖路径(执行报错就查百度,一般是缺少依赖)
perl Makefile.PL PREFIX=/usr/local/percona-toolkit
#安装(执行报错就查百度,一般是缺少依赖)
make && make install

其中pt-query-digest 是用来分析慢查询日志的工具
安装完毕之后,安装目录下的bin子目录就是各种命令了,如上make安装完毕后,安装目录为:/usr/local/percona-toolkit

使用【pt-query-digest 慢查询日志文件路径】来分析慢查询日志

image.png

第一个红框-总体概要信息
依次为
Current date:当前时间
Hostname: 主机名
Files: 文件路径
Overall: 分析的sql数量统计
Time range: sql的执行时间,最早时间和最晚时间

下面的表格分别表示
第一行 Exec time 执行时间,总共177s,最小执行时间6us,最大451ms,平均144us ,95%的执行时间424us,标准偏差899us,中位数93us
第二行 Lock time:锁占用的时间,各个列的含义同执行时间一样
第二行 Row sent:发送到客户端的行数,各个列的含义同执行时间一样
第二行 Row examine:select语句扫描行数,各个列的含义同执行时间一样
第二行 Query size:查询的字符数,各个列的含义同执行时间一样

第二个红框-SQL概要信息
统计了最慢的几个sql的信息,每一行一个SQL的信息
第一行数据释义:

  1. SQL语句大致为SELECT EP?_EQUIP_INFO
  2. 序号为1
  3. pt-query-digest为此SQL生成的唯一ID为0X0EE51CD49......... (Query ID字段),可搜索此ID找到本SQL对应的详细信息
  4. 此SQL总共执行1037142次 (Calls字段)
  5. 总共执行时间为100.3179秒,占本次分析的所有sql执行时间之和的56.8% (Response time字段)
    6.平均每次执行的响应时间为0.0001秒 (R/Call字段)

SQL详细信息
2个红框下面就是各个SQL的详细信息,如下图

image.png

第一个红框的内容同上面大致一致
下面的Database/Hosts/users 表示执行的数据库,主机号,用户等信息
第二个红框是时间分布的直方图,如图,表示大部分执行时间在10us100us,而1ms10ms 次数较少

下面的Tables部分是 pt-query-digest为你生成的SQl语句,用于分析SQL语句用的。
如第一行,显示表当前状态;第二行,显示建表语句;第三行,explain语句分析SQL

pt-query-digest工具还有很多参数,如从tcpdump文件、binlog文件中分析,筛选时间范围,将分析结果存入数据库等,可查阅官网资料、网上博客了解

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 202,607评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,047评论 2 379
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 149,496评论 0 335
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,405评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,400评论 5 364
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,479评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,883评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,535评论 0 256
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,743评论 1 295
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,544评论 2 319
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,612评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,309评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,881评论 3 306
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,891评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,136评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,783评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,316评论 2 342

推荐阅读更多精彩内容