今天带着同事一起分析了一个常见的MySQL慢日志报警,从分析的过程希望带给大家一些启示和反思。
报警信息类似:
PROBLEM P5 Endpoint:xxxx Metric:mysql.slow_queries Tags:idc=IDC1,port=4306,service=test diff(#1): 335>300 Note:[[warning]SQL语句执行效率慢] Max:3, .....
看到这条报警信息,可以明确一个任务,此时数据库中存在大量的慢日志,条数为335,超出了阈值设置的300
当然打开日志来分析的时候,会发现比想象的要复杂一些,因为慢日志文件可能有几百兆甚至更大,要分析整个文件显然是不可行的,所以我们需要过滤条件,把慢日志限定在一个较小的范围内来分析。
这里我们可以使用mysqldumpslow来做一个简单的分析,推荐更好的一款工具是pt-query-digest。
如下是慢日志的头部:
可以明显看到在1分钟的时间里SQL执行的整体情况,1分钟内有400多的SQL执行。但是仔细看指标“Exec time”会有一个明显的问题,那就是这个时长指标其实很低,总数才881ms,显然是不符合我们理解中的慢日志阈值的。
所以我们可以得到一个基本的印象,这个指标是和一个慢日志相关的参数:log_queries_not_using_indexes 相关,这个参数意思是如果SQL没有使用索引则会计入慢日志。
为了做进一步验证,我们往下看profile.
看profile信息的时候我们要按照重点来把握,即那些明显的性能SQL占比通常很高。如果检查前两个表会发现,根据现在的条件,这两条SQL的where条件部分是没有相关的索引的。
第一个SQL有点意思。
UPDATE SELECT dic_push_dao_assistant tem_selectAssDAO。。。
这是什么意思,我们可以详细的Query ID的解析来得到。对于update语句会转义成等价的select语句
update `dic_push_dao_assistant` set `state` = 1 where `id` in ( select `id` from `tem_selectAssDAO` )G # Converted for EXPLAIN # EXPLAIN /*!50100 PARTITIONS*/ select `state` = 1 from `dic_push_dao_assistant` where `id` in ( select `id` from `tem_selectAssDAO` )G
当然这个语句本身是有些粗糙,完全可以进一步优化。
我们再分析一下第2条SQL,问题是很明显的,即相关的SQL缺少索引而走了全表扫描。
但是建议还是做下补充,可能这些信息是在慢日志之外,就是建表语句:
从这里我们可以清晰的看出,这个表只有2190条记录,目前的扫描基本就是少数几个页就搞定了,但是自增列已经到了1000万左右,可以看出这个表的变更是极为频繁的,那么是否存在碎片呢。验证的方式我们可以直接查看对应的物理文件,可以看到2000条记录大概占用了20M左右的空间,这能不能说明有碎片呢。
# ll *cccd*
-rw-r----- 1 mysql mysql 70494 Nov 20 09:37 dic_fsm_cccd_info.frm
-rw-r----- 1 mysql mysql 26214400 Feb 27 17:50 dic_fsm_cccd_info.ibd
验证方式其实也不难,我们在另外一个库中模拟创建一个表补充数据即可,大概是10M左右。
# ll *cccd*
-rw-r----- 1 mysql mysql 70494 Feb 27 23:47 dic_fsm_cccd_info.frm
-rw-r----- 1 mysql mysql 10485760 Feb 27 23:48 dic_fsm_cccd_info.ibd
所以目前来看这个表是存在碎片的,说明大量的数据是写入了库中,然后很可能做了delete操作,导致数据总量变化不大,按照这种方式是存在隐患的。
从自增列来看,很可能数据会出现较大的增长,就会导致这个操作马上成为瓶颈,这条SQL一分钟执行了144次,算是比较频繁了,所以从目前的情况来看,这个表很可能成为性能的瓶颈,所以需要建议业务评估添加相关的索引。而之前根据业务的反馈,说这个库经常会有一些操作的延迟,也不难理解了。
我们在这里处理应该得出什么结论呢?
1)关闭参数log_queries_not_using_indexes
2)对相关的表进行分析,根据条件和频率创建相应的索引
其实到了这里,我们的分析还是不够深入,我们可以发掘出更多的信息,那就是可以提供给业务方一个更全面的信息列表,比如那些表中的索引是冗余索引,那些表走了全表扫描需要考虑添加索引。
这里需要正确引用sys schema,比如:
通过如上的信息可以发现我们需要重点考虑前面的几个表,走了全表扫描,产生了较大的延迟。
而稍后的解决方法,其实是通过对于业务的反馈优化,在业务添加了相关索引之后,还是建议打开参数:log_queries_not_using_indexes ,这对于一些业务场景的监控其实也是有效的。
如此一来,我们对慢日志的分析也告一段落,如果对于每条报警信息我们都认真对待,其实相应技术能力的提升也会很快。
其实行业里有一个常见的“伪需求“,就是开发同学经常需要关注慢日志,从工作的角色和分工来看,他们得到慢日志之后的分析和处理常常和问题的本质相左,换句话说,他们得到慢日志,是希望通过分析日志来发现一些明显的性能问题,通过这种信息检索的方式,来快速定位问题,但是实际上得到日志之后的分析结果是不可控的,可能10分钟,可能分析不出来。
而这个工作其实是应该作为运维的前置工作来完成的,既然开发对于慢日志的处理不专业,势必需要DBA来提供专业的建议,而如果我们能够通过一种透明自助的方式来提供分析和有效建议,对于开发同学来说,其实他们需要的不是慢日志,而是你的数据服务能力。