转载

如何进行 Python性能分析，你才能如鱼得水？

【编者按】本文作者为 Bryan Helmig，主要介绍Python 应用性能分析的三种进阶方案。文章系国内ITOM 管理平台OneAPM 编译呈现。

我们应该忽略一些微小的效率提升，几乎在 97% 的情况下，都是如此：过早的优化是万恶之源。—— Donald Knuth

如果不先想想Knuth的这句名言，就开始进行优化工作，是不明智的。然而，有时你为了获得某些特性不假思索就写下了O(N^2) 这样的代码，虽然你很快就忘记它们了，它们却可能反咬你一口，给你带来麻烦：本文就是为这种情况而准备的。

本文会介绍用于快速分析Python程序的一些有用工具和模式。主要目标很简单： 尽快发现问题，修复问题，并确认修复是行之有效的 。

编写一个测试

在教程开始前，要先写一个简单的概要测试来演示延迟。你可能需要引入一些最小数据集来重现可观的延迟。通常一或两秒的运行时间，已经足够在发现问题时，让你做出改进了。

此外，进行一些基础测试来确保你的优化不会修改缓慢代码的行为也是有必要的。在分析和调整时，你也可以多次运行这些测试，作为基准。

那么现在，我们来看第一个分析工具。

简单的计时器

计时器是简单、灵活的记录执行时间的方法。你可以把它放到任何地方，并且几乎没有副作用。自己创建计时器非常简单，并且可以根据你的喜好定制化。例如，一个简单的计时器可以这么写：

import time def timefunc(f):       def f_timer(*args, **kwargs):         start = time.time()         result = f(*args, **kwargs)         end = time.time()                 print f.__name__, 'took', end - start, 'time'                 return result          return f_timer       def get_number():       for x in xrange(5000000):               yield x  @timefunc def expensive_function():        for x in get_number():         i = x ^ x ^ x        return 'some result!' # prints "expensive_function took 0.72583088875 seconds" result = expensive_function()

当然，你可以用上下文管理器来增强它的功能，添加一些检查点或其他小功能：

import time  class timewith():        def __init__(self, name=''):         self.name = name         self.start = time.time()                 @property        def elapsed(self):              return time.time() - self.start              def checkpoint(self, name=''):               print '{timer} {checkpoint} took {elapsed} seconds'.format(             timer=self.name,             checkpoint=name,             elapsed=self.elapsed,         ).strip()                  def __enter__(self):                return self                 def __exit__(self, type, value, traceback):         self.checkpoint('finished')                 pass          def get_number():        for x in xrange(5000000):               yield x        def expensive_function():        for x in get_number():         i = x ^ x ^ x         return 'some result!'      # prints something like: # fancy thing done with something took 0.582462072372 seconds # fancy thing done with something else took 1.75355315208 seconds # fancy thing finished took 1.7535982132 seconds with timewith('fancy thing') as timer:     expensive_function()     timer.checkpoint('done with something')     expensive_function()     expensive_function()     timer.checkpoint('done with something else')      # or directly timer = timewith('fancy thing') expensive_function() timer.checkpoint('done with something')

有了计时器，你还需要进行一些“挖掘”工作。封装一些更为高级的函数，然后确定问题根源之所在，进而深入可疑的函数，不断重复。当你发现运行特别缓慢的代码之后，修复它，然后进行测试以确认修复成功。

提示：不要忘了便捷的 timeit 模块！将它用于小段代码块的基准校验比实际测试更加有用。

计时器的优点：容易理解和实施，也非常容易在修改前后进行对比，对于很多语言都适用。
计时器的缺点：有时候，对于非常复杂的代码库而已太过简单，你可能会花更多的时间创建、替换样板代码，而不是修复问题！

内建分析器

内建分析器就好像大型枪械。虽然非常强大，但是有点不太好用，有时，解释和操作起来比较困难。

