本节书摘, 源自异步社区所出版的《高性能编程》一书里的第2章, 也就是第2.6节, 作者是戈雷利克 （Micha） , 由胡世杰、徐旭彬进行翻译, 若想查看更多章节内容, 能够前往云栖社区“异步社区”公众号去查看。
2.6 使用模块
这是内建于标准库的一个分析工具, 它钩入虚拟机, 以此测量每一个函数运行所耗费的时间, 这项技术会带来巨大开销, 然而能获得更多信息, 有时候这些额外信息会给代码带来令人惊讶的发现。
它属于标准库内建的三个分析工具当中的一个, 另外的那两个分别是和。它目前还处在实验阶段, 而那个是原始形式的纯分析器。它具备和一样的接口, 并且是默认选用的分析工具。要是你对这些库的过往历史有着兴趣, 那么可以去查看一下Armin Rigo在2005年提出的把包含进标准库的请求（）。
就分析工作而言, 一个不错的实践是, 在着手分析以前, 先针对你代码各部分的运行速度作出假设。Ian 有这样的喜好, 即把存在问题的代码打印出来, 并且予以标注。预先生成一个假设, 这表明存在一种可能性, 那就是你能测出自己错得多么离谱, 是真的能测出来, 而且这能提升你对于特定编程风格的直觉。
警告
永远不要忽视靠直觉进行的性能分析（虽然你一定会犯错！）。在分析前先进行假设是绝对值得的，因为这样可以帮助你学习如何定位你代码中可能有问题的地方，而且你应该始终用证据来证明你的选择。
持续依据你的测量所得结果, 采用一些速度快且方式粗糙的分析办法, 以此保证你所进行分析的是正确之地。没有什么情况会比在明智地对一段程序代码予以优化之后, 也许过去了数小时或者数天, 才发觉你实际上遗漏了进程中最为缓慢的部分, 并且压根就没有寻找到真正的问题所在这件事更让人感到羞耻的了。
我们的假设究竟是什么呢, 我们清楚有可能是代码当中速度最为缓慢的部分, 存在于那个函数里所做大量的解引用这一情况, 还有频繁多次调用基本的算术操作及对于abs函数的使用, 这些情况极有可能都是花销或是消耗CPU相关资源较大数量有着很大占比的厉害角色, 会耗费大量CPU资源。
这里, 我们运用模块来运行我们代码的一种变体, 其输出呈现出格式化的状态, 这便于我们弄清楚前往何处去开展进一步的分析。
进行排序, 通过 -s 开关告知对每个函数累计花费的时间进行此项操作, 这样做能够使我们瞧见代码最慢的部分, 输出会被直接打印到屏幕。
$ python -m cProfile -s cumulative julia1_nopil.py
...
36221992 function calls in 19.664 seconds
Ordered by: cumulative time
Ncalls tottime percall cumtime percall filename:lineno(function)
1 0.034 0.034 19.664 19.664 julia1_nopil.py:1()
1 0.843 0.843 19.630 19.630 julia1_nopil.py:23
(calc_pure_python)
1 14.121 14.121 18.627 18.627 julia1_nopil.py:9
(calculate_z_serial_purepython)
34219980 4.487 0.000 4.487 0.000 {abs}
2002000 0.150 0.000 0.150 0.000 {method 'append' of 'list' objects}
1 0.019 0.019 0.019 0.019 {range}
1 0.010 0.010 0.010 0.010 {sum}
2 0.000 0.000 0.000 0.000 {time.time}
4 0.000 0.000 0.000 0.000 {len}
1 0.000 0.000 0.000 0.000 {method 'disable' of
'_lsprof.Profiler' objects}
依据累计时间进行排序, 能够将大部分执行时间耗费的位置告知我们。此结果揭示, 恰恰仅在短短19秒钟的时段内, 总共产生了36 221 992次函数的调用行为（这其中的时间涵盖了使用时所产生的开销）。在此之前, 我们的代码执行所需时间为13秒——为了精准估量每个函数为执行而耗用的时间, 我们额外增添了一个为5秒的时间损耗。
我能瞧见第一行, .py的代码入口处总共用时19秒。这是经够调用达成的。为1表明这一行仅仅执行了一回。
在内部之中, 其调用所耗费的时间为18.6秒。这两个函数各自均仅执行了一回。依据此情况我们能够推断出, 大约有1秒的时长是用在了内部, 那些处于调用除外的代码部分。然而我们却没办法知晓究竟是哪几条代码行耗费了这些时间。
于内部而言, 存在这样的情况, 有一些代码行, 它们并未调用其他函数, 花在这些代码行上的时长为14.1秒, 且有某个函数调用了abs达34 219 980次, 这一同花费时长4.4秒, 除此之外存在着还有其他的一些会形成调用, 但所花时间并不多的情形。
那个被称作{abs}的究竟是什么物件呢? 这单独的一行所进行的测量, 针对的乃是对abs函数的调用行为。就每一次调用而言, 其所产生的代价基本上可以忽略不计（仅有0.000秒）, 然而这多次调用加起来总共耗费了4.4秒的时光。我们实在是没有办法去预先推测将会调用abs函数多少次, 这是由于Julia函数具备那种难以预测的动态特性所致（而这恰恰也是为何针对它的分析会如此充满趣味的原因所在）。
我们能够讲的是, 它最少会被调用1 000 000次, 这是鉴于我们要计算1000×1000个像素点。它最多会被调用300 000 000次, 这是由于我们对1 000 000个像素点最多开展300次迭代。因而三千四百万次调用仅仅是最差情况的10%。
要是我们去看原样的灰阶图, 也就是图2 - 3, 然后在脑海里头把白色的部分往角落挤压, 这样我们能够估算出费时间的白色区域大约占据了整个图的10%。
紧接着的分析输出, { '' of 'list' }, 显现出了针对2 002 000个列表项予以创建的情况标点符号。
问题
为什么是2 002 000个项目？在你读下去之前，先思考一下总共需要创建多少个项目。
2 002 000个列表项的创建发生在的设置阶段。
列表zs有1000×1000个项目, 列表cs同样有1000×1000个项目, 它们是依据1000个x坐标创建的, 也是依据1000个y坐标创建的, 所以总共需调用2 002 000次。
需留意的方面是, 其输出并非依据父函数进行排序, 它对执行的代码块的所有函数皆作了总结, 极难弄明白函数当中的每一行到底发生了何种状况, 缘故在于我们所获取到的仅仅是函数自身调用的分析信息, 而非函数内部的每一行。
在里面, 我们能够针对{abs}以及{range}予以剖析, 这两个函数的总计用时大概是4.5秒。我们清楚自身总共耗费了18.6秒。
最后一行, 由性能分析输出提及的, 乃是本工具进化至先前原始名字的情况, 此可忽略。
要想得到对于结果的更为多的控制, 咱能够弄出一个统计文件, 之后凭借去做分析。
$ python -m cProfile -o profile.stats julia1.py
我们可以这样将其调入，它会输出跟之前一样的累计时间报告：
In [1]: import pstats
In [2]: p = pstats.Stats("profile.stats")
In [3]: p.sort_stats("cumulative")
Out[3]:
In [4]: p.print_stats()
Tue Jan 7 21:00:56 2014 profile.stats
36221992 function calls in 19.983 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.033 0.033 19.983 19.983 julia1_nopil.py:1()
1 0.846 0.846 19.950 19.950 julia1_nopil.py:23
(calc_pure_python)
1 13.585 13.585 18.944 18.944 julia1_nopil.py:9
(calculate_z_serial_purepython)
34219980 5.340 0.000 5.340 0.000 {abs}
2002000 0.150 0.000 0.150 0.000 {method 'append' of 'list' objects}
1 0.019 0.019 0.019 0.019 {range}
1 0.010 0.010 0.010 0.010 {sum}
2 0.000 0.000 0.000 0.000 {time.time}
4 0.000 0.000 0.000 0.000 {len}
1 0.000 0.000 0.000 0.000 {method 'disable' of
'_lsprof.Profiler' objects}
借助以追溯我们所进行分析的函数所用方式, 我们能够针对调用者的既有信息予以打印。于紧随其后依序排列的两个列表当中, 我们能够有所察觉的是最为耗费时间的函数, 并且该函数仅仅是在唯一一个特定的地方被予以调用这般情况。要是它在多个不同的地方都被调用了的话, 那么这些先后罗列的列表极有可能会对我们成功定位到最为耗费时间的上级函数产生助力作用:
In [5]: p.print_callers()
Ordered by: cumulative time
Function was called by...
ncalls tottime cumtime
julia1_nopil.py:1() <-
julia1_nopil.py:23(calc_pure_python) <- 1 0.846 19.950
julia1_nopil.py:1()
julia1_nopil.py:9(calculate_z_serial_purepython) <- 1 13.585 18.944
julia1_nopil.py:23
(calc_pure_python)
{abs} <- 34219980 5.340 5.340
julia1_nopil.py:9
(calculate_z_serial_purepython)
{method 'append' of 'list' objects} <- 2002000 0.150 0.150
julia1_nopil.py:23
(calc_pure_python)
{range} <- 1 0.019 0.019
julia1_nopil.py:9
(calculate_z_serial_purepython)
{sum} <- 1 0.010 0.010
julia1_nopil.py:23
(calc_pure_python)
{time.time} <- 2 0.000 0.000
julia1_nopil.py:23
(calc_pure_python)
{len} <- 2 0.000 0.000
julia1_nopil.py:9
(calculate_z_serial_purepython)
2 0.000 0.000
julia1_nopil.py:23
(calc_pure_python)
{method 'disable' of '_lsprof.Profiler' objects} <-
我们还可以反过来显示哪个函数调用了其他函数：
In [6]: p.print_callees()
Ordered by: cumulative time
Function called...
ncalls tottime cumtime
julia1_nopil.py:1() -> 1 0.846 19.950
julia1_nopil.py:23
(calc_pure_python)
julia1_nopil.py:23(calc_pure_python) -> 1 13.585 18.944
julia1_nopil.py:9
(calculate_z_serial_purepython)
2 0.000 0.000
{len}
2002000 0.150 0.150
{method 'append' of 'list'
objects}
1 0.010 0.010
{sum}
2 0.000 0.000
{time.time}
julia1_nopil.py:9(calculate_z_serial_purepython) -> 34219980 5.340 5.340
{abs}
2 0.000 0.000
{len}
1 0.019 0.019
{range}
{abs} ->
{method 'append' of 'list' objects} ->
{range} ->
{sum} ->
{time.time} ->
{len} ->
{method 'disable' of '_lsprof.Profiler' objects} ->
信息输出量颇为庞大, 你得拥有一块副屏幕, 如此方可防止整字出现换行情形。它属于内建的, 为了能够快速定位瓶颈而存在的便利工具。随后, 等到我们于本章后面部分所探讨的、heapy以及相似工具, 才能够助力你深入精准地定位到, 需要你予以留意关注的具体代码行。
扫一扫
406
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
