发现瓶颈 - Profiling(程序剖析) -MySQL Profiling

MySQL程序剖析（Profiling）

我们将要详细的讲到MySQL的剖析(Profiling),因为它很少依赖于你的应用。应用和服务器级别的剖析有的时候都是有必要的。虽然应用级别的剖析可以给你整个应用性能的总揽。，但是对MySQL的剖析提供了信息是服务器级别所提供不了的。比如，对PHP代码进行剖析不会显示MySQL有多少行语句执行了。

 

与应用剖析一样，目标是找出MySQL哪部分消耗过多的时间。我们不会剖析MySQL源码的，虽然有的时候定制化MySQL安装很有用，但是这是另一本书的主题了。所替代的是，我们将教你一些可以技术来获取和分析不同种类的MySQL执行语句的信息。

 

你可以用在任意的颗粒级别以满足你的需求：你可能对整个服务器进行剖析或者单独检查一个语句或者一组语句。下列信息你可以一点点的收集：

 

• MySQL经常访问的那些数据
• MySQL经常执行语句的类型
• MySQL线程大部分时间的状态
• MySQL经常执行语句的子系统
• MySQL执行语句所访问的数据类型
• 不同活动的类型，比如扫描索引。

我们先从范围最广的剖析开始，那就是服务器剖析，将教你更多细节。

记录执行的语句

MySQL有两种记录语句的类型：general log和slow log。他们都是记录执行语句，但是却在语句执行进程的两端。general log记录了每个服务器收到的语句，因此它的语句可能包含了那些没有执行导致错误的语句。general Log记录了所有的语句，包括了一些非执行语句的事件，比如连接和断开连接。你可以用一个指令来启用它。

log = <file_name>

 

根据设计，general log不会包括执行时间和其他一些仅仅在语句执行完毕的信息。相比较而言，slow log记录执行完毕的语句。尤其是，它记录那些超过指定时间执行的语句。这两种日志都对程序剖析很有用，但是slow log是获取问题语句的主要工具。我们常常推荐把它开启。

 

下面列出的配置会开启这个日志。获取所有执行时间超过2s的语句，以及记录那些不使用索引的语句。它也会记录一些执行慢的管理语句，比如OPTIMIZE TABLE:

 

 

log-slow-queries              = <file_name>

long_query_time               = 2

log-queries-not-using-indexes

log-slow-admin-statements

 

你可以自定义这些配置，然后把它们放到my.conf文件中。更多的服务器配置将在以后的章节详细讲述。

 

long_query_time的默认值是10s。这个设置太慢了，因此我们一般都设置它为2s。然而，对于许多应用，可能1s都非常慢了。我们在下一部分将讲述如何获得颗粒度更细的日志。

 

在MySQL5.1中，提供了运行时调整slow_query_log，slow_query_log_file参数来控制slow log.但是在MySQL5.0中，在不启动MySQL的情况下，不能开闭slow log。对于MySQL5.0的变通方法是，可以动态的修改long_query_time变量。下面的语句虽然不是真正开启slow log的方式，但是取得了同样的效果。（如果有语句执行超过了10000s，那么你需要优化了这些语句了）

 

mysql> SET GLOBAL long_query_time = 10000;

 

相关配置变量，log_queries_not_using_indexes 使服务器记录没有使用索引的语句。而不管它们的执行时间。虽然开启了slow log会增加一些时间的消耗，导致语句执行速度减慢，但是没有使用索引的语句还是可以经常和非常快速的执行。（比如一些查询一些数据量小的表）这样会使降低服务器的速度，以及使用大量的硬盘空间保存日志。

 

不幸的是，在MySQL5.0中不能动态的开启或关闭日志。你必须修改MySQL配置文件，然后重启MySQL。当你想关闭日志而不想重启服务器，可以把日志文件做一个/dev/null的指向。在确定了MySQL关闭了日志文件描述以及在/dev/null重新打开它，那么你仅执行FLUSH LOGS就可以了。

 

