Question

程序运行慢的原因有很多，但真正的原因往往是一两段设计并不那么良好的不起眼的程序，比如对一系列元素进行自定义的类型转换等。程序性能影响往往符合80/20法则，即20%的代码的运行时间占用了80%的总运行时间（实际上，比例要夸张得多，通常是几十行代码占用了95%以上的运行时间），所以如何定位瓶颈所在很有难度，靠经验是很难找出造成性能瓶颈的代码的。这时候，我们需要一个工具帮忙，下文通过cProfile分析相关的独立模块，基本上解决了定位性能瓶颈问题。

profile是Python的标准库。可以统计程序里每一个函数的运行时间，并且提供了多样化的报表，而cProfile则是它的C实现版本，剖析过程本身需要消耗的资源更少。所以在Python 3中，cProfile代替了profile，成为默认的性能剖析模块。使用cProfile来分析一个程序很简单，以下面一个程序为例：

      sum = 0
      for i in range(100):
        sum += i
      return sum
  if __name__ == "__main__":
      foo()

现在要用profile分析这个程序。很简单，把if程序块改为如下：

  if __name__ == "__main__":
      import cProfile
      cProfile.run("foo()")

我们仅仅是import了cProfile这个模块，然后以程序的入口函数名为参数调用了cProfile.run这个函数。程序运行的输出如下：

      5 function calls in 0.143 CPU seconds     Ordered by: standard name
   ncalls tottime percall cumtime percall filename:lineno(function)
      1  0.000  0.000  0.000  0.000 :0(range)
      1  0.143  0.143  0.143  0.143 :0(setprofile)
      1  0.000  0.000  0.000  0.000 <string>:1(?)
      1  0.000  0.000  0.000  0.000 prof1.py:1(foo)
      1  0.000  0.000  0.143  0.143 profile:0(foo())
      0  0.000       0.000      profile:0(profiler)

上面显示了prof1.py里函数调用的情况，根据数据我们可以清楚地看到foo()函数占用了100%的运行时间，foo()函数是这个程序里名副其实的热点。

除了用这种方式，cProfile还可以直接用Python解释器调用cProfile模块来剖析Python程序。如在命令行界面输入如下命令：

  python -m cProfile prof1.py

产生的输出跟直接修改脚本调用cProfile.run()函数有一样的功效。

cProfile的统计结果分为ncalls、tottime、percall、cumtime、percall、filename:lineno(function)等若干列，如表8-1所示。

表8-1　cProfile 的统计结果以及各项意义

通常情况下，cProfile的输出都直接输出到命令行，而且默认是按照文件名排序输出的。这就给我们造成了障碍，我们有时候希望能够把输出保存到文件，并且能够以各种形式来查看结果。cProfile简单地支持了一些需求，我们可以在cProfile.run()函数里再提供一个实参，就是保存输出的文件名。同样，在命令行参数里，我们也可以加多一个参数，用来保存cProfile的输出。

cProfile解决了我们的对程序执行性能剖析的需求，但还有一个需求：以多种形式查看报表以便快速定位瓶颈。我们可以通过pstats模块的另一个类Stats来解决。Stats的构造函数接受一个参数——就是cProfile的输出文件名。Stats提供了对cProfile输出结果进行排序、输出控制等功能。如我们把前文的程序改为如下：

  # 
…略
  if __name__ == "__main__":
      import cProfile
      cProfile.run("foo()", "prof.txt")
      import pstats
      p = pstats.Stats("prof.txt")
      p.sort_stats("time").print_stats()

引入pstats之后，将cProfile的输出按函数占用的时间排序，输出如下：

  Sun Jan 14 00:03:12 2007  prof.txt
       5 function calls in 0.002 CPU seconds
    Ordered by: internal time
    ncalls tottime percall cumtime percall filename:lineno(function)
       1  0.002  0.002  0.002  0.002 :0(setprofile)
       1  0.000  0.000  0.002  0.002 profile:0(foo())
       1  0.000  0.000  0.000  0.000 G:/prof1.py:1(foo)
       1  0.000  0.000  0.000  0.000 <string>:1(?)
       1  0.000  0.000  0.000  0.000 :0(range)
       0  0.000       0.000      profile:0(profiler)

Stats有若干个函数，这些函数组合能输出不同的cProfile报表，功能非常强大，如表8-2所示。下面简单地介绍一下这些函数。

表8-2　Stats函数以及对应作用

这里最重要的函数就是sort_stats和print_stats，通过这两个函数我们几乎可以用适当的形式浏览所有的信息了。下面来详细介绍一下。

1）sort_stats()接收一个或者多个字符串参数，如time、name等，表明要根据哪一列来排序。这相当有用，例如我们可以通过用time为key来排序得知最消耗时间的函数；也可以通过cumtime来排序，获知总消耗时间最多的函数。这样我们优化的时候就有了针对性，可以做到事半功倍了。

