如何进行 Python性能分析，你才能如鱼得水？
a316615091
8年前
<p>我们应该忽略一些微小的效率提升，几乎在 97% 的情况下，都是如此：过早的优化是万恶之源。—— Donald Knuth</p> <p>如果不先想想Knuth的这句名言，就开始进行优化工作，是不明智的。然而，有时你为了获得某些特性不假思索就写下了O(N^2) 这样的代码，虽然你很快就忘记它们了，它们却可能反咬你一口，给你带来麻烦：本文就是为这种情况而准备的。</p> <p>本文会介绍用于快速分析Python程序的一些有用工具和模式。主要目标很简单： <strong>尽快发现问题，修复问题，并确认修复是行之有效的</strong> 。</p> <h2>编写一个测试</h2> <p>在教程开始前，要先写一个简单的概要测试来演示延迟。你可能需要引入一些最小数据集来重现可观的延迟。通常一或两秒的运行时间，已经足够在发现问题时，让你做出改进了。</p> <p>此外，进行一些基础测试来确保你的优化不会修改缓慢代码的行为也是有必要的。在分析和调整时，你也可以多次运行这些测试，作为基准。</p> <p>那么现在，我们来看第一个分析工具。</p> <h2>简单的计时器</h2> <p>计时器是简单、灵活的记录执行时间的方法。你可以把它放到任何地方，并且几乎没有副作用。自己创建计时器非常简单，并且可以根据你的喜好定制化。例如，一个简单的计时器可以这么写：</p> <pre> <code class="language-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()</code></pre> <p>当然，你可以用上下文管理器来增强它的功能，添加一些检查点或其他小功能：</p> <pre> <code class="language-python">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')</code></pre> <p>有了计时器，你还需要进行一些“挖掘”工作。 封装一些更为高级的函数，然后确定问题根源之所在，进而深入可疑的函数，不断重复。当你发现运行特别缓慢的代码之后，修复它，然后进行测试以确认修复成功。</p> <p>提示：不要忘了便捷的 <a href="/misc/goto?guid=4959673185061414171" rel="nofollow,noindex">timeit</a> 模块！将它用于小段代码块的基准校验比实际测试更加有用。</p> <ul> <li> <p>计时器的优点：容易理解和实施，也非常容易在修改前后进行对比，对于很多语言都适用。</p> </li> <li> <p>计时器的缺点：有时候，对于非常复杂的代码库而已太过简单，你可能会花更多的时间创建、替换样板代码，而不是修复问题！</p> </li> </ul> <h2>内建分析器</h2> <p>内建分析器就好像大型枪械。虽然非常强大，但是有点不太好用，有时，解释和操作起来比较困难。</p> <p>你可以 <a href="/misc/goto?guid=4959673185188732861" rel="nofollow,noindex">点此</a> 阅读更多关于内建分析模块的内容，但是内建分析器的基本操作非常简单：你启用和禁用分析器，它能记录所有的函数调用和执行时间。接着，它能为你编译和打印输出。一个简单的分析器用例如下：</p> <pre> <code class="language-python">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()</code></pre> <p>在上面代码中，控制台打印的内容如下：</p> <pre> <code class="language-python"> 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}</code></pre> <p>如你所见，它给出了不同函数调用的详细数据。但是，它遗漏了一项关键信息：是什么原因，导致函数运行如此缓慢？</p> <p>然而，这对于基础分析来说是个好的开端。有时，能够帮你尽快找到解决方案。我经常在开始调试过程时，把它作为基本测试，然后再深入测试某个不是运行缓慢，就是调用频繁的特定函数。</p> <ul> <li> <p>内建分析器的优点：没有外部依赖，运行非常快。对于快速的概要测试非常有用。</p> </li> <li> <p>内建分析器的缺点：信息相对有限，需要进一步的调试；报告不太直观，尤其是对于复杂的代码库。</p> </li> </ul> <h2>Line Profiler</h2> <p>如果内建分析器是大型枪械，line profiler就好比是离子炮。它非常的重量级且强大，使用起来也非常有趣。</p> <p>在这个例子里，我们会用非常棒的 <a href="/misc/goto?guid=4959673185294835212" rel="nofollow,noindex">kernprof</a> line-profiler，作为 <a href="/misc/goto?guid=4959673185404782724" rel="nofollow,noindex">line_profiler PyPi包</a> 。为了方便使用，我们会再次用装饰器进行封装，同时也可以防止我们把它留在生产代码里（因为它比蜗牛还慢）。</p> <pre> <code class="language-python">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()</code></pre> <p>如果运行上面的代码，就会看到以下的报告：</p> <pre> <code class="language-python">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!'</code></pre> <p>如你所见，这是一个非常详细的报告，能让你完全洞悉代码的运行情况。和内建的cProfiler不同，它能分析核心语言特性的耗时，比如循环或导入，并且给出不同代码行的耗时累计值。</p> <p>这些细节能让我们更容易理解函数内部原理。 此外，如果需要研究第三方库，你可以将其导入，直接输到装饰器中。</p> <p>提示：将测试函数封装为装饰器，再将问题函数作为参数传进去就好了！</p> <ul> <li> <p>Line Profiler 的优点：有非常直接和详细的报告。能够追踪第三方库里的函数。</p> </li> <li> <p>Line Profiler 的缺点：因为系统开销巨大，会比实际执行时间慢一个数量级，所以不要用它进行基准测试。同时，它是外部工具。</p> </li> </ul> <h2>结论和最佳方案</h2> <p>你应该使用简单的工具（比如计时器或内建分析器）对测试用例（特别是那些你非常熟悉的代码）进行基本检查，然后使用更慢但更加细致的工具，比如 line_profiler ，深入检查函数内部。</p> <p>十有八九，你会发现一个愚蠢的错误，比如在循环内重复调用，或是使用了错误的数据结构，消耗了90%的函数执行时间。在进行快速（且令人满意的）调整之后，问题就能得到解决。</p> <p>如果你仍然觉得程序运行太过缓慢，然后开始进行对比属性访问(ttribute accessing)方法，或调整相等检查(equality checking)方法等晦涩的调整，你可能已经适得其反了。你应该考虑如下方法：</p> <p>1．忍受缓慢或者预先计算/缓存</p> <p>2．重新思考整个实施方法</p> <p>3．使用更多的优化数据结构(通过 Numpy，Pandas等)</p> <p>4．编写一个 <a href="/misc/goto?guid=4959673185517280715" rel="nofollow,noindex">C扩展</a></p> <p>注意，优化代码会带来有罪恶感的快乐！寻找加速Python的合理方法很有趣，但是不要因为加速，破坏了本身的逻辑。易读的代码比运行速度更重要。实施缓存，往往是最简单的解决方法。</p> <p>教程到此为止，希望你今后的Python性能分析能够如鱼得水！</p> <p>PS: <a href="/misc/goto?guid=4959673185633625803" rel="nofollow,noindex">点此</a> 查看代码实例。此外， <a href="/misc/goto?guid=4959549104139758944" rel="nofollow,noindex">点此</a> 学习如何如鱼得水地调试 Python 程序。</p> <p>OneAPM 能帮你查看Python 应用程序的方方面面，不仅能够监控终端的用户体验，还能监控服务器性能，同时还支持追踪数据库、第三方 API 和 Web 服务器的各种问题。想阅读更多技术文章，请访问OneAPM 官方技术博客。</p> <p>via： http://blog.oneapm.com/apm-tech/700.html</p>