相比较而言，MySQL5.1能实时更改日志以及能把日志记录到表中。这是个很大的进步了。

 

细颗粒度的日志

MySQL5.0以及更早的版本的slow log 都有一定的限制，在一些用途下就没用了。最首要的问题就是它的颗粒度仅仅是秒。以及long_query_time在MySQL5.0中最小单位就是1s。大部分交互的应用中，这个时间就比较长了。如果你正在开发一个高性能的WEB应用，你可能希望整个页面生成小于1s.以及在开始生成的过程中记录许多语句。这种情况下，一个语句执行了150ms，也会被认为是个很慢的语句。

 

另一个问题是，并不是所有的执行语句都记录在slow log中（尤其是，子节点的线程语句不能被记录）。general log记录了所有的语句，但是是在这些语句解析之前记录的，只要就不能记录一些如执行时间，锁时间，以及执行的行数的记录了。只有slow log包含这些信息。

 

最终，如果你开启了log_queries_not_using_indexes参数。可能slow log就被大量的实体，高效的语句所填满。比如，如果你过你生成一个下拉菜单的数据，你可能执行SELECT * FROM STATES。这个语句就被记录了，因为它是整张表的扫描。

 

当程序剖析的目标是性能优化，你应该查看让MySQL服务器大量工作的语句。这并不是意味着总是执行慢的语句。所以记录执行慢的语句可能也没什么用处了。一个例子，一个10ms的语句在一秒内执行了1000次对服务器的压力高于10s语句每秒运行一次。为了发现这个问题，你必须记录每条语句和分析结果。

 

一起查看执行慢的语句和导致服务器压力过大的语句执行总量是非常有用的方法。这会让你发现不同的问题。如一个语句导致了很差的用户体验。

 

 

我们已经开发了一个MySQL的补丁。基于Georg Richter工作之上而开发的。让你指定slow log语句时间到毫秒级别，而不是原来的秒。通过设置long_query_time=0，它也能让你记录所有的语句。这个补丁的地址是http://www.mysqlperformanceblog.com/mysql-patches/。它的主要缺点就是你需要自己编译MySQL。因为这个补丁在MySQL5.1之前并没有包含在MySQL发行包中。

 

目前，MySQL5.1包含了这个补丁，但仅能修改时间的颗粒度。这个补丁的新版本，将不会包含在MySQL的发行包中。新版本将添加一些有用的功能。这些功能包含了语句执行的连接ID，也包含了语句执行的缓存，连接类型，临时表，以及排序。也添加了InnoDB的统计，比如I/O行为以及锁等待。

 

新版本的补丁可以记录子节点所执行的语句。如果在子节点复制的过程中出现问题，这个功能就尤其有用。它也能让你选择一些会话的日志。这些功能对程序剖析来说已经足够了，我们认为这就是最佳实践了。

 

这个补丁是比较新的，因此如果你要应用，要小心的使用它。我们想它已经很安全了，但是它在其他的MySQL服务器还没有经过足够的考验。如果你担心这个还有补丁的MySQL服务器的稳定性，你不一定要一直运行它，你可以先运行它几个小时记录一些语句，然后在恢复你自己的MySQL版本。

 

当程序剖析的时候，把参数long_query_time=0记录所有语句是个很好的方法。如果大部分的读取来自于非常简单的语句，你可能想知道这些情况。记录所有语句会影响一些性能以及它要求更多的硬盘空间-这就是另一个不需要记录所有语句的理由。幸运的是，你可以随时修改long_query_time而不用去重新启动服务器。因此很容易在一段时间内获取所有语句。然后在恢复记录那些执行比较慢的语句。

 

怎样读取slow log

这是一个slow log的例子

 

1 # Time: 030303 0:51:27

2 # User@Host: root[root] @ localhost []

3 # Query_time: 25 Lock_time: 0 Rows_sent: 3949 Rows_examined: 378036

4 SELECT ...

 

