Python性能分析器 -- line_profiler

  |  

摘要: 《Python性能分析与优化》关于 line_profiler 的笔记

【对算法,数学,计算机感兴趣的同学,欢迎关注我哈,阅读更多原创文章】
我的网站:潮汐朝夕的生活实验室
我的公众号:算法题刷刷
我的知乎:潮汐朝夕
我的github:FennelDumplings
我的leetcode:FennelDumplings


在文章Python性能分析基础中,我们学习了性能分析的基础知识方法论,如果把性能分析方法整合到开发过程中,就可以帮助我们提高产品的开发质量。

然后在文章 Python性能分析器 — cProfile 中,我们进一步学习了 cProfile 这个性能分析器。之后在文章 使用cProfile进行性能分析与优化实践 中,我们通过计算斐波那契数和读取大 csv 文件并做简单统计的两个例子进行了 cProfile 性能分析和优化的实践。

通过 cProfile 我们可以对代码进行性能分析,获取每个函数的调用次数和总调用次数。它帮助我们通过系统全局视角改进代码。

本文我们将学习另一种性能分析器,它可以为我们提供每一行代码的性能细节,这是cProfile无法提供的

line_profiler

其他性能分析器主要关注函数调用消耗的CPU时间。大多数情况下,这足以发现问题,消除瓶颈(就像我们之前看到的那样)。但是,有时候,瓶颈问题发生在函数的某一行中,这时就需要line_profiler解决了。

line_profiler 安装

1
pip install line_profiler

line_profiler 的使用

(1) 直接使用 line_profiler

使用 line_profiler 进行性能分析,有两种方式可以获得函数的性能分析数据:用构造器或者用add_function方法。

line_profiler 和 cProfile.Profile 一样,也提供了下列方法。但是enable 和 disable在嵌入模块统计性能时并不安全,使用时要当心。

1
2
3
4
5
run
runctx
runcall
enable
disable

进行性能分析之后, 可以用dump_stats(filename)方法把stats加载到文件中。也可以用print_stats([stream])方法打印结果。它会把结果打印到sys.stdout里,或者任何其他设置成参数的数据流中。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
import line_profiler
import sys

def test():
for i in range(10):
print(i ** 2)
print("End of the function")

# pass in the function to profile
prof = line_profiler.LineProfiler(test)

prof.enable() # start profiling
test()
prof.disable() # stop profiling

prof.print_stats(sys.stdout) # print out the results

profile 信息

1
2
3
4
5
6
7
8
9
10
11
12
Timer unit: 1e-06 s

Total time: 8.1e-05 s
File: test.py
Function: test at line 5

Line # Hits Time Per Hit % Time Line Contents
==============================================================
5 def test():
6 11 10.0 0.9 12.3 for i in range(10):
7 10 68.0 6.8 84.0 print(i ** 2)
8 1 3.0 3.0 3.7 print("End of the function")

结果会显示函数的每一行,旁边是时间信息。共六列,出去代码行外的另外五列的含义如下

Line #: 表示文件中的行号。
Hits: 性能分析时一行代码的执行次数。
Time: 一行代码执行的总时间,由计时器的单位决定。在分析结果的最开始有一行Timer unit,该数值就是转换成秒的计时单位(要计算总时间,需要用Time数值乘以计时单位)。不同系统的计时单位可能不同。
Per hit: 执行一行代码的平均消耗时间,依然由系统的计时单位决定。
% Time: 执行一行代码的时间消耗占程序总消耗时间的比例。

(2) kernprof 工具

line_profiler 作者建议使用 kernprof 工具。kernprof 会创建一个性能分析器实例,并把名字添加到 __builtins__ 命名空间的 profile 中。

line_profiler 性能分析器被设计成一个装饰器,可以装饰任何一个函数,它会统计每一行消耗的时间。

