发现瓶颈 - Profiling(程序剖析) - 对一个应用进行剖析（profiling）

Profiling（程序剖析）

程序剖析（profiling）可以显示系统每部分的消耗。最简单的消耗度量就是时间。但是它也可以测量函数调用次数，I/O操作，数据库执行的语句，等等。目标就是为什么系统的表现是这样的。

 

 

对一个应用进行剖析（profiling）

就像基准测试一样，你可以对应用程序进行剖析(profile)，或者一个单独的组件，比如MySQL 服务器。应用级别的剖析(profiling)可以更深入的优化应用以及提供更多准确的结果。因为它是整个应用工作下而生成的。比如，如果你对优化应用的MySQL语句比较感兴趣，你可能仅仅去运行和分析语句。然而，如果那么做的话，可能会丢失许多关于这些语句重要的信息。比如，当读取结果到内存中并处理它们的时候，深入了解应用必须做的工作。

 

因为大部分web应用对于MySQL都是一个普通的用例，所以我们把一个PHP网站作为我们的例子。一般来说，你可能会对整个应用进行剖析，以便于查看系统是怎样加载的，但是你可能会需要对感兴趣的子系统进行独立的剖析。比如搜索功能。有价值的模块对于独立剖析是个好的候补。

 

当我们需要优化PHP是怎样使用MySQL的时候，在PHP代码中，我们更喜欢收集对象或模块级别的统计数据。全局来说，能测量每个网页的数据库操作所消耗的时间。访问数据库是经常的，但并不是总是，瓶颈在应用级别。瓶颈一般由于以下因素引起的。

 

• 外部资源，比如调用web services或者搜索引擎。
• 需要处理大规模数据的操作，比如解析大数据量的XML。
• 在循环中一些昂贵的操作，比如滥用正则表达式。
• 糟糕的优化算法，比如使用糟糕的算法在一个列表中查找某一项。

在查看MySQL执行语句之前，你应该能指出系统性能问题的源头。应用级别的程序剖析（profiling）能帮你找到瓶颈，以及它是监控和提高整体性能的一个重要步骤。

怎样测量和测量什么？

对于大部分应用，时间是一个恰当的程序剖析（profiling）的度量，因为最终用户关注的就是时间。在web应用中，我们喜欢的debug模式是，使每个页面显示语句的时间和行数。之后，我们可以用EXPLAIN来分析比较慢的语句。更深层次的分析，可以在MySQL服务器上结合数据进行分析。

我们推荐你在每个新建项目中包含程序剖析的代码.往老项目中添加这写代码可能比较难，但对于新建项目却比较简单。许多库都包含了这个特性以及使它更容易使用。比如，Java的JDBC和PHP的mysqli的库中，都有内置的功能去剖析数据库的访问。

程序剖析代码对于追踪一些奇怪的错误是非常有价值的。这些错误往往在开发中不会出现，而在生产环境中才会出现。

你的程序剖析代码应该获取记录如下的内容：

• 总共的执行时间或者是时钟时间（在web应用中，是整个页面完全显示的时间）
• 每个执行的语句，以及它们消耗的时间。
• 对MySQL服务器每个开放的连接
• 每个调用外部资源，比如web services,memcached,以及其他的调用脚本。
• 潜在的高开销的方法调用。比如解析XML.
• 用户和系统CPU时间。

上面的这些信息能让你更容易监控应用的性能。它能给你更深入的查看性能的一些方面。你可能不知道如下的信息

• 总的性能问题
• 偶尔增加的相应时间
• 系统得瓶颈，不仅仅是MySQL的
• 对于不可见用户的执行时间，比如搜索引擎爬虫。

一个关于PHP程序剖析的例子

这部分可以使你看到程序剖析代码对于PHP web应用程序是很简单以及无侵入的。让我们看看一些代码的示例。第一个例子教你怎样去建立基础的应用，记录语句和其他的程序剖析的数据到MySQL log表中，以及分析这些结果。

 

为了降低日志对应用的影响，我们把所有的日志信息写入到内存中，之后当页面完成的时候在写入单独的一行中。这个方法要好于记录每条执行语句。因为记录每条语句对MySQL的插入语句是你应该插入语句的两倍之多。单独的记录程序剖析代码其实更难分析瓶颈，因为你并不需要这种颗粒度去发现和解决一些问题。

 

