MySQL如何由慢查询寻问题SQL

简书不维护了,欢迎关注我的知乎:[波罗学的个人主页](https://www.zhihu.com/people/xue-jian-27/activities)

最近一直在研究学习MySQL的性能优化。影响MySQL性能的原因来自多个方面,包括硬件、操作系统、系统配置、表结构以及SQL语句和索引。就优化效果与成本的考量,SQL语句与索引的优化是我们最先需要考虑的优化策略,而这类优化的前提需要我们先找出有问题的SQL。

我们如何找出有问题的SQL呢?总结有以下几种方式:

通过分析慢查询日志,慢查询日志专注于慢SQL记录,寻找问题SQL最佳途径

通过MySQL性能监控,如引言所述,性能问题多样,未必SQL问题

通过应用层性能剖析,考量范围更大,可能是如代码设计、外部服务等非MySQL问题

通过用户反馈,比如哪些页面存在严重卡顿,此方式太被动,通过反馈的问题基本已严重影响了用户体验

以上几种最直接有效的方式就是分析MySQL慢查询日志。这是一项技术活,但对你而言或许是一项体力活。本篇文章重点在于如何利用慢查询日志找出问题SQL。

实验环境:Centos7 + MySQL-5.6.34

开启慢查询日志

主要是介绍一些慢查询日志的配置选项:

slow_query_log:是否开启慢查询,0或者OFF为关闭,1或者ON为开启,默认值为OFF,即为关闭

slow_query_log_file:指定慢查询日志存放路径

long_query_time:大于等于此时间记录慢查询日志,精度可达微秒级别,默认为10s。当设置为0时表示记录所谓查询记录

通过如下命令查看当前配置:

其他相关配置项

log_queries_not_using_indexes:是否记录未使用索引的查询,默认OFF

log_throttle_queries_not_using_indexes:每分钟允许写入到慢查询日志的未使用索引的语句,MySQL 5.6.5新增,默认为0,无限制

log_slow_admin_statements:是否记录管理类指令,默认OFF

b. 配置方式:

第一种方式set global, 请注意重启MySQL后配置无效。 配置如下:

mysql>set global slow_query_log=ON;

mysql>set global long_query_log=0.100000;

mysql>set global slow_query_log_file

第二种方式配置文件

可通过如下命令查看配置文件查找顺序

$ mysqld --help --verbose | grep -A1"Default options"

Default options arereadfrom the following filesinthe given order:

/etc/my.cnf /etc/mysql/my.cnf /usr/etc/my.cnf ~/.my.cnf

...

从输出看出配置文件查找顺序/etc/my.cnf=>/etc/mysql/my.cnf=>/usr/etc/my.cnf=>~/.my.cnf

打开/etc/my.conf,添加如下配置:

[mysqld]

...

slow_query_log=ON

long_query_time=0.100000

slow_query_log_file=/var/lib/mysql/localhost-slow.log

关于long_query_time阈值时间设定,根据自己具体的实际情况来设置。

如版本大于5.6.5可以开启log_queries_not_using_indexes记录未使用索引的记录,通过log_throttle_queries_not_using_indexes限制每分钟写入的条数。

克服了对慢查询日志的心理担忧和正确配置之后,请重启MySQL服务。下面我们就可以静静等待每天产生的慢查询日志了。

慢查询日志的组成

记录慢查询日志是为了从中分析出有价值的信息。在此之前,首先需要看看慢查询日志包含哪些内容,不同版本的MySQL的慢查询日志组成也是不尽相同。下面以MySQL-5.6.34为例说明:

# Time: 161211 16:35:09

# User@Host: root[root] @ localhost []  Id:     4

# Query_time: 5.007305  Lock_time: 0.000112 Rows_sent: 5  Rows_examined: 10

SET timestamp=1481470509;

select customer_id, sleep(1) from customer cwherec.customer_idin(select customer_id p from payment)limit5;

下面说明下各组成部分的含义:

第一部分如下:

# Time: 161211 16:35:09

慢查询产生时间。同一时间内多个慢sql,只有第一条sql会显示此时间

注意 这个时间是语句执行结束时间,对这时间理解有误将会得到错误结论。

第二部分如下:

# User@Host: root[root] @ localhost [127.0.0.1] Id: 4

客户端相关信息,如连接用户,主机和连接线程id。上图可以知道

连接用户User:root,

连接主机Host:localhost,ip为.0.0.1

连接线程Id:7,连接线程id可通过select connection_id获取

第三部分如下:

# Query_time: 5.007305 Lock_time: 0.000112 Rows_sent: 5 Rows_examined: 10

包含查询时间、等待锁的时间、获取行数和扫描行数

查询时间Query_time:5.007305,查询花费的总时间

等待锁时间Lock_time:0.000112,这些锁具体有哪些?初步理解,很少是因为数据的行级锁导致,可能查询缓存的锁,日志文件锁等需要保持原子操作的锁,有深刻理解的大神求指教

获取行数Rows_sent:5,实际获取的数据行数

扫描行数Rows_examined:10,实际扫描的数据行数

第四部分如下:

SET timestamp=1481470509;

select customer_id, sleep(1) from customer c where c.customer_id in (select customer_id p from payment) limit 5;

具体的慢SQL,SET timestamp可以忽略,查看下面一句。

select customer_id, sleep(1) from customer c where c.customer_id in (select customer_id p from payment) limit 5;

MySQL的慢查询日志主要组成就是这些。MySQL的PerconaServer版本慢查询日志内容更为丰富,更利于问题定位,包含如执行是否被killed、发送的bytes、是否Full_scan、是否Full_join、是否使用query_cache、是否使用临时表和是否使用filesort等等信息,如有兴趣可以研究一下。

如何分析慢查询日志

拿到一份慢查询日志,请不要直接打开。否则你会发现在耗费了很长一段时间之后,依然毫无结论。正如开头所说,分析慢查询日志本来是一门技术活,但对于你而言,或许是门体力活。总结几点慢查询日志中本人比较关心的点:

慢查询的总条数

慢查询执行时间大于指定时间条数

慢查询指定时间段数量,如只想分析公司大促期间慢查询

哪些语句耗时最严重,可能因某条语句导致服务器整体性能下降

哪些语句平均耗时严重,如执行次数不多但是本身执行时间太长的语句

哪些语句执行时间分布不均,可能因查询条件不同选择不同索引或查询缓存导致

不合理的sql,如代码问题导致select * from table无条件查询大表

语句是否已经使用了索引

using filesort或者using tempary,大表排序且未正确使用索引

只查询某个用户某张表的慢查询

某慢查询在总值占比情况等等

随机总结了几条,有些或许不是很合理。重点在于说明,要有正确的方向再进行分析,才不会只做体力劳动。

有了基本的思路之后,是不是需要完全由我们自己去编写脚本去分析慢查询日志呢?答案当然是否。遵循不重复造轮子的思想,这里给大家推荐几款工具:

mysqlslowdump,官方自带的慢查询日志分析工具,支持如执行时间,锁定时间和发送行数的总值和平均值排序,支持pattern过滤等功能,可以满足基本使用。但无具体分析数据,且无法进行更精细的搜索,如指定的日期范围等

pt-query-digest 个人认为这个工具是神器,percontoolkit中的慢查询分析工具,除了上述基本功能外,还支持慢查询报表统计,占比分析,离差指数,精确的搜索如指定用户,指定时间范围,指定IP等等,匹配此工具的还有一款PHP开发的web监控工具Query-digest-UI,不过暂时还比较简陋。perconaToolkit这个工具集还有其他很多对于mMySQL有用的工具,如pt-online-schema-change不锁表改表、pt-config-diff检测服务器配置等等。本人暂时也没有太多了解,有兴趣可以一起看一下。

## pt-query-digest

- 查询近时间慢查询

  如统计最近12小时的慢查询

$ pt-query-digest --since 12h mysql-slow-1110-1111.log > recent_12h-all-parse

- 分析指定范围内的查询

  如统计2016年11月10日 09:50:00至11月10日 10:10:00的慢查询

$ pt-query-digest --since '2016-11-10 09:50:00' --until '2016-11-10 10:10:00' mysql-slow-1110-1111.log > 1110095000_1110101000-all-parse

- 分析指定语句的慢查询

  如统计只含有select语句的慢查询

$ pt-query-digest --filter '$event->{fingerprint}=~ m/^select/i' mysql-slow-1110-1111.log > 1110_1111-select-parse

- 针对某个用户的慢查询

  如统计db_user用户的慢查询

$ pt-query-digest --filter '($event->{user} || "")=~ m/^db_user/i' mysql-slow-1110-1111.log > 1110_1111-db_user-parse

- 分析所有的全表扫描

  统计所有全表扫描慢查询

$ pt-query-digest --filter '($event->{Full_scan} || "") eq "yes"' mysql-slow-1110-1111.log > 1110_1111-full_scan-parse

- 查询保存到query_review表

$ pt-query-digest  --user=root –password=abc123 --review  h=localhost,D=test,t=query_review--create-review-table  slow.log

- 把查询保存到query_history表

$ pt-query-digest  --user=root –password=abc123 --review  h=localhost,D=test,t=query_history --create-review-table  slow.log_20140401

$ pt-query-digest  --user=root –password=abc123--review  h=localhost,D=test,t=query_history --create-review-table  slow.log_20140402

- 通过tcpdump抓取mysql的tcp协议数据,然后再分析

  $ tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt

  $ pt-query-digest --type tcpdump mysql.tcp.txt> slow_report9.log

- 分析binlog

mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql

pt-query-digest  --type=binlog  mysql-bin000093.sql > slow_report10.log

- 分析general log

pt-query-digest  --type=genlog  localhost.log > slow_report11.log

官方文档:http://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html

这些工具本篇文章不做细致介绍,具体细节可看后续文章。最终目标是针对这些工具开发出一套切实可行的MySQL慢查询监控方案,虽然pt-query-digest足够强大,但可能完全依靠其实现所有需求未必现实。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念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

推荐阅读更多精彩内容