Python 性能分析大全

虽然运行速度慢是 Python 与生俱来的特点,大多数时候我们用 Python 就意味着放弃对性能的追求。但是,就算是用纯 Python 完成同一个任务,老手写出来的代码可能会比菜鸟写的代码块几倍,甚至是几十倍(这里不考虑算法的因素,只考虑语言方面的因素)。很多时候,我们将自己的代码运行缓慢地原因归结于python本来就很慢,从而心安理得地放弃深入探究。

但是,事实真的是这样吗?面对python代码,你有分析下面这些问题吗:

  • 程序运行的速度如何?
  • 程序运行时间的瓶颈在哪里?
  • 能否稍加改进以提高运行速度呢?

为了更好了解python程序,我们需要一套工具,能够记录代码运行时间,生成一个性能分析报告,方便彻底了解代码,从而进行针对性的优化(本篇侧重于代码性能分析,不关注如何优化)。

谁快谁慢

假设有一个字符串,想将里面的空格替换为字符‘-’,用python实现起来很简单,下面是四种方案:

def slowest_replace():
    replace_list = []
    for i, char in enumerate(orignal_str):
        c = char if char != " " else "-"
        replace_list.append(c)
    return "".join(replace_list)

def slow_replace():
    replace_str = ""
    for i, char in enumerate(orignal_str):
        c = char if char != " " else "-"
        replace_str += c
    return replace_str

def fast_replace():
    return "-".join(orignal_str.split())

def fastest_replace():
    return orignal_str.replace(" ", "-")

这四种方案的效率如何呢,哪种方案比较慢呢?这是一个问题!

时间断点

最直接的想法是在开始 replace 函数之前记录时间,程序结束后再记录时间,计算时间差即为程序运行时间。python提供了模块 time,其中 time.clock() 在Unix/Linux下返回的是CPU时间(浮点数表示的秒数),Win下返回的是以秒为单位的真实时间(Wall-clock time)。

由于替换函数耗时可能非常短,所以这里考虑分别执行 100000次,然后查看不同函数的效率。我们的性能分析辅助函数如下:

def _time_analyze_(func):
    from time import clock
    start = clock()
    for i in range(exec_times):
        func()
    finish = clock()
    print "{:<20}{:10.6} s".format(func.__name__ + ":", finish - start)

这样就可以了解上面程序的运行时间情况:

第一种方案耗时是第四种的 45 倍多,大跌眼镜了吧!同样是 python代码,完成一样的功能,耗时可以差这么多。

为了避免每次在程序开始、结束时插入时间断点,然后计算耗时,可以考虑实现一个上下文管理器,具体代码如下:

class Timer(object):
    def __init__(self, verbose=False):
        self.verbose = verbose

    def __enter__(self):
        self.start = clock()
        return self

    def __exit__(self, *args):
        self.end = clock()
        self.secs = self.end - self.start
        self.msecs = self.secs * 1000  # millisecs
        if self.verbose:
            print 'elapsed time: %f ms' % self.msecs

使用时只需要将要测量时间的代码段放进 with 语句即可,具体的使用例子放在 gist 上。

timeit

上面手工插断点的方法十分原始,用起来不是那么方便,即使用了上下文管理器实现起来还是略显笨重。还好 Python 提供了timeit模块,用来测试代码块的运行时间。它既提供了命令行接口,又能用于代码文件之中。

命令行接口

命令行接口可以像下面这样使用:

$ python -m timeit -n 1000000 '"I like to reading.".replace(" ", "-")'
1000000 loops, best of 3: 0.253 usec per loop
$ python -m timeit -s 'orignal_str = "I like to reading."' '"-".join(orignal_str.split())'
1000000 loops, best of 3: 0.53 usec per loop

具体参数使用可以用命令 python -m timeit -h 查看帮助。使用较多的是下面的选项:

  • -s S, --setup=S: 用来初始化statement中的变量,只运行一次;
  • -n N, --number=N: 执行statement的次数,默认会选择一个合适的数字;
  • -r N, --repeat=N: 重复测试的次数,默认为3;