kernprof 与 line_profiler 是集成在一起的。kernprof 将为我们做以下事情:

  • 它将和cProfile、lsprof甚至profile模块一起工作,具体要看哪一个性能分析器可用。
  • 它会自动寻找脚本文件,如果文件不在当前文件夹,它会检测PATH路径。
  • 将实例化分析器,并把名字添加到builtins命名空间的profile中。这样我们就可以在代码中使用性能分析器了。我们甚至可以直接把它当作装饰器用,不需要导入。
  • stats性能分析文件的查看方式,下面的第二种和第三种注意后缀不一样
    • 用pstats.Stats类
    • python -m pstats stats_file.py.prof
    • python -m line_profiler stats_file.py.lprof

例如: test.py 内容如下

1
2
3
4
5
6
7
8
9
10
import line_profiler

@profile
def fib(n):
a, b = 0, 1
for i in range(n):
a, b = b, a + b
return a

fib(int(1e5))

用以下命令执行性能分析器,被装饰的函数将被分析。

1
kernprof -l test.py

kernprof默认情况下会把分析结果写入test.py.lprof文件

可以用 -v 在命令行直接显示结果。

1
kernprof -l -v test.py

profile 结果如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
Wrote profile results to test2.py.lprof
Timer unit: 1e-06 s

Total time: 0.169616 s
File: test2.py
Function: fib at line 3

Line # Hits Time Per Hit % Time Line Contents
==============================================================
3 @profile
4 def fib(n):
5 1 1.0 1.0 0.0 a, b = 0, 1
6 100001 31797.0 0.3 18.7 for i in range(n):
7 100000 137817.0 1.4 81.3 a, b = b, a + b
8 1 1.0 1.0 0.0 return a

在读取kernprof的输出结果时,有两件事情需要注意。

  • 在性能分析函数调用另一个函数时,没有把每一行消耗的时间增加到总时间上:当完成一个函数的性能分析时,可能会发生之前的函数分析结果没有加到总时间上的情况。这是因为kernprof只记录函数内部消耗的时间,以免对程序造成额外的负担。
  • 分析报告中,列表综合(list comprehension)表达式的Hit比它们实际消耗的要多很多:基本上是因为对表达式进行性能分析时,分析报告对每次迭代增加了一个Hit。

line_profiler 性能分析实例: 斐波那契数

在文章中 使用cProfile进行性能分析与优化实践 中我们用 cProfile 分析了斐波那契数的优化过程。共有原始的递归实现 fib,递归改迭代的实现 fib_seq,以及递归、迭代分别加上装饰器缓存。

这里用 line_profiler 对这四种实现进行分析,先分析不加装饰器缓存的递归和迭代实现。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
import line_profiler

class cached:
def __init__(self, fn):
self.fn = fn
self.cache = {}

def __call__(self, *args):
try:
return self.cache[args]
except KeyError:
self.cache[args] = self.fn(*args)
return self.cache[args]

@profile
def fib_iter(n):
a, b = 0, 1
for i in range(0, n):
a, b = b, a+b
return a

@profile
def fib(n):
if n <= 1:
return n
else:
return fib(n-1) + fib(n-2)

@profile
def fib_seq(n):
seq = [ ]
for i in range(0, n + 1):
seq.append(fib(i))
return seq

@profile
def fib_iter_seq(n):
seq = [ ]
for i in range(0, n + 1):
seq.append(fib_iter(i))
return seq

fib_seq(30)
fib_iter_seq(30)

性能分析器输出结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
Wrote profile results to fibo.py.lprof
Timer unit: 1e-06 s

Total time: 0.000282 s
File: fibo.py
Function: fib_iter at line 15

Line # Hits Time Per Hit % Time Line Contents
==============================================================
15 @profile
16 def fib_iter(n):
17 31 11.0 0.4 3.9 a, b = 0, 1
18 496 135.0 0.3 47.9 for i in range(0, n):
19 465 134.0 0.3 47.5 a, b = b, a+b
20 31 2.0 0.1 0.7 return a

