Python统计代码耗时的几种方法
本文实例讲述了Python中统计代码片段、函数运行耗时的几种方法，分享给大家，仅供参考。
时间戳相减
在代码执行前后各记录一个时间点，两个时间戳相减即程序运行耗时。
获取时间戳time.time()
import time
start_time = time.time()
sum = 0
for i in range(100000000):
sum += i
print(sum)
end_time = time.time()
print("耗时: {:.2f}秒".format(end_time - start_time))
输出：
4999999950000000
耗时: 10.53秒
获取当前日期 datetime.datetime.now()
import datetime
start_time = datetime.datetime.now()
sum = 0
for i in range(100000000):
sum += i
print(sum)
end_time = datetime.datetime.now()
print("耗时: {}秒".format(end_time - start_time))
装饰器
装饰器是一个装饰函数的函数，能够在不改变函数源码和函数调用方式的情况下给函数增加新的功能。很多时候统计函数的耗时，可以使用装饰器实现。
import time
def get_time(f):
def inner(*arg,**kwarg):
s_time = time.time()
res = f(*arg,**kwarg)
e_time = time.time()
print('耗时：{}秒'.format(e_time - s_time))
return res
return inner
@get_time
def test():
time.sleep(2) # 模拟运行2s
test()
输出：
耗时：2.000781536102295秒
timeit模块
timeit 模块提供了测量 Python 小段代码执行时间的方法，可以在命令行界面直接使用，也可以通过导入模块进行调用。
语句执行 number 次的时间
#导入timeit.timeit
from timeit import timeit
#看x=1的执行一次的时间（number可以省略，缺省为1000000)
t1 = timeit('x=1', number=1)
print(t1)
#一个列表生成器的执行时间,执行10000次：
t2 = timeit('[i for i in range(100) if i%2==0]', number=10000)
print(t2)
输出：
4.0000000001150227e-07
0.04841430000000002
计算函数的执行时间
from timeit import timeit
def func(a):
sum = 0
for i in range(a):
sum += i
return sum
# timeit(函数名_字符串，运行环境_字符串，number=运行次数)
t = timeit('func(10000000)', 'from __main__ import func', number=1)
print(t)
输出：
0.4887406
重复调用 timeit()
repeat() 方法相当于持续多次调用 timeit() 方法并将结果返回为一个列表。repeat 参数指定重复的次数，number 参数传递给 timeit() 方法的 number 参数。
import timeit
def func(a):
sum = 0
for i in range(a):
sum += i
return sum
# timeit(函数名_字符串，运行环境_字符串，number=运行次数,repeat=重复次数，repeat=5)
t = timeit.repeat('func(100000)', 'from __main__ import func', number=100, repeat=5)
print(t)
cProfile性能分析工具
cProfile（语言编写的测试模块）是一个标准库内建的性能分析工具，可以在标准输出中看到每一个函数被调用的次数和运行的时间，从而找到程序的性能瓶颈，从而有针对性的进行性能优化。
import cProfile
def func(a):
sum = 0
for i in range(a):
sum += i
return sum
if __name__ == '__main__':
cProfile.run("func(10000000)")
初识profile
profile是python的标准库。可以统计程序里每一个函数的运行时间，并且提供了多样化的报表。使用profile来分析一个程序很简单，举例说如果有一个程序如下：
def foo(): sum = 0 for i in range(100): sum += i return sum if __name__ == "__main__": foo() |
现在要用profile分析这个程序，很简单，把if程序块改为如下：
if __name__ == "__main__": import profile profile.run("foo()") |
我们仅仅是import了profile这个模块，然后以程序的入口函数名为参数调用了profile.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()函数是这个程序里名至实归的热点。
除了用这种方式，profile还可以直接用python解释器调用profile模块来剖分py程序，如在命令行界面输入如下命令：
python -m profile prof1.py
产生的输出跟直接修改脚本调用profile.run()函数有一样的功效。
profile的统计结果分为ncalls, tottime, percall, cumtime, percall, filename:lineno(function)等若干列：
ncalls | 函数的被调用次数 |
tottime | 函数总计运行时间，除去函数中调用的函数运行时间 |
percall | 函数运行一次的平均时间，等于tottime/ncalls |
cumtime | 函数总计运行时间，含调用的函数运行时间 |
percall | 函数运行一次的平均时间，等于cumtime/ncalls |
filename:lineno(function) | 函数所在的文件名，函数的行号，函数名 |
通常情况下，profile的输出都直接输出到命令行，而且默认是按照文件名排序输出的。这就给我们 造成了障碍，我们有时候希望能够把输出保存到文件，并且能够以各种形式来查看结果。profile简单地支持了一些需求，我们可以在 profile.run()函数里再提供一个实参，就是保存输出的文件名；同样的，在命令行参数里，我们也可以加多一个参数，用来保存profile的输 出。
用pstats自定义报表
profile解决了我们的一个需求，还有一个需求：以多种形式查看输出，我们可以通过 profile的另一个类Stats来解决。在这里我们需要引入一个模块pstats，它定义了一个类Stats，Stats的构造函数接受一个参数—— 就是profile的输出文件的文件名。Stats提供了对profile输出结果进行排序、输出控制等功能，如我们把前文的程序改为如下：
# …略 if __name__ == "__main__": import profile profile.run("foo()", "prof.txt") import pstats p = pstats.Stats("prof.txt") p.sort_stats("time").print_stats() |
引入pstats之后，将profile的输出按函数占用的时间排序，输出如下：
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有若干个函数，这些函数组合能给我们输出不同的profile报表，功能非常强大。下面简单地介绍一下这些函数：
strip_dirs() | 用以除去文件名前名的路径信息。 |
add(filename,[…]) | 把profile的输出文件加入Stats实例中统计 |
dump_stats(filename) | 把Stats的统计结果保存到文件 |
sort_stats(key,[…]) | 最重要的一个函数，用以排序profile的输出 |
reverse_order() | 把Stats实例里的数据反序重排 |
print_stats([restriction,…]) | 把Stats报表输出到stdout |
print_callers([restriction,…]) | 输出调用了指定的函数的函数的相关信息 |
print_callees([restriction,…]) | 输出指定的函数调用过的函数的相关信息 |
这里最重要的函数就是sort_stats和print_stats，通过这两个函数我们几乎可以用适当的形式浏览所有的信息了，下面来详细介绍一下。
sort_stats()接受一个或者多个字符串参数，如”time”、”name” 等，表明要根据哪一列来排序，这相当有用，例如我们可以通过用time为key来排序得知最消耗时间的函数，也可以通过cumtime来排序，获知总消耗 时间最多的函数，这样我们优化的时候就有了针对性，也就事半功倍了。sort_stats可接受的参数如下：
‘ncalls’ | 被调用次数 |
‘cumulative’ | 函数运行的总时间 |
‘file’ | 文件名 |
‘module’ | 文件名 |
‘pcalls’ | 简单调用统计（兼容旧版，未统计递归调用） |
‘line’ | 行号 |
‘name’ | 函数名 |
‘nfl’ | Name/file/line |
‘stdname’ | 标准函数名 |
‘time’ | 函数内部运行时间（不计调用子函数的时间） |
另一个相当重要的函数就是print_stats——用以根据最后一次调用sort_stats之后 得到的报表。print_stats有多个可选参数，用以筛选输出的数据；print_stats的参数可以是数字也可以是perl风格的正则表达式，相 关的内容通过其它渠道了解，这里就不详述啦，仅举三个例子：
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之一，这四个数分 别对应”stdname”, “calls”, “time”和”cumulative”；但如果你使用了数字为参数，那么pstats只按照第一个参数进行排序，其它参数将被忽略。
hotshot——更好的profile
因为profile本身的机制（如使用精确到毫秒的计时器等）导致在相当多情况下profile模块 的“测不准”问题相当严重。hotshot大部分都是用C实现的，相对于profile模块它的计时函数对性能剖分的影响就小得多，而且支持以行为单位统 计运行时间。美中不足的是hotshot不支持多线程的程序，确切来说，是它的计时核心有个关于临界段的bug；更加不幸的是，hotshot已经不再被 维护，而且可能在未来的python版本中会从标准库中移除。不过，对于没有使用多线程的程序而言，hotshot目前仍然是非常好的剖分器。
hotshot有一个Profile类，它的构造函数原型如下：
class Profile( logfile[, lineevents[, linetimings]])
logfile参数是保存剖分统计结果的文件名，lineevents表示是否统计每一行源码的运行时间，默认为0，即以函数执行时间为统计粒度，linetimings为是否记录时间信息，默认为1。下面仍然是示例：
# …略 if __name__ == "__main__": import hotshot import hotshot.stats prof = hotshot.Profile("hs_prof.txt", 1) prof.runcall(foo) prof.close() p = hotshot.stats.load("hs_prof.txt") p.print_stats() |
输出：
1 function calls in 0.003 CPU seconds Random listing order was used ncalls tottime percall cumtime percall filename:lineno(function) 1 0.003 0.003 0.003 0.003 i:/prof1.py:1(foo) 0 0.000 0.000 profile:0(profiler) |
我们可以看到来自hotshot的干扰信息比profile的少了很多，这也有利于我们分析数据找出热点。不过正如我在前面代码中使用prof = hotshot.Profile("hs_prof.txt", 1)一样，我发现使lineevents=1跟忽略linveevents参数没有什么不同，还请大家赐教。
使用hotshot能够更加灵活地统计程序的运行情况，因为hotshot.Profile提供了下面一系列的函数：
run(cmd) | 执行一段脚本，跟profile模块的run()函数一样功能 |
runcall(func, *args, **keywords) | 调用一个函数，并统计相关的运行信息 |
runctx(cmd, globals, locals) | 指定一段脚本的执行环境，执行脚本并统计运行信息 |
通过这几个函数，我们可以非常方便地建立测试的桩模块，不必再像使用profile那样手工地编写很多驱动模块了。hotshot.Profile还提供其它有用的函数，具体请参考相关的manual。