Python 接口

可以用下面的程序测试四种 replace函数的运行情况(完整的测试程序可以在 gist 上找到):

def _timeit_analyze_(func):
    from timeit import Timer
    t1 = Timer("%s()" % func.__name__, "from __main__ import %s" % func.__name__)
    print "{:<20}{:10.6} s".format(func.__name__ + ":", t1.timeit(exec_times))

运行结果如下:

Python的timeit提供了 timeit.Timer() 类,类构造方法如下:

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

其中:

  • stmt: 要计时的语句或者函数;
  • setup: 为stmt语句构建环境的导入语句;
  • timer: 基于平台的时间函数(timer function);

Timer()类有三个方法:

  • timeit(number=1000000): 返回stmt执行number次的秒数(float);
  • repeat(repeat=3, number=1000000): repeat为重复整个测试的次数,number为执行stmt的次数,返回以秒记录的每个测试循环的耗时列表;
  • print_exc(file=None): 打印stmt的跟踪信息。

此外,timeit 还提供了另外三个函数方便使用,参数和 Timer 差不多。

timeit.timeit(stmt='pass', setup='pass', timer=<default timer>, number=1000000)
timeit.repeat(stmt='pass', setup='pass', timer=<default timer>, repeat=3, number=1000000)
timeit.default_timer()

profile

以上方法适用于比较简单的场合,更复杂的情况下,可以用标准库里面的profile或者cProfile,它可以统计程序里每一个函数的运行时间,并且提供了可视化的报表。大多情况下,建议使用cProfile,它是profile的C实现,适用于运行时间长的程序。不过有的系统可能不支持cProfile,此时只好用profile。

可以用下面程序测试 timeit_profile() 函数运行时间分配情况。

import cProfile
from time_profile import *

cProfile.run("timeit_profile()")

这样的输出可能会很长,很多时候我们感兴趣的可能只有耗时最多的几个函数,这个时候先将cProfile 的输出保存到诊断文件中,然后用 pstats 定制更加有好的输出(完整代码在 gist 上)。

cProfile.run("timeit_profile()", "timeit")
p = pstats.Stats('timeit')
p.sort_stats('time')
p.print_stats(6)

输出结果如下:

如果觉得 pstas 使用不方便,还可以使用一些图形化工具,比如 gprof2dot 来可视化分析 cProfile 的诊断结果。

vprof

vprof 也是一个不错的可视化工具,可以用来分析 Python 程序运行时间情况。如下图:

20160613_vprof_analyze.png

line_profiler

上面的测试最多统计到函数的执行时间,很多时候我们想知道函数里面每一行代码的执行效率,这时候就可以用到 line_profiler 了。

line_profiler 的使用特别简单,在需要监控的函数前面加上 @profile 装饰器。然后用它提供的 kernprof -l -v [source_code.py] 行进行诊断。下面是一个简单的测试程序 line_profile.py:

from time_profile import slow_replace, slowest_replace

for i in xrange(10000):
    slow_replace()
    slowest_replace()

运行后结果如下:

输出每列的含义如下:

  • Line #: 行号
  • Hits: 当前行执行的次数.
  • Time: 当前行执行耗费的时间,单位为 "Timer unit:"
  • Per Hit: 平均执行一次耗费的时间.
  • % Time: 当前行执行时间占总时间的比例.
  • Line Contents: 当前行的代码

line_profiler 执行时间的估计不是特别精确,不过可以用来分析当前函数中哪些行是瓶颈。

我的博客

更多阅读

A guide to analyzing Python performance
timeit – Time the execution of small bits of Python code
Profiling Python using cProfile: a concrete case
profile, cProfile, and pstats – Performance analysis of Python programs.
How can you profile a Python script?
检测Python程序执行效率及内存和CPU使用的7种方法
代码优化概要
Python性能优化的20条建议

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,456评论 5 477
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,370评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,337评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,583评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,596评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,572评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,936评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,595评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,850评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,601评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,685评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,371评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,951评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,934评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,167评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 43,636评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,411评论 2 342

推荐阅读更多精彩内容