服务器性能剖析
Q:如何确认服务器是否达到了性能最佳的状态 / 找出某条语句为什么执行不够快 / 诊断被用户描述成“停顿”,“堆积”,“卡死”的某些间歇性疑难故障
-
这里将性能优化定义成响应时间(为完成某件任务所需要的时间度量),并假设性能优化就是在一定工作负载的情况下尽可能的降低响应时间。注意,CPU使用率只是一种现象,而不是很好的可度量的目标。
-
通过性能剖析进行优化:先测量任务所花费的时间,然后对结果进行统计和排序,将重要的任务排到前面。可以将相似的任务分组并进行汇总。
- 性能剖析报告会列出所有任务列表,每行记录一个任务,包括任务名,任务的执行时间,任务的消耗时间,任务的平均时间,以及该任务执行时间占全部时间的百分比。根据消耗时间降序排列
- 基于执行时间的分析研究的是什么任务的执行时间最长。 基于等待的分析则是判断任务在什么阶段被阻塞的时间最长。事实上,当基于执行时间的分析发现一个任务需要花费时间花费太多时间的时候,应该深入去分析一下,可能会发现某些“执行时间”其实是在等待(如等待I/O完成)
-
理解性能剖析:依然存在很多重要信息缺失的现象。
- 什么样的查询值得优化:(阿姆达尔定律)一些只占总响应时间比重很小的查询是不值得优化的。
- 异常情况:某些任务即使没出现在性能剖析输出的前面也需要优化。如任务执行次数少但单次执行都很慢
- 未知的未知:任务总时间和实际测量时间的差值是”丢失的时间“
- 被掩藏的细节:只相信平均值非常危险
-
对应用系统进行性能剖析:在更高层次的堆栈中进行交互式的分析。建议对系统进行自上而下的性能分析,追踪自用户发起到服务器响应的整个流程。(剖析应用程序比剖析数据库容易且回报更多)
- 外部资源,比如调用了外部的Web服务器或者搜索引擎
- 应用需要处理大量的数据,比如分析一个超大的XML文件
- 在循环执行昂贵的操作,比如滥用正则表达式
- 使用低效的算法,如暴力搜索
注:MySQL没有这么复杂,故只需要一款应用程序的剖析工具即可。该尽可能地测量一切可以测量的地方,并且接受这些测量带来的额外开销。测量点至少为性能优化共享10%
-
剖析MySQL查询
-
剖析服务器负载:CPU负载指的是一段时间内任务队列的长度,即一段时间内一共有多少任务在使用或等待使用CPU。MySQL的每一个新版本都增加了更多的可测量点。但是如果只是需要剖析并找出代价高的查询,慢查询日志即可满足需求。慢日志是一种轻量且全面的性能剖析工具。(用于定位耗时的查询语句)
- 捕获MySQL的查询到日志文件中
- 将long_query_time设为0来捕获所有的查询,查询的响应时间已经达到微秒级。
- 慢查询日志是开销最低,同时精度最高的测量查询时间的工具。不需要担心额外的I/O开销,反而要关注其可能消耗大量的磁盘空间。如果长期开启慢查询日志,主要要配合部署日志轮转工具(log rotation): 使用log rotate工具切割MySQL日志与慢日志分析发送到邮箱
- Percona Server的慢查询日志比MySQL官方社区版本记录了更多更有价值的信息,如查询计划,锁,I/O活动等。还在可管理性上进行了增强
- 权限不足无法在服务器上查询记录的两种替代技术都集成到了Percona Toolkit工具包中的pt-query-digest:使用–processlist参数 / 抓起TCP网络包
- 分析查询日志:不要直接点开,而因该生成剖析报告(pt-query-digest工具)
- 捕获MySQL的查询到日志文件中
-
剖析单条查询:定位到需要优化的单条查询后,可以针对此查询钻取更多信息。
-
使用SHOW PROFILE:
set profiling=1
语句使得在服务器上执行的所有语句都会测量其耗费时间和其他一些查询执行状态变更相关的数据。当一条查询提交给服务器时,此工具会记录剖析信息到一张临时表,并给查询赋一个从1开始的整数标识符。set profiling=1 select * from t_Order; select * from t_Product show profiles +----------+------------+-------------------------+ | Query_ID | Duration | Query | +----------+------------+-------------------------+ | 1 | 9.75e-05 | SHOW WARNINGS | | 2 | 0.00052075 | select * from t_order | | 3 | 0.000511 | select * from t_product | | 4 | 5.3e-05 | SHOW WARNINGS | +----------+------------+-------------------------+ show profile for query 3 +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000065 | | checking permissions | 0.000009 | | Opening tables | 0.000142 | | init | 0.000022 | | System lock | 0.000010 | | optimizing | 0.000008 | | statistics | 0.000013 | | preparing | 0.000012 | | executing | 0.000007 | | Sending data | 0.000154 | | end | 0.000010 | | query end | 0.000011 | | closing tables | 0.000010 | | freeing items | 0.000016 | | cleaning up | 0.000012 | +----------------------+----------+
剖析报告给出了查询执行的每个步骤及其花费的时间,输出是按照执行顺序进行排序,且不可通过order by之类的命令重排。下面给出使用INFORMATION_SHCEMA来查询剖析报告的办法:
set @query_id=1 SELECT STATE,SUM(DURATION) AS Total_R, ROUND( 100*SUM(DURATION)/(SELECT SUM(DURATION) FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID = @query_id),2 ) AS Pct_R,COUNT(*) AS Calls,SUM(DURATION)/COUNT(*) AS "R/Call" FROM INFORMATION_SCHEMA.PROFILING WHERE QUERY_ID=@query_id GROUP BY STATE ORDER BY Total_R DESC # 输出如下: +----------------------+----------+-------+-------+--------------+ | STATE | Total_R | Pct_R | Calls | R/Call | +----------------------+----------+-------+-------+--------------+ | starting | 0.000072 | 20.45 | 1 | 0.0000720000 | | Sending data | 0.000047 | 13.35 | 1 | 0.0000470000 | | init | 0.000030 | 8.52 | 1 | 0.0000300000 | | Opening tables | 0.000026 | 7.39 | 1 | 0.0000260000 | | checking permissions | 0.000025 | 7.10 | 1 | 0.0000250000 | | cleaning up | 0.000023 | 6.53 | 1 | 0.0000230000 | | System lock | 0.000019 | 5.40 | 1 | 0.0000190000 | | statistics | 0.000018 | 5.11 | 1 | 0.0000180000 | | preparing | 0.000016 | 4.55 | 1 | 0.0000160000 | | optimizing | 0.000015 | 4.26 | 1 | 0.0000150000 | | freeing items | 0.000014 | 3.98 | 1 | 0.0000140000 | | query end | 0.000013 | 3.69 | 1 | 0.0000130000 | | closing tables | 0.000012 | 3.41 | 1 | 0.0000120000 | | executing | 0.000011 | 3.13 | 1 | 0.0000110000 | | end | 0.000011 | 3.13 | 1 | 0.0000110000 | +----------------------+----------+-------+-------+--------------+ #通过这个结果可以很容易看到查询时间长主要是因为花了很大时间在sending data上 #这个状态代表的原因非常多,可能是各种不同的服务器活动,包括在关联时搜索匹配的行记录等,这部分很难说能优化节省多少消耗的时间。 #若Sorting result花费的时间比较多,则可以考虑增大sort buffer size
-
使用show status(不是一款剖析工具):返回一些计数器,既有服务器级别的全局技术器,也有基于某个连接的会话级别的计数器。其结果可以显示某些活动如读索引的频繁程度,但无法给出具体的消耗时间。show status的结果中只有一条Innodb_row_lock_time指的是操作时间,且是全局性的,还是无法测量会话级别的工作。最有用的计数器包括句柄计数器,临时文件和表计数器等。将会话级别的计数器重置为0,然后查询前面提到的视图,再检查计数器的结果:
flush status; select * from sakila.nicer_but_slower_film_list; #............... show status where variable_name like "Handler%" or Variable_name like "Created%"; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Created_tmp_disk_tables | 2 | | Created_tmp_files | 2 | | Created_tmp_tables | 3 | | Handler_commit | 1 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 10 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 3 | | Handler_read_key | 12942 | | Handler_read_last | 0 | | Handler_read_next | 6462 | | Handler_read_prev | 0 | | Handler_read_rnd | 5462 | | Handler_read_rnd_next | 6478 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 0 | +----------------------------+-------+
我们发现,该查询使用了三个临时表,其中两个是磁盘临时表,并且有很多的没有用到索引的读操作(Handler_read_rnd_next)。注意,使用show status本身也会创建一个临时表,而且也会通过句柄操作访问此临时表,也会影响show status结果中对应的数字,不同的版本可能行为也不尽相同,比较前面通过show profiles获得的查询的的执行计划结果来看,至少临时表的计数器多加了2
-
使用慢查询日志:其记录的条目包含SHOW PROFILE和SHOW STATUS的所有输出,且还有更多信
-
使用performance_schema和sys视图库
-
-
使用性能剖析(如何分析结果)
-
-
诊断间歇性问题:需要确定是单条查询问题 OR 服务器问题(如果服务器的整体运行没问题,只有某条查询偶尔变慢,就需要重点关注这条特定的查询, 服务器问题往往能通过升级硬件或升级到MySQL新版本解决)
- 使用show global status:以较高频率(如一秒执行一次)show global status命令捕获数据,问题出现时可通过某些计数器(如Threads_running、Threads_connected)的”尖刺“或者”凹陷“来发现。
- 使用show processlist:不停地捕获show processlist的输出,观察是否大量线程处于不正常的状态或者有其他不正常的特征。
- 使用查询日志
-
捕获诊断数据
-
其他剖析工具:USER_STATISTICS表/stace