暂无图片
暂无图片
暂无图片
暂无图片
暂无图片

【StoneDB故障诊断】慢SQL诊断

原创 来来士 2022-07-25
701

慢查询日志用来记录SQL的执行时间超过long_query_time的阀值,慢查询日志支持将日志写入文件,也支持将日志写入数据库的表。慢查询日志能帮助我们捕捉到有性能问题的SQL,相关慢查询日志参数如下:
slow_query_log:慢查询日志是否开启
slow_query_log_file:慢查询日志记录的文件
long_query_time:SQL实际执行时间超过该参数阀值就会被记录
log_queries_not_using_indexes:未使用索引就会被记录
log_slow_admin_statements:是否记录管理语句,如alter、create、drop
注:long_query_time记录的是SQL实际执行时间,不包含锁等待时间,虽然有的SQL执行时间很长,但可能是由于锁等待引起的,实际上这种SQL不会被记录到慢查询日志。
慢查询日志输出解释:
Query_time:SQL总执行时间,即实际执行时间 + 锁等待时间
Lock_time:锁等待时间
Rows_sent:发送给客户端的行数
Rows_examined:表示执行过程中扫描了多少行,这个值是在执行器每次调用存储引擎获取数据行的时候累加的,是在Server层统计的
注:在有些场景下,执行器调用一次,在存储引擎内部则扫描了多行,因此存储引擎扫描行数和rows_examined并不是完全相同的。

mysqldumpslow

mysqldumpslow常用于对慢查询日志进行汇总分类。
1)查看慢查询日志中TOP 10(以平均执行时间降序排列)

mysqldumpslow -t 10 /var/lib/mysql/mysql-slow.log | more
复制

2)查看慢查询日志中返回总记录数最多的TOP 10(以返回总记录数降序排列)

mysqldumpslow -s r -t 10 /var/lib/mysql/mysql-slow.log | more
复制

3)查看慢查询日志中总执行次数最多的TOP 10(以总执行次数降序排列)

mysqldumpslow -s c -t 10 /var/lib/mysql/mysql-slow.log | more
复制

4)查看慢查询日志中按照总执行时间排序,前10条包含left join的SQL

mysqldumpslow -s t -t 10 -g "left join" /var/lib/mysql/mysql-slow.log | more
复制

相关参数解释:
-s:降序排序
al:平均锁定时间排序
ar:平均返回记录数排序
at:平均执行时间排序,默认
c:总执行次数排序
l:总锁定时间排序
r:总返回记录数排序
t:总执行时间排序
-t NUM:返回top n
-g:使用正则表达式
-h:根据主机名选择
-i:根据实例名选择
-l:不要从总时间减去锁定时间

profiling

profiling分析工具可以获得一条SQL在整个执行过程中的每一步状态,以及每一步状态的资源消耗情况,如CPU、IO、Swap,同时还能获得每一步状态的函数调用,以及该函数所在的源文件和出现的位置。
用法示例如下:
开启当前线程的profiling:

set profiling=on;
复制

查询当前线程执行的所有SQL:

show profiles;
复制

查询某个SQL在执行过程中每个状态的CPU、IO消耗:

show profile cpu,block io for query query_id;
复制

查询某个SQL在执行过程中每个状态的所有消耗:

show profile all for query query_id;
复制

每个状态的所有消耗返回结果示例如下:

+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+ | Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file | Source_line | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+ | starting | 0.000363 | 0.000239 | 0.000025 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL | | checking permissions | 0.000055 | 0.000040 | 0.000004 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 809 | | checking permissions | 0.000045 | 0.000000 | 0.000047 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 809 | | Opening tables | 0.000315 | 0.000000 | 0.000307 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 7 | 0 | open_tables | sql_base.cc | 5815 | | System lock | 0.000057 | 0.000000 | 0.000056 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | mysql_lock_tables | lock.cc | 330 | | init | 0.000047 | 0.000000 | 0.000048 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | optimize_select | Engine_execute.cpp | 330 | | optimizing | 0.000195 | 0.000000 | 0.000203 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | optimize | sql_optimizer.cc | 175 | | update multi-index | 0.000488 | 0.000216 | 0.000272 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 6 | 0 | UpdateMultiIndex | ParameterizedFilter. | 981 | | join | 8.127252 | 6.948224 | 1.168786 | 236 | 18 | 0 | 168 | 0 | 0 | 0 | 304466 | 0 | UpdateJoinCondition | ParameterizedFilter. | 603 | | aggregation | 0.021095 | 0.000957 | 0.000102 | 3 | 0 | 72 | 8 | 0 | 0 | 0 | 18 | 0 | Aggregate | AggregationAlgorithm | 26 | | query end | 0.000185 | 0.000092 | 0.000009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 7 | 0 | mysql_execute_command | sql_parse.cc | 4972 | | closing tables | 0.000156 | 0.000141 | 0.000015 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 11 | 0 | mysql_execute_command | sql_parse.cc | 5031 | | freeing items | 0.000152 | 0.000136 | 0.000015 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | mysql_parse | sql_parse.cc | 5659 | | logging slow query | 0.006152 | 0.000401 | 0.000000 | 1 | 0 | 8 | 8 | 0 | 0 | 0 | 6 | 0 | log_slow_do | log.cc | 1718 | | cleaning up | 0.000245 | 0.000154 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 13 | 0 | dispatch_command | sql_parse.cc | 1935 | +----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
复制