我们开始的这些代码你可以用来获取程序剖析的信息。这个基本的PHP5日志的类。class.Timer.php.这个使用了内置函数如getrusage()去测定校本资源的使用。

 

 

1 <?php
2 /*
3 * Class Timer, implementation of time logging in PHP
4 */
5
6 class Timer {
7 private $aTIMES = array( );
8
9 function startTime($point)
10 {
11 $dat = getrusage( );
12
13 $this->aTIMES[$point]['start'] = microtime(TRUE);
14 $this->aTIMES[$point]['start_utime'] =
15 $dat["ru_utime.tv_sec"]*1e6+$dat["ru_utime.tv_usec"];
16 $this->aTIMES[$point]['start_stime'] =
17 $dat["ru_stime.tv_sec"]*1e6+$dat["ru_stime.tv_usec"];
18 }
19
20 function stopTime($point, $comment='')
21 {
22 $dat = getrusage( );
23 $this->aTIMES[$point]['end'] = microtime(TRUE);
24 $this->aTIMES[$point]['end_utime'] =
25 $dat["ru_utime.tv_sec"] * 1e6 + $dat["ru_utime.tv_usec"];
26 $this->aTIMES[$point]['end_stime'] =
27 $dat["ru_stime.tv_sec"] * 1e6 + $dat["ru_stime.tv_usec"];
28
29 $this->aTIMES[$point]['comment'] .= $comment;
30
31 $this->aTIMES[$point]['sum'] +=
32 $this->aTIMES[$point]['end'] - $this->aTIMES[$point]['start'];
33 $this->aTIMES[$point]['sum_utime'] +=
34 ($this->aTIMES[$point]['end_utime'] -
35 $this->aTIMES[$point]['start_utime']) / 1e6;
36 $this->aTIMES[$point]['sum_stime'] +=
37 ($this->aTIMES[$point]['end_stime'] -
38 $this->aTIMES[$point]['start_stime']) / 1e6;
39 }
40
41 function logdata( ) {
42
43 $query_logger = DBQueryLog::getInstance('DBQueryLog');
44 $data['utime'] = $this->aTIMES['Page']['sum_utime'];
45 $data['wtime'] = $this->aTIMES['Page']['sum'];
46 $data['stime'] = $this->aTIMES['Page']['sum_stime'];
47 $data['mysql_time'] = $this->aTIMES['MySQL']['sum'];
48 $data['mysql_count_queries'] = $this->aTIMES['MySQL']['cnt'];
49 $data['mysql_queries'] = $this->aTIMES['MySQL']['comment'];
50 $data['sphinx_time'] = $this->aTIMES['Sphinx']['sum'];
51
52 $query_logger->logProfilingData($data);
53
54 }
55
56 // This helper function implements the Singleton pattern
57 function getInstance( ) {
58 static $instance;
59
60 if(!isset($instance)) {
61 $instance = new Timer( );
62 }
63
64 return($instance);
65 }
66 }
67 ?>

 

 

在应用中可以很容易使用这个类。你只需要把timer围绕在潜在消耗高(或者你感兴趣)的调用。比如这个代码就是把timer围绕在每个MySQL语句中。PHP的新的mysqli接口让你很容易继承mysqli类以及重写query方法。

 

68 <?php
69 class mysqlx extends mysqli {
70 function query($query, $resultmode) {
71 $timer = Timer::getInstance( );
72 $timer->startTime('MySQL');
73 $res = parent::query($query, $resultmode);
74 $timer->stopTime('MySQL', "Query: $query\n");
75 return $res;
76 }
77 }
78 ?>

 

 

这种技术不需要修改多少代码。你可以简单的全局的吧mysqli更改为mysqlx，以及你的整个应用都可以开始记录这些语句了。你可以使用这个方法测量访问任意的资源，比如这些一些调用sphinx全文搜索引擎的语句。

 

$timer->startTime('Sphinx');
$this->sphinxres = $this->sphinx_client->Query ( $query, "index" );
$timer->stopTime('Sphinx', "Query: $query\n");

 

 