第一行显示了日志记录的时间，第二行显示谁执行了这些语句。第三行显示这语句执行的时间，在MySQL服务器级别等待表锁的时间，执行语句返回的行数，以及语句检索的行数。这些语句都是被注视掉的。因此如果你把日志提供给MySQL Client,他们也不会执行。最后一行就是执行的语句。

 

这个例子是MySQL5.1版本的

 

1 # Time: 070518 9:47:00

2 # User@Host: root[root] @ localhost []

3 # Query_time: 0.000652 Lock_time: 0.000109 Rows_sent: 1 Rows_examined: 1

4 SELECT ...

 

和上个日志基本相同，除了第三行，精度变得更高了。上一部分我们提到的补丁提供了更全面的信息

 

 

1 # Time: 071031 20:03:16

2 # User@Host: root[root] @ localhost []

3 # Thread_id: 4

4 # Query_time: 0.503016 Lock_time: 0.000048 Rows_sent: 56 Rows_examined: 1113

5 # QC_Hit: No Full_scan: No Full_join: No Tmp_table: Yes Disk_tmp_table: No

6 # Filesort: Yes Disk_filesort: No Merge_passes: 0

7 # InnoDB_IO_r_ops: 19 InnoDB_IO_r_bytes: 311296 InnoDB_IO_r_wait: 0.382176

8 # InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.067538

9 # InnoDB_pages_distinct: 20

10 SELECT ...

 

第五行显示了这个语句是否使用了缓存，是否检索了整张表，是否没有用索引进行表连接，是否是否临时表，以及临时表是否创建在硬盘上。第六行给出了是否进行了文件排序以及，如果是，是否保存到硬盘上以及有多少合并排序通过它执行的。

 

如果语句执行在InnoDB上，第7，8，9行就会显示。第7行显示了在执行语句的时候，InnoDB计划读取的页数，与它一起的是byte数值。第7行最后的一个值是InnoDB从硬盘读取数据的时间。第8行显示了语句等待行锁以及用了多少时间等待进入InnoDB内核。

 

第9行显示了语句访问唯一InnoDB大约的页面数。这个数值越大，准确度貌似就越低了。这个信息的一种用处就是估计在页面中语句的工作集。这个就是InnoDB缓冲池缓存数据的方式。它也能显示你的集群索引是非常的有用。如果这个语句的行很好的集群索引了，它们会填充更少的页面。以后会讲到集群索引。

 

使用slow log去解决慢语句并不总是很简单。虽然log包含了很多有用的信息，但是一个非常重要的信息却丢失了：那就是语句执行为什么会这么慢的一个想法。有的时候，这是显而易见的。如果log得出了12，000，000行被检查以及1，200，000被发送到了客户端，你知道为什么这么慢的原因了--这是个很大的执行语句。然而，这是很难的的清晰。

 

要注意的是，不要给slow log添加过多的含义。如果你看到一条语句在log中出现多次，那就发现了这语句很慢以及需要优化。但是仅仅因为一个语句在log出现的频率并不意味着它是个糟糕的语句或者甚至并不是缓慢的。你可能找到了一个很慢的语句，运行它，以及发现它执行的时间只是一眨眼的时间。出现在日志中只能说明在过去的那个时候这个语句执行时间很长，并不意味着现在或以后它会执行很长时间。一个语句有的时候很慢，在另外的时间却很快，这种情况原因是很多的：

 

• 一个表可能被锁定了，导致了语句必须去等待。Lock_time指明了这个语句等待锁释放的时间。
• 数据或者索引没有被缓存。在MySQL刚启动的时候或还没有调整好的情况下，这种问题很常见。
• 可能是备份正在执行，导致了硬盘I/O很慢。
• 这个服务器同时还运行着其他语句，导致了这个语句很慢。

因此，你查看slow log应该把它作为部分数据来看。你可以使用它创建一个可疑语句的列表，但是你需要更深层次的分析每一项。

