在我的程序中的分析器中显示，额外的时间消耗在哪里?

Question

我在我的代码中第一次使用cProfiler，并试图理解它的结果。我在这里发布了一个玩具代码来说明我的问题。有两个循环，一个在另一个里面，我不知道分析器计算的时间是多少。

例如，如果我把分析器放在主循环之外，它会正确地计算程序的运行时间(大约7秒):

prof=cProfile.Profile()
tmax=100
t=0
dt=0.1
n=10000
prof.enable()
while t<tmax:
B=[]
t=t+dt
for j in range(n):
val=dt*j
B.append(val)
B=sorted(B)
B=np.array(B)
C=B*cos(dt)
mini=min(C[C>0])
if mini==0:
mini=1  
prof.disable()
prof.print_stats()

输出:

10014023 function calls in 7.323 seconds
Ordered by: standard name
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
1    0.000    0.000    0.000    0.000 <ipython-input-59-761fc8d7f6eb>:22(<module>)
1    4.316    4.316    7.322    7.322 <ipython-input-59-761fc8d7f6eb>:8(<module>)
2    0.000    0.000    0.000    0.000 codeop.py:140(__call__)
2    0.000    0.000    0.000    0.000 hooks.py:139(__call__)
2    0.000    0.000    0.000    0.000 hooks.py:204(pre_run_code_hook)
2    0.000    0.000    0.000    0.000 interactiveshell.py:1067(user_global_ns)
2    0.000    0.000    7.322    3.661 interactiveshell.py:2852(run_code)
2    0.000    0.000    0.000    0.000 ipstruct.py:125(__getattr__)
2    0.000    0.000    0.000    0.000 {built-in method builtins.compile}
2    0.000    0.000    7.322    3.661 {built-in method builtins.exec}
1001    0.996    0.001    0.996    0.001 {built-in method builtins.min}
1001    0.119    0.000    0.119    0.000 {built-in method builtins.sorted}
1001    0.003    0.000    0.003    0.000 {built-in method math.cos}
1001    0.982    0.001    0.982    0.001 {built-in method numpy.array}
10010000    0.906    0.000    0.906    0.000 {method 'append' of 'list' objects}
1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

考虑如果我将分析器如下所示会发生什么:

prof=cProfile.Profile()
tmax=100
t=0
dt=0.1
n=10000

while t<tmax:
prof.enable()
B=[]
t=t+dt
for j in range(n):
val=dt*j
B.append(val)
B=sorted(B)
B=np.array(B)
C=B*cos(dt)
mini=min(C[C>0])
if mini==0:
print("Zero")    
prof.disable()
prof.print_stats()

输出:

10015005 function calls in 3.032 seconds
Ordered by: standard name
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
1001    1.014    0.001    1.014    0.001 {built-in method builtins.min}
1001    0.120    0.000    0.120    0.000 {built-in method builtins.sorted}
1001    0.004    0.000    0.004    0.000 {built-in method math.cos}
1001    0.963    0.001    0.963    0.001 {built-in method numpy.array}
10010000    0.930    0.000    0.930    0.000 {method 'append' of 'list' objects}
1001    0.001    0.000    0.001    0.000 {method 'disable' of '_lsprof.Profiler' objects}

在后一种情况下，如果分析器只显示最后一次while循环迭代的时间，那么它仍然没有意义，因为如果一次迭代需要3秒，那么只有2次迭代，总时间约为7秒，但会有更多的迭代发生(大约1000次)

这是怎么回事?

Answer 1

我注意到当分析器被用来分析顺序代码而不是函数时，它似乎没有给出正确的答案。

例如这里的时间和分析器的时间是非常不同的。

...
s = time.time()
prof.enable()
#line1
#line2
...
#lineN
e = time.time()
prof.disable()

，但这给出了正确的结果。当你输入line1…函数foo()

中的亚麻

...
s = time.time()
prof.enable()
foo()
e = time.time()
prof.disable()
...

所以编辑你的代码，把你想要分析的代码放在一个函数中，然后使用分析器。

Answer 2

根据报告的ncalls，很明显后一种情况显示了while循环所有1001次迭代的累积信息(由于t += 0.1的浮点不精度，它是1001而不是1000)

前者与后者的区别在于前者的例子花了4秒以上的时间来处理动作<ipython-input-59-761fc8d7f6eb>:8(<module>)

看起来您是在解释器中运行这些测试。您是否尝试过将相同的代码作为脚本运行?