Total time: 5.93703 s
File: fibo.py
Function: fib at line 22

Line # Hits Time Per Hit % Time Line Contents
==============================================================
22 @profile
23 def fib(n):
24 7049123 2113346.0 0.3 35.6 if n <= 1:
25 3524577 847516.0 0.2 14.3 return n
26 else:
27 3524546 2976165.0 0.8 50.1 return fib(n-1) + fib(n-2)

Total time: 16.4287 s
File: fibo.py
Function: fib_seq at line 29

Line # Hits Time Per Hit % Time Line Contents
==============================================================
29 @profile
30 def fib_seq(n):
31 1 1.0 1.0 0.0 seq = [ ]
32 32 15.0 0.5 0.0 for i in range(0, n + 1):
33 31 16428689.0 529957.7 100.0 seq.append(fib(i))
34 1 1.0 1.0 0.0 return seq

Total time: 0.000567 s
File: fibo.py
Function: fib_iter_seq at line 36

Line # Hits Time Per Hit % Time Line Contents
==============================================================
36 @profile
37 def fib_iter_seq(n):
38 1 1.0 1.0 0.2 seq = [ ]
39 32 10.0 0.3 1.8 for i in range(0, n + 1):
40 31 555.0 17.9 97.9 seq.append(fib_iter(i))
41 1 1.0 1.0 0.2 return seq

在fib函数里,没有一行代码消耗了太多时间也就是 Per-Hit 很小(,也不应该消耗很多时间)。在fib_seq里面,只有一行消耗了大量时间,但那是因为递归是在fib里面运行的。所以要解决的问题就是降低递归的次数。

在 fib_iter 和 fib 上均价上 cached 装饰器缓存。其余代码不变。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
@cached
@profile
def fib_iter(n):
a, b = 0, 1
for i in range(0, n):
a, b = b, a+b
return a

@cached
@profile
def fib(n):
if n <= 1:
return n
else:
return fib(n-1) + fib(n-2)

性能分析器的结果如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
Wrote profile results to fibo.py.lprof
Timer unit: 1e-06 s

Total time: 0.000295 s
File: fibo.py
Function: fib_iter at line 15

Line # Hits Time Per Hit % Time Line Contents
==============================================================
15 @cached
16 @profile
17 def fib_iter(n):
18 31 9.0 0.3 3.1 a, b = 0, 1
19 496 120.0 0.2 40.7 for i in range(0, n):
20 465 159.0 0.3 53.9 a, b = b, a+b
21 31 7.0 0.2 2.4 return a

Total time: 4.8e-05 s
File: fibo.py
Function: fib at line 23

Line # Hits Time Per Hit % Time Line Contents
==============================================================
23 @cached
24 @profile
25 def fib(n):
26 31 10.0 0.3 20.8 if n <= 1:
27 2 1.0 0.5 2.1 return n
28 else:
29 29 37.0 1.3 77.1 return fib(n-1) + fib(n-2)

Total time: 0.000157 s
File: fibo.py
Function: fib_seq at line 31

Line # Hits Time Per Hit % Time Line Contents
==============================================================
31 @profile
32 def fib_seq(n):
33 1 1.0 1.0 0.6 seq = [ ]
34 32 9.0 0.3 5.7 for i in range(0, n + 1):
35 31 147.0 4.7 93.6 seq.append(fib(i))
36 1 0.0 0.0 0.0 return seq

Total time: 0.000656 s
File: fibo.py
Function: fib_iter_seq at line 38

Line # Hits Time Per Hit % Time Line Contents
==============================================================
38 @profile
39 def fib_iter_seq(n):
40 1 0.0 0.0 0.0 seq = [ ]
41 32 10.0 0.3 1.5 for i in range(0, n + 1):
42 31 646.0 20.8 98.5 seq.append(fib_iter(i))
43 1 0.0 0.0 0.0 return seq

fib 的 Hit 数量大幅下降(7049123 -> 31)。


Share