紧接着，让我们来看看怎样记录你收集的数据。这个例子，展示了智能使用MyISAM或者Archive存储引擎的时机。这两个任意的引擎都可以做为存储日志的候选。当添加日志的时候，我们用INSERT DELAYED，因此这个INSERT可以做为数据库服务器后端的一个线程去执行。意思就是这个语句将会立即返回，因此这样就不会影响应用的相应时间。(即使我们不使用INSERT DELAYED，除非我们显式的关闭inserts，不然的话inserts将会并发执行，因此外部的select语句不会阻塞日志)最终，我们可以按日期分区，为每个日期创建新的日志表。

 

这个是日志表的CREATE TABLE语句

 

 

CREATE TABLE logs.performance_log_template (
ip INT UNSIGNED NOT NULL,
page VARCHAR(255) NOT NULL,
utime FLOAT NOT NULL,
wtime FLOAT NOT NULL,
mysql_time FLOAT NOT NULL,
sphinx_time FLOAT NOT NULL,
mysql_count_queries INT UNSIGNED NOT NULL,
mysql_queries TEXT NOT NULL,
stime FLOAT NOT NULL,
logged TIMESTAMP NOT NULL
default CURRENT_TIMESTAMP on update CURRENT_TIMESTAMP,
user_agent VARCHAR(255) NOT NULL,
referer VARCHAR(255) NOT NULL
) ENGINE=ARCHIVE;

 

 

实际中，我们并不会对这个表插入任何信息，这个仅仅是创建日志表的模板，我们可以为每天的数据创建这个表。

 

我们将在下一章详细解释这些内容，但是现在，我们要知道的是要使用最小数据类型去保存期望的数据。我们使用无符号整型去存储IP地址。我们也使用255长度的字符类型去存储页面和来源。这个值可能会多于255字符，但是首个255对于我们的需求足够了。

 

最终让人迷惑的一段就是当页面完成之后，要记录一些结果。

PHP代码如下

 

79 <?php
80 // Start of the page execution
81 $timer = Timer::getInstance( );
82 $timer->startTime('Page');
83 // ... other code ...
84 // End of the page execution
85 $timer->stopTime('Page');
86 $timer->logdata( );
87 ?>

 

 

Timer类使用DBQueryLog类，这个就是把日志存储到数据库中，以及每天创建新的数据库表，代码如下

 

 

88 <?php
89 /*
90 * Class DBQueryLog logs profiling data into the database
91 */
92 class DBQueryLog {
93
94 // constructor, etc, etc...
95
96 /*
97 * Logs the data, creating the log table if it doesn't exist. Note
98 * that it's cheaper to assume the table exists, and catch the error
99 * if it doesn't, than to check for its existence with every query.
100 */
101 function logProfilingData($data) {
102 $table_name = "logs.performance_log_" . @date("ymd");
103
104 $query = "INSERT DELAYED INTO $table_name (ip, page, utime,
105 wtime, stime, mysql_time, sphinx_time, mysql_count_queries,
106 mysql_queries, user_agent, referer) VALUES (.. data ..)";
107
108 $res = $this->mysqlx->query($query);
109 // Handle "table not found" error - create new table for each new day
110 if ((!$res) && ($this->mysqlx->errno == 1146)) { // 1146 is table not found
111 $res = $this->mysqlx->query(
112 "CREATE TABLE $table_name LIKE logs.performance_log_template");
113 $res = $this->mysqlx->query($query);
114 }
115 }
116 }
117 ?>

 

 

一旦我们记录了数据，我们可以分析日志了。使用MySQL记录日志的好处就是可以更灵活的使用SQL去分析数据，因此你可以写一些语句去获取你要得到的日志报表。一个实例，2007年2月的第一天执行时间多余10s的页面。

 

 

mysql> SELECT page, wtime, mysql_time
-> FROM performance_log_070201 WHERE wtime > 10 LIMIT 7;

+-------------------------------------------+---------+------------+
| page | wtime | mysql_time |
+-------------------------------------------+---------+------------+
| /page1.php | 50.9295 | 0.000309 |
| /page1.php | 32.0893 | 0.000305 |
| /page1.php | 40.4209 | 0.000302 |
| /page3.php | 11.5834 | 0.000306 |
| /login.php | 28.5507 | 28.5257 |
| /access.php | 13.0308 | 13.0064 |
| /page4.php | 32.0687 | 0.000333 |
+-------------------------------------------+---------+------------+

 

 