一个SQL需要经历如下的Status过程:
starting:语法语义解析,生成解析树
checking permissions:根据解析后的解析树,对需要访问的表进行鉴权
opening tables:打开访问的表
System lock:确认是由哪种锁引起的
optimizing/statistics/preparing:这3个状态处于语句的物理和逻辑优化阶段,之后生成执行计划
Sending data:服务层与存储引擎层正在进行数据交互
Update:insert语句,如果遇到行锁会处于这个状态下
Updating:delete/update语句,如果遇到行锁会处于这个状态下
query end:提交过程,如果遇到大事务会处于这个状态下
closing tables:关闭表的访问,与opening tables对应
freeing items:释放解析树
如果Status长时间处于如下几种状态,说明SQL存在性能问题或者等待。
Sending data:服务层与存储引擎层正在进行数据交互
converting HEAP to MyISAM:查询结果集太大,内存临时表不够用,需要暂存到磁盘临时文件
Creating tmp table:创建临时表,然后拷贝数据到临时表,用完之后删除临时表,通常是有group by、distinct、子查询操作
Copying to tmp table on disk:把内存中的临时表拷贝到磁盘
Creating sort index:在做排序操作,通常是order by
locked:被阻塞
Waiting for table metadata lock:发生元数据锁等待

optimizer trace

有时候我们不仅想知道SQL的执行计划,还想知道优化器为什么选择这个执行计划。optimizer trace功能可以让我们知道优化器生成执行计划的过程,这个功能是由系统变量optimizer_trace来决定的。

mysql> show variables like 'optimizer_trace'; +-----------------+--------------------------+ | Variable_name | Value | +-----------------+--------------------------+ | optimizer_trace | enabled=off,one_line=off | +-----------------+--------------------------+
复制

enabled=off表示optimizer trace默认是关闭的,如果要开启,需要设置enabled=on,而且一般只作为当前线程开启;one_line=off表示输出格式,默认off表示换行输出。
使用optimizer trace功能的完整步骤如下:
1)设置optimizer_trace缓存大小,目的是保存完整的trace,不要被截断

set optimizer_trace_max_mem_size = 100*1024;
复制

2)开启optimizer_trace

set optimizer_trace='enabled=on';
复制

3)执行具体的SQL
注:如果SQL执行时间很长,而又不想等SQL执行结束才生成trace,使用explain SQL也是可以生成trace的。
4)从optimizer_trace表中查看上一个SQL的优化过程

select * from information_schema.optimizer_trace;
复制

5)关闭optimizer_trace

set optimizer_trace='enabled=off';
复制

optimizer trace的输出分3个阶段,分别是:
1)join_preparation
2)join_optimization
3)join_execution
其中join_optimization阶段是基于成本计算的。对于单表查询来说,主要关注的是row_estimation过程,这个过程分析了全表扫描成本和各个索引扫描的成本。对于多表关联查询来说,主要关注的是considered_execution_plans过程,这个过程分析了不同表关联顺序的成本。
join_optimization阶段需要关注的部分
condition_processing:优化器在这个过程会做查询条件处理,如等值传递转换、常量传递转换、消除没用的条件。例如:原始的查询条件是:“a=1 and b=a”,经过转换后是:“a=1 and b=1”
rows_estimation:单表查询的行预估
table_scan:全表扫描统计
rows:全表扫描预估行数
cost:全表扫描的成本
potential_range_indexes:可能使用的索引
“index”: “PRIMARY”, —>表示主键索引不可用
“usable”: false,
“cause”: “not_applicable”
“index”: “idx_xxx”, —>表示idx_xxx索引可能被使用
“usable”: true,
“key_parts”: [
“column1”,
“column2”,
“id”
analyzing_range_alternatives:分析各种可能使用的索引的成本
“index”: “idx_xxx”,
“ranges”: [
“2 <= column1 <= 2 AND 0 <= column2 <= 0”
],
“index_dives_for_eq_ranges”: true, —>使用index dive
“rowid_ordered”: true, —>使用该索引获取的记录是否按照主键排序
“using_mrr”: false, —>是否使用mrr
“index_only”: false, —>是否使用索引覆盖
“rows”: xxx, —>使用该索引预估行数
“cost”: xxx, —>使用该索引的成本
“chosen”: true —>是否选择该索引
chosen_range_access_summary:最终选择的执行计划
considered_execution_plans:分析各种可能的执行计划,常用于多表关联查询
attaching_conditions_to_tables:尝试给查询添加一些其他的查询条件
reconsidering_access_paths_for_index_ordering:是否因排序导致执行计划改变

「喜欢这篇文章,您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容,转载时必须标注文章的来源(墨天轮),文章链接,文章作者等基本信息,否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容,欢迎发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论