sort_stats可接受的参数如表8-3所示。

表8-3　sort_stats可接受参数列表

2）print_stats输出最后一次调用sort_stats之后得到的报表。print_stats有多个可选参数，用以筛选输出的数据。print_stats的参数可以是数字也可以是Perl风格的正则表达式。相关的内容通过其他渠道了解，这里就不详述啦。仅举以下3个例子：

print_stats(".1", "foo:")

这个语句表示将stats里的内容取前面的10%，然后再将包含“foo:”这个字符串的结果输出。

print_stats("foo:",".1")

这个语句表示将stats里的包含“foo:”字符串的内容的前10%输出。

print_stats(10)

这个语句表示将stats里前10条数据输出。

实际上，profile输出结果的时候相当于如下调用了Stats的函数：

p.strip_dirs().sort_stats(-1).print_stats()

其中sort_stats函数的参数是-1，这也是为了与旧版本兼容而保留的。sort_stats可以接受-1、0、1、2之一，这4个数分别对应“stdname”、“calls”、“time”和“cumulative”。但如果你使用了数字为参数，那么pstats只按照第一个参数进行排序，其他参数将被忽略。

除了编编程接口外，pstats还提供了友好的命令行交互环境，在命令行执行python–m pstats就可以进入交互环境，在交互环境里可以使用read或add指令读入或加载剖分结果文件，stats指令用以查看报表，callees和callers指令用以查看特定函数的被调用者和调用者。如图8-2所示是pstats的截图，标识了它的基本使用方法。

图8-2　pstats输出信息截图

如果我们某天心血来潮，想知道向list里添加一个元素需要多少时间，或者想知道抛出一个异常需要多少时间，那使用profile就好像用牛刀杀鸡了。这时候一般我们先手动写如下一段代码：

import time
def profile():
    bgn = time.time()
    for i in xrange(100000):
        [].append(1)
    return time.time() - bgn
print profile()

为了测定一条语句，写了好几条代码，真的让人汗颜。更好的选择是timeit模块。

timeit除了有非常友好的编程接口，也同样提供了友好的命令行接口。首先来看看编程接口。timeit模块包含一个类Timer，它的构造函数如下：

class Timer( [stmt='pass' [, setup='pass' [, timer=<timer function>]]])

stmt参数是字符串形式的一个代码段，这个代码段将被评测运行时间；setup参数用以设置stmt的运行环境；timer可以由用户使用自定义精度的计时函数。

timeit.Timer有3个成员函数，简单介绍如下：

timeit( [number=1000000])

timeit()执行一次Timer构造函数中的setup语句之后，就重复执行number次stmt语句，然后返回总计运行消耗的时间。

repeat( [repeat=3 [, number=1000000]])

repeat()函数以number为参数调用timeit函数repeat次，并返回总计运行消耗的时间。

print_exc( [file=None])

print_exc()函数用以代替标准的tracback，原因在于print_exc()会输出错行的源代码。如：

>>> t = timeit.Timer("t = foo()/n;print t") 
>>> t.timeit()
Traceback (most recent call last):
 File "<pyshell#12>", line 1, in -toplevel-
  t.timeit()
 File "E:/Python27/lib/timeit.py", line 158, in timeit
  return self.inner(it, self.timer)
 File "<timeit-src>", line 6, in inner
  foo()
NameError: global name 'foo' is not defined

在这里NameError有点让人迷惑，foo未定义到底是来自被timeit的那段代码还是调用timeit的代码本身呢？这个场景就是print_exc()函数的用武之地了。

>>> try:
     t.timeit()
except:
     t.print_exc()
Traceback (most recent call last):
 File "<pyshell#17>", line 2, in ?
 File "E:/Python27/lib/timeit.py", line 158, in timeit
  return self.inner(it, self.timer)
 File "<timeit-src>", line 6, in inner
  t = foo()
NameError: global name 'foo' is not defined

可以看到traceback里原来的foo()变成了整行代码t=foo()，这样丰富的信息能够加速定位错误。

除了可以使用timeit的编程接口外，我们也可以在命令行里使用timeit，非常方便。

python -m timeit [-n N] [-r N] [-s S] [-t] [-c] [-h] [statement ...]

其中参数的定义如下：

-n N/--number=N，statement语句执行的次数，

-r N/--repeat=N，重复多少次调用timeit()，默认为3，

-s S/--setup=S，用以设置statement执行环境的语句，默认为“pass”。

-t/--time，计时函数，除了Windows平台外默认使用time.time()函数。

-c/--clock，计时函数，Windows平台默认使用time.clock()函数。

-v/--verbose，输出更大精度的计时数值。

-h/--help，简单的使用帮助。

小巧实用的timeit蕴藏了无限的潜能等待你去发掘。如本节开始的例子可以使用一句命令行命令搞定。

$ python -m timeit "[].append(1)"
1000000 loops, best of 3: 0.187 usec per loop