你可以点此阅读更多关于内建分析模块的内容，但是内建分析器的基本操作非常简单：你启用和禁用分析器，它能记录所有的函数调用和执行时间。接着，它能为你编译和打印输出。一个简单的分析器用例如下：

import cProfile  def do_cprofile(func):       def profiled_func(*args, **kwargs):         profile = cProfile.Profile()                 try:             profile.enable()             result = func(*args, **kwargs)             profile.disable()                         return result                     finally:             profile.print_stats()             return profiled_func          def get_number():        for x in xrange(5000000):                 yield x        @do_cprofile def expensive_function():        for x in get_number():         i = x ^ x ^ x        return 'some result!'     # perform profiling result = expensive_function()

在上面代码中，控制台打印的内容如下：

         5000003 function calls in 1.626 seconds     Ordered by: standard name       ncalls  tottime  percall  cumtime  percall filename:lineno(function)      5000001    0.571    0.000    0.571    0.000 timers.py:92(get_number)            1    1.055    1.055    1.626    1.626 timers.py:96(expensive_function)            1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

如你所见，它给出了不同函数调用的详细数据。但是，它遗漏了一项关键信息：是什么原因，导致函数运行如此缓慢？

然而，这对于基础分析来说是个好的开端。有时，能够帮你尽快找到解决方案。我经常在开始调试过程时，把它作为基本测试，然后再深入测试某个不是运行缓慢，就是调用频繁的特定函数。

内建分析器的优点：没有外部依赖，运行非常快。对于快速的概要测试非常有用。
内建分析器的缺点：信息相对有限，需要进一步的调试；报告不太直观，尤其是对于复杂的代码库。

Line Profiler

如果内建分析器是大型枪械，line profiler就好比是离子炮。它非常的重量级且强大，使用起来也非常有趣。

在这个例子里，我们会用非常棒的 kernprof line-profiler，作为 line_profiler PyPi包。为了方便使用，我们会再次用装饰器进行封装，同时也可以防止我们把它留在生产代码里（因为它比蜗牛还慢）。

try:        from line_profiler import LineProfiler            def do_profile(follow=[]):               def inner(func):                      def profiled_func(*args, **kwargs):                             try:                     profiler = LineProfiler()                     profiler.add_function(func)                                         for f in follow:                         profiler.add_function(f)                     profiler.enable_by_count()                                         return func(*args, **kwargs)                              finally:                     profiler.print_stats()                      return profiled_func                return inner         except ImportError:       def do_profile(follow=[]):             "Helpful if you accidentally leave in production!"             def inner(func):                    def nothing(*args, **kwargs):                           return func(*args, **kwargs)                    return nothing              return inner       def get_number():        for x in xrange(5000000):              yield x             @do_profile(follow=[get_number]) def expensive_function():        for x in get_number():         i = x ^ x ^ x        return 'some result!'  result = expensive_function()

如果运行上面的代码，就会看到以下的报告：

Timer unit: 1e-06 s  File: test.py Function: get_number at line 43Total time: 4.44195 s  Line #      Hits         Time  Per Hit   % Time  Line Contents ==============================================================     43                                           def get_number():     44   5000001      2223313      0.4     50.1      for x in xrange(5000000):     45   5000000      2218638      0.4     49.9          yield x  File: test.py Function: expensive_function at line 47Total time: 16.828 s  Line #      Hits         Time  Per Hit   % Time  Line Contents ==============================================================     47                                           def expensive_function():     48   5000001     14090530      2.8     83.7      for x in get_number():     49   5000000      2737480      0.5     16.3          i = x ^ x ^ x     50         1            0      0.0      0.0      return 'some result!'

如你所见，这是一个非常详细的报告，能让你完全洞悉代码的运行情况。和内建的cProfiler不同，它能分析核心语言特性的耗时，比如循环或导入，并且给出不同代码行的耗时累计值。

这些细节能让我们更容易理解函数内部原理。此外，如果需要研究第三方库，你可以将其导入，直接输到装饰器中。

提示：将测试函数封装为装饰器，再将问题函数作为参数传进去就好了！