slow log补丁的出现帮助你理解为什么语句执行会很慢。尤其在你使用InnoDB的时候，InnoDB统计信息能带给我们更多的信息：你可以查看语句执行是否在等待硬盘的I/O，InnoDB队列中它是否在花费大量的时间去等待，以及等等其他的信息。

日志分析工具

现在你已经记录了一些执行的语句了。是时候分析结果了。一般的策略是找出对服务器影响最大的语句，用Explain检查它们执行计划进行必要的调整。在调整之后不断地重复这个过程。因为你的修改可能会影响其他语句的执行。比较常见的就是索引可以提高SELECT的速度但是会降低INSERT或UPDATE语句。

 

一般来说你应该在日志中查找如下的执行语句：

 

1. Long queries(运行时间长的语句)：固定时间的批量任务使语句执行缓慢，但是正常的语句不应该执行的很慢。
2. High-impact queries(影响大的语句)：找出那些占用服务器执行大部分时间的语句。还记得上一部分说过的执行时间短的语句占用了很多时间。
3. new queries(新出现的语句)：找出那些昨天还没有在前100个，但是今天却出现的语句。这些语句可能是新出现的也可能是被很快的运行以及正在变得糟糕。可能因为不同的索引或者其他别的什么改变。

如果的slow log记录的数据很少，那么可以去手工去处理，但是你如果记录了所有的执行语句（这是我们所推荐的），那么你就需要一个工具去帮助你了。下列的工具你能用的上。

mysqldumpslow：

这是MySQL本身提供的mysqldumpslow。这个是个Perl脚本能总结slow log以及每个执行语句在log中出现的次数。有这个方法你就不会浪费时间优化一个一天，才执行一次的30s慢语句。而去优化那些看起来很快的语句，但是每天却执行了上千次。mysqldumpslow的优势是它是默认安装的，缺点是相对于其他工具灵活性不足。它的文档也不是很全，以及它也不能分析我们以前介绍过得那个low log补丁生成的log。

mysql_slow_log_filter：

下载地址http://www.mysqlperformanceblog.com/files/utils/mysql_slow_log_filter，这个工具可以解析精确度为ms的log.你可以提取那些执行时间高于指定时间的语句或者检查给定的行数。这个工具是对slow log补丁的很好补充。你可以设置一个高的临界值去优化语句，直到这个语句效率提高。然后在改变参数获得更多的执行语句继续调整。

以下命令的意思就是，显示那些执行超过0.5s以及检查超过1000行的语句。

$ tail -f mysql-slow.log | mysql_slow_log_filter -T 0.5 -R 1000

mysql_slow_log_parser：

这是另一个工具，地址为：http://www.mysqlperformanceblog.com/files/utils/mysql_slow_log_parser，这款工具可以聚合slow log信息。除了聚合和报表，它也显示了执行时间和分析的行数的最大和最小值。打印一个“标准化”的执行语句，以及打印一个你可以EXPAIN的语句。下面是个简单输出

### 3579 Queries

### Total time: 3.348823, Average time: 0.000935686784017883

### Taking 0.000269  to 0.130820  seconds to complete

### Rows analyzed 1 - 1

SELECT id FROM forum WHERE id=XXX;

SELECT id FROM forum WHERE id=12345;

mysqlsla：

MySQL Statement Log Analyzer.地址如下：http://hackmysql.com/

它不仅仅能分析slow log也能分析general log和"raw" log（这个log是把SQL语句用分隔符分开的log）.想mysql_slow_log_parser一样。它能标准化和进行汇总。它也能EXPLAIN语句（它对许多非查询语句进行了重写）以及生成复杂的报表。

你可以使用slow log的统计信息去预测下你将会降低多少服务器系统资源的消耗。假设你抽样执行语句1个小时。发现总和的语句执行时间是10000s（总的时间是超过时钟时间的，因为语句执行是并行的）。如果日志分析一个最差的语句执行了3000s，你会知道它占了整个读取的30%。现在你就知道通过优化这个语句你可以降低服务器多少资源消耗了。