python 的线路分析器中的总时间很奇怪

Question

这是我的 insertion.py:

import random

#@profile
def insertion_sort(l):
    for j in range(1, len(l)):
        k = l[j]
        i = j - 1
        while i >= 0 and l[i] > k:
            l[i + 1] = l[i]
            i -= 1
        l[i + 1] = k


if __name__ == '__main__':
    l = range(5000)
    random.shuffle(l)
    insertion_sort(l)

当我运行 time python insertion.py 时，我得到：

real    0m0.823s
user    0m0.818s
sys     0m0.004s

但是当我取消注释配置文件装饰器和运行: kernprof -l -v insertion.py, 我得到:

Wrote profile results to insertion.py.lprof
Timer unit: 1e-06 s

Total time: 7.25971 s
File: insertion.py
Function: insertion_sort at line 4

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
 4                                           @profile
 5                                           def insertion_sort(l):
 6      5000         2110      0.4      0.0      for j in range(1, len(l)):
 7      4999         1929      0.4      0.0          k = l[j]
 8      4999         1719      0.3      0.0          i = j - 1
 9   6211255      2695158      0.4     37.1          while i >= 0 and l[i] > k:
10   6206256      2396675      0.4     33.0              l[i + 1] = l[i] 
11   6206256      2160158      0.3     29.8              i -= 1
12      4999         1959      0.4      0.0          l[i + 1] = k

我的问题是为什么线路分析器的总时间比系统时间大很多？我认为行分析器的 "Total time" 描述了用 @profile 装饰的函数运行ning 的时间。在我看来，time 的输出应该更大或至少接近线性分析器。我对结果的解释有误吗？线路分析器是否将自己的时间添加到 "Total time"？

Answer 1

我的结果表明 ContextualProfile adds almost no overhead in this case, but the LineProfiler 增加了大量开销。

这并不奇怪，因为 LineProfiler 执行 a bunch of code for every line。因此，以前是简单赋值或简单比较的行现在包括几个比较、函数调用和数据结构。

在我的结果中，LineProfiler 开销可以估计为每行 527 到 615 纳秒，计算方法是将总时间 (11.2287s) 除以命中数 (5000 + 4999 + 4999 + 6081512 + 6076513 + 6076513 + 4999 = 18254535 ≅ 18M)，然后减去另一个分析器的总时间除以相同的命中数。同样，这只是对开销的粗略估计。

完整的输出如下：

$ time python2 insertion.py

real    0m1.561s
user    0m1.548s
sys     0m0.012s

$ sed -i 's/^#@profile$/@profile/' insertion.py
$ kernprof -b -v insertion.py
Wrote profile results to insertion.py.prof
         5 function calls in 1.619 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    1.619    1.619    1.619    1.619 insertion.py:5(insertion_sort)
        1    0.000    0.000    0.000    0.000 kernprof.py:63(disable_by_count)
        1    0.000    0.000    0.000    0.000 {len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {range}

$ kernprof -b -l -v insertion.py
Wrote profile results to insertion.py.lprof
Timer unit: 1e-06 s

Total time: 11.2287 s
File: insertion.py
Function: insertion_sort at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           @profile
     6                                           def insertion_sort(l):
     7      5000         2819      0.6      0.0      for j in range(1, len(l)):
     8      4999         2870      0.6      0.0          k = l[j]
     9      4999         2792      0.6      0.0          i = j - 1
    10   6081512      3871421      0.6     34.5          while i >= 0 and l[i] > k:
    11   6076513      4014703      0.7     35.8              l[i + 1] = l[i]
    12   6076513      3330633      0.5     29.7              i -= 1
    13      4999         3425      0.7      0.0          l[i + 1] = k

python 的线路分析器中的总时间很奇怪

Total time in python's line profiler is strange

python

sorting

profiling