(我们一般尽可能的选择多的数据，但是我们更好的示例，减少了一些结果。)

 

如果你比较wtime(时钟时间)和语句执行时间。你会发现MySQL执行语句的响应慢的时间仅仅是2个页面。因为我们存储了执行的语句，我们可以获取它们。

 

 

mysql> SELECT mysql_queries
-> FROM performance_log_070201 WHERE mysql_time > 10 LIMIT 1\G

mysql_queries:
Query: SELECT id, chunk_id FROM domain WHERE domain = 'domain.com'
Time: 0.00022602081298828
Query: SELECT server.id sid, ip, user, password, domain_map.id as chunk_id FROM
server JOIN domain_map ON (server.id = domain_map.master_id) WHERE domain_map.id = 24
Time: 0.00020599365234375
Query: SELECT id, chunk_id, base_url,title FROM site WHERE id = 13832
Time: 0.00017690658569336
Query: SELECT server.id sid, ip, user, password, site_map.id as chunk_id FROM server
JOIN site_map ON (server.id = site_map.master_id) WHERE site_map.id = 64
Time: 0.0001990795135498
Query: SELECT from_site_id, url_from, count(*) cnt FROM link24.link_in24 FORCE INDEX
(domain_message) WHERE domain_id=435377 AND message_day IN (...) GROUP BY from_site_
id ORDER BY cnt desc LIMIT 10
Time: 6.3193740844727
Query: SELECT revert_domain, domain_id, count(*) cnt FROM art64.link_out64 WHERE
from_site_id=13832 AND message_day IN (...) GROUP BY domain_id ORDER BY cnt desc
LIMIT 10
Time: 21.3649559021

 

 

我们看到了两个有问题语句，一个是6.3s，一个事21.3s。明显需要优化。

 

记录所有的查询消耗是非常大的。因此我们经常只记录一部分页面或者仅仅在DEBUG模式下记录日志。

 

你怎样知道没有程序剖析部分是否存在瓶颈？最简单的方法是看“丢失时间”。一般来说，时钟时间(wtime)是用户时间，系统时间，SQL执行时间以及其他你能测量时间之和，再加上你没有测量的“丢失时间”。可能会出现一定的重叠，比如，需要用PHP代码处理SQL语句的CPU时间，但是通常是不重要的。下列的图显示了时钟时间的分割形式。

 

理想的情况下，“丢失时间”应该尽可能的小。如果你从wtime中去除了你所有测量的时间，但是还有许多的时间。说明有些你没有测量的因素增加了脚本执行时间。这个可能是生成页面的时间或者需要等待的其他因素。

 

有两种类型需要等待：在队列中等待CPU时间，以及等待资源。当进程准备运行的时候，它在等待，但是所有的CPU都没有空闲。一般不可能指出在CPU队列中进程花费等待的时间是多少，但是这通常不是个问题。更有可能的是，使用了外部的资源而没有去剖析(profiling)它.

 

如果你的程序剖析完成了，你应该很容易发现瓶颈了。这很直接：如果你的脚本执行时间几乎是CPU时间，你可能需要优化优化PHP代码。有的时候，一些测量遮盖了其他，比如，因为你系统有个bug,它是你的缓存系统没有效率以及强迫系统执行过多语句，可能CPU占用率会很高。

 

通过这些例子，程序剖析在应用的级别还是非常灵活和重要的技术。如果可能，把程序剖析(profiling)插入任意的你需要找出性能问题的应用，都是个很好的方法。

 

最后需要注意的是，我们应该提到是，上一部分所展示例子仅仅是基本的程序剖析的技术。我们这部分的目标是指出MySQL是否存在问题。你可能也需要剖析应用本身的代码。比如，因为使用了过多的CPU时间，你决定优化你的PHP代码。你可以使用的工具如xdebug,Valgirn何cachegrind去剖析下CPU的使用。

 

一些语言内置的支持了程序剖析（profiling）.比如，在ruby中使用-r命令行参数以及使用如下命令来剖析Perl.

 

$ perl -d:DProf <script file>

$ dprofpp tmon.out

 

你可以通过在web上搜索"profiling <language>"来开始学每种语言的剖析（profiling）。