1. 整体介绍
1.1 性能分析

计算机科学界的大牛Donald Knuth的一句名言:“我们应该忘掉小的效率问题,大约97%的时间:过早的优化是万恶之源。”这句话的核心思想是警告程序员不要在编程初期就过分追求代码的优化,因为那时往往还没有清晰的性能瓶颈证据,盲目优化可能会导致代码的复杂性上升,反而带来更多问题。

Python性能分析,顾名思义,是指对Python程序进行性能评估,以确定代码中的瓶颈所在,进而优化程序的运行效率。性能分析不仅能帮助我们找到最耗时的部分,而且能为我们提供决策依据,让我们知道何时以及在哪里优化。

在Python中进行性能分析,通常我们会使用一些内置的工具,如cProfile和profile模块,它们可以帮助我们收集程序运行时的各项数据,例如函数调用次数、执行时间等。性能分析通常有两种方法:

  • 基于事件的性能分析,又称确定性分析,它通过监控程序运行时的关键事件(如函数调用、返回等)来记录性能数据。这种方法可以提供非常详细的性能数据,但它也可能对程序的性能产生较大的影响,因为每个事件都会被跟踪记录。
  • 统计式性能分析,又称为随机抽样分析,它并不记录程序中的每一个事件,而是在程序执行过程中随机采样,记录这些样本点的性能数据。这种方法对程序性能的干扰较小,但可能不如基于事件的分析那样详尽。然而,对于大多数情况,统计式分析所提供的数据已经足够用来指出性能瓶颈。

举个形象的例子,基于事件的性能分析就像是给跑步的运动员戴上一个记录仪,记录下每一步的速度、步长等详尽数据;而统计式分析则相当于在跑道的不同位置放置摄像头,每隔一段时间拍摄运动员的状况,从而得到一个大概的运动情况。

python之(19)CPU性能分析常见工具-LMLPHP

1.2 Python性能分析常用工具

以下是Python中常见的性能分析工具及其作用和适用场景的对比。

一般Profile等工具提供的是统计概览,不能用于性能基准测试,而是用于找出可能的性能瓶颈,一般用timeit这类工具来精确统计并进行对比

许多流行的Python IDE都集成了性能分析工具,如PyCharm的Profile工具。这些工具提供可视化界面,无需额外安装,直接在IDE中使用,适用于在开发过程中快速分析和优化代码性能。

2. CPU性能工具
2.1 timeit工具

timeit用于计算一小段 Python 代码的耗时,它有命令行接口以及一个可调用方法(作为库使用),能避免许多测量时间的常见陷阱。

timeit会多次运行代码以获取更准确的执行时间,这样可以避免因短暂的系统负载波动而导致的评估不准确。

ubuntu->~:$ python3 -m timeit '"-".join(str(n) for n in range(100))'
20000 loops, best of 5: 12.4 usec per loop
ubuntu->~:$ python3 -m timeit '"-".join([str(n) for n in range(100)])'
20000 loops, best of 5: 10.6 usec per loop
ubuntu->~:$ python3 -m timeit '"-".join(map(str, range(100)))'
50000 loops, best of 5: 8.62 usec per loop

在Python代码中使用timeit,可以这样做:

import timeit

# 使用timeit.timeit()方法
duration = timeit.timeit('"-".join(str(n) for n in range(100))', number=10000)
print(duration)

# 使用timeit.repeat()方法
durations = timeit.repeat('"-".join(str(n) for n in range(100))', repeat=5, number=10000)
print(durations)

timeit.timeit()会测试将0到99的数字转换成字符串,并用连字符连接成一个长字符串的时间,测试会运行10000次。

timeit.timeit()函数接受三个主要参数:

  1. 第一个参数是要测试的代码片段,通常以字符串形式传入。
  2. 第二个参数setup是一个可选参数,用于设置需要运行代码之前的初始化设置,可用于导入模块和函数。
  3. 第三个参数number是代码被执行的次数,默认值为1000000。

timeit.repeat()函数可以指定重复测试的次数,并返回一个包含每次测试结果的列表。这对于消除偶然性因素非常有用。

运行结果如下所示(多次测试的数据还是存在波动):

ubuntu->temp:$ python3 timeit-test.py 
0.1448463276028633
[0.12999246455729008, 0.12962577678263187, 0.1295402403920889, 0.12987900990992785, 0.13619758747518063]

更详细使用说明参考文档: timeit — 测量小代码片段的执行时间 — Python 3.11.8 文档

2.2 cProfile工具

cProfile通常用两种方式使用:

(1) 直接作为脚本运行,在命令行中使用python -m cProfile script.py,用于分析整个脚本的性能。

下面是一段测试代码,执行大量的列表和字符串化操作:

for i in range(10000):
	"-".join(str(n) for n in range(100))

保存为test.py,执行下述命令来查看耗时情况:

ubuntu->temp:$ python3 -m cProfile test.py 
         1020003 function calls in 0.278 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.005    0.005    0.278    0.278 test.py:1(<module>)
  1010000    0.165    0.000    0.165    0.000 test.py:2(<genexpr>)
        1    0.000    0.000    0.278    0.278 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    10000    0.108    0.000    0.273    0.000 {method 'join' of 'str' objects}

(2) 作为一个模块,在代码中调用,可以使用cProfile.run()函数来分析特定的代码块。

如下一段测试代码:

import cProfile

def test():
	for i in range(10000):
		"-".join(str(n) for n in range(100))

cProfile.run('test()')

保存为test2.py,运行结果如下所示:

ubuntu->temp:$ python3 test2.py 
         1020004 function calls in 0.296 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.296    0.296 <string>:1(<module>)
        1    0.005    0.005    0.296    0.296 test2.py:3(test)
  1010000    0.176    0.000    0.176    0.000 test2.py:5(<genexpr>)
        1    0.000    0.000    0.296    0.296 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    10000    0.114    0.000    0.291    0.000 {method 'join' of 'str' objects}

输出字段解释如下:

  • 第一行显示有1020004个调用被监控。如果有primitive字段,则表示这些调用不是通过递归引起的,当函数不递归时,这两个值是相同的,并且只打印单个数字。
  • Ordered by: cumulative time 表示输出是按 cumtime 值排序的。
  • ncalls,函数调用次数。
  • tottime,在指定函数中消耗的总时间(不包括调用子函数的时间)。
  • percall,是 tottime 除以 ncalls 的商。
  • cumtime,指定的函数及其所有子函数(从调用到退出)消耗的累积时间,这个数字对于递归函数来说是准确的。
  • percall,是 cumtime 除以原始调用(次数)的商(即:函数运行一次的平均时间)。
  • filename:lineno(function),提供相应数据的每个函数。

cProfile可以与另一个模块pstats一起使用,来提供报告的排序或过滤

import cProfile
import pstats

times = 0
def test():
    global times
    for i in range(10000):
        "-".join(str(n) for n in range(100))
    if times == 0:
        times = 1
        test()

# 创建一个Profile对象
profiler = cProfile.Profile()
# 启动性能分析
profiler.enable()
test()
# 停止性能分析
profiler.disable()
# 创建Stats对象
stats = pstats.Stats(profiler)
# 清除所有的统计信息
stats.strip_dirs()
# 按照调用时间对统计结果进行排序
stats.sort_stats('cumulative')
# 打印出所有统计信息
stats.print_stats()
# 可以打印出前10行排序后的统计信息
# stats.print_stats(10)

保存为test-pro.py,然后执行该文件:

ubuntu->temp:$ python3 test-pro.py 
         2040003 function calls (2040002 primitive calls) in 0.666 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      2/1    0.012    0.006    0.666    0.666 test-pro.py:5(test)
    20000    0.260    0.000    0.654    0.000 {method 'join' of 'str' objects}
  2020000    0.394    0.000    0.394    0.000 test-pro.py:8(<genexpr>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

这个排行按照函数耗时顺序,主要耗时在str(n) for n in range(100)迭代,占了0.4s,然后strjoin方法又耗费了0.25秒。

更多详细信息可参考文档: Python 性能分析器 — Python 3.11.8 文档

2.3 py-spy工具

py-spy是一个用Rust编写的性能分析工具,它可以监控Python程序的运行情况,而不需要修改代码或者重新启动程序。它对于分析生产环境中的Python程序特别有用,因为它采用了一种无侵入式的方式,即便是在高负载下也几乎不会对程序性能造成影响。使用py-spy,开发者可以实时地查看程序的CPU使用情况,并生成火焰图来可视化哪些函数占用了最多的处理器时间。

py-spy可以在大多数Unix-like系统上运行,包括Linux和macOS,同时也支持Windows(实际测试发现存在问题,且有多人报出bug)。py-spy通过读取Python进程的内存,获取程序的运行时堆栈信息,从而生成性能分析报告,因此需要高运行权限,否则会报错。

要使用py-spy,首先需要安装它。可以通过Python的包管理工具pip来安装:

pip install py-spy

安装完成后,可以通过命令行接口来运行py-spy(需要root权限)。下面是一些常见的py-spy命令和用法:

  1. 监控正在运行的Python程序。如果你已经有一个正在运行的Python程序,可以通过以下命令来监控它的性能:

    onceday->~:# py-spy top --pid 2450560
    
    
    Collecting samples from 'python3 test-pro.py' (python v3.10.6)
    Total Samples 2957
    GIL: 1.00%, Active: 2.00%, Threads: 1
    
      %Own   %Total  OwnTime  TotalTime  Function (filename)                                                                   
      2.00%   2.00%   0.160s    0.200s   test (test-pro.py)
      0.00%   0.00%   0.040s    0.040s   <genexpr> (test-pro.py)
      0.00%   2.00%   0.000s    0.200s   <module> (test-pro.py)
    

    这里的2450560应替换为目标Python进程ID(PID)。这将显示一个实时更新的列表,包括当前Python程序中的活跃函数和它们的CPU使用情况。对于给出的py-spy统计输出,我们可以逐行解释如下:

    (1) Total Samples 2957

    • 总采样数为2957,即py-spy在分析期间总共对Python程序进行了2957次采样。

    (2) GIL: 1.00%, Active: 2.00%, Threads: 1

    • GIL(Global Interpreter Lock)占用率为1.00%,表示在采样期间,Python解释器的全局解释器锁占用的时间占总时间的1.00%。
    • Active占用率为2.00%,表示在采样期间,Python程序处于活动状态(即正在执行代码)的时间占总时间的2.00%。
    • Threads为1,表示该Python程序只有一个线程在运行。

    (3) 函数执行时间统计表格:

    • %Own: 函数自身执行时间占总采样时间的百分比。
    • %Total: 函数自身及其调用的子函数执行时间占总采样时间的百分比。
    • OwnTime: 函数自身执行时间,单位为秒。
    • TotalTime: 函数自身及其调用的子函数执行时间,单位为秒。
    • Function (filename): 函数名及其所在的文件名。
  2. 生成火焰图py-spy能够生成火焰图,这是一种可视化技术,用于展示程序运行时的函数调用情况。命令如下:

    onceday->~:# py-spy record -o profile.svg --pid 2450560
    py-spy> Sampling process 100 times a second. Press Control-C to exit.
    
    ^C #主动按下Ctrl+C终止程序
    py-spy> Stopped sampling because Control-C pressed
    py-spy> Wrote flamegraph data to 'profile.svg'. Samples: 10 Errors: 0
    

    这将记录指定进程ID的Python程序,并生成一个名为profile.svg的火焰图文件,可以使用任何支持SVG格式的浏览器或图像查看器打开它。

python之(19)CPU性能分析常见工具-LMLPHP

这张火焰图是从上往下看,横向表示占据的运行时间,对于复杂程序,需要逐层分析,找到关键性能消耗点

  1. 分析Python脚本。如果想分析一个Python脚本的性能,可以直接运行该脚本并附带py-spy

    onceday->~:# py-spy top -- python3 /home/ubuntu/temp/test-pro.py
    
    
    Collecting samples from 'python3 /home/ubuntu/temp/test-pro.py' (python v3.10.6)
    Total Samples 100
    GIL: 0.00%, Active: 1.11%, Threads: 1
    
      %Own   %Total  OwnTime  TotalTime  Function (filename)                                                                   
      1.11%   1.11%   0.010s    0.010s   test (test-pro.py)
      0.00%   1.11%   0.000s    0.010s   <module> (test-pro.py)
    

    这将运行你的脚本,并且py-spy将监控其性能。

  2. 打印Python堆栈。如果想查看当前python运行堆栈,可以直接运行py-spy来打印信息。

    onceday->~:# py-spy dump --pid 2450560
    Process 2450560: python3 test-pro.py
    Python v3.10.6 (/usr/bin/python3.10)
    
    Thread 2450560 (idle)
        test (test-pro.py:6)
        <module> (test-pro.py:8)
    

在使用py-spy时,需要注意的是,由于它需要访问操作系统的进程信息,可能需要管理员或者root权限才能正常运行。此外,虽然py-spy对性能的影响很小,但在极端的高负载情况下,仍然可能对程序性能有轻微的影响。

更多详细信息请参考GitHub主页:benfred/py-spy: Sampling profiler for Python programs (github.com)

2.4 Pyinstrument工具

Pyinstrument是一个Python性能分析工具,它的主要特点是通过记录程序运行期间的函数调用栈来帮助开发者理解程序的性能瓶颈。与cProfilepy-spy等工具相比,Pyinstrument采用了不同的采样方法,它使用了所谓的统计分析技术,这种技术可以提供更容易理解的性能报告,特别是在分析复杂系统的时候。

安装Pyinstrument也很简单,可以通过pip进行安装:

pip install pyinstrument

安装完成后,就可以使用pyinstrument来分析Python代码了。Pyinstrument可以直接从命令行运行,也可以作为一个模块在代码中使用。

(1) 从命令行运行一个脚本并分析它的性能,可以这样做:

ubuntu->temp:$ pyinstrument test-pro.py
^C
  _     ._   __/__   _ _  _  _ _/_   Recorded: 15:06:13  Samples:  356
 /_//_/// /_\ / //_// / //_'/ //     Duration: 3.629     CPU time: 0.062
/   _/                      v4.6.2

Program: /usr/local/bin/pyinstrument test-pro.py

3.628 <module>  test-pro.py:1
└─ 3.628 test  test-pro.py:3
   └─ 3.628 sleep  <built-in>

To view this report with different options, run:
    pyinstrument --load-prev 2024-03-24T15-06-13 [options]

这个命令会执行test-pro.py脚本,并在执行完成后显示一个性能报告。报告将以树状结构显示函数调用,并展示每个函数在执行过程中消耗的时间。

(2) 如果你想在代码中使用Pyinstrument,可以这样写:

from pyinstrument import Profiler

profiler = Profiler()
profiler.start()

# 你的代码块
def test():
    for i in range(100000):
        "-".join(str(n) for n in range(100))
	
test()

# 停止分析并打印报告
profiler.stop()

print(profiler.output_text(unicode=True, color=True))

在这个例子中,我们首先导入pyinstrumentProfiler类,并创建一个实例。然后启动性能分析,执行我们想要分析的代码块,最后停止性能分析并打印出性能报告。Pyinstrument输出的报告非常直观,它以时间顺序展示了函数调用的层次结构,因此非常适合用来识别那些需要进一步优化的代码部分。

下面是运行结果:

ubuntu->temp:$ python3 test4.py 

  _     ._   __/__   _ _  _  _ _/_   Recorded: 15:12:20  Samples:  2901
 /_//_/// /_\ / //_// / //_'/ //     Duration: 2.902     CPU time: 2.902
/   _/                      v4.6.2

Program: test4.py

2.901 <module>  test4.py:1
└─ 2.901 test  test4.py:7
   ├─ 1.727 <genexpr>  test4.py:9
   ├─ 0.979 [self]  test4.py
   └─ 0.195 str.join  <built-in>

此外,Pyinstrument还支持生成HTML格式的报告,这使得分析结果更加易于理解和分享。生成HTML报告的命令行代码如下:

pyinstrument -r html -o report.html script.py 

这个命令将运行script.py并将HTML格式的性能报告保存到report.html文件中,然后浏览器查看数据:

python之(19)CPU性能分析常见工具-LMLPHP

非常直观,而且支持互动操作,对比复杂Python程序来说,是性能分析和优化的利器

更多信息请参考官方使用文档:User guide - pyinstrument 4.6.1 documentation

2.5 line_profiler工具

line_profiler是一种性能分析工具,专门用于对Python代码进行逐行分析,以帮助开发者发现代码中的性能瓶颈。这个工具的独特之处在于它能够提供每行代码的执行时间,从而允许开发者精确地看到程序的哪些部分在运行时消耗时间最多。

要开始使用line_profiler,首先需要通过pip安装它:

pip install line_profiler

安装完成之后,可以使用kernprof这个脚本来运行line_profilerkernprofline_profiler的一个组件,它用于运行Python脚本并进行性能分析。

使用line_profiler的一个关键步骤是对想要分析的函数使用装饰器@profile进行标记。这样做的原因是line_profiler并不会默认分析代码中的每一行,而是只分析那些被@profile装饰的函数。这样可以减少分析的开销,将关注点集中在最有可能出现性能问题的区域。下面是一个使用@profile的简单示例:

@profile
def test():
    for i in range(100000):
        "-".join(str(n) for n in range(100))

test()

在这个例子中,我们定义了一个简单的函数test,并且在定义之前使用了@profile装饰器。

接下来,要分析这个被标记的函数,我们可以使用以下命令:

kernprof -l -v script.py

这里的-l参数告诉kernprof要进行逐行的分析,而-v参数表示在分析结束后立即输出结果。script.py是Python脚本文件名。

分析完成后,line_profiler会输出一个报告,其中包含了每行代码的执行次数、每次执行的平均时间以及总时间。这样的输出对于查找代码的热点(最耗时的部分)非常有用。

执行kernprof -l -v test5.py后,会看到类似于以下的输出:

ubuntu->temp:$ kernprof -l -v test5.py
Wrote profile results to test5.py.lprof
Timer unit: 1e-06 s

Total time: 3.10574 s
File: test5.py
Function: test at line 1

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     1                                           @profile
     2                                           def test():
     3    100001      21355.7      0.2      0.7      for i in range(100000):
     4    100000    3084386.0     30.8     99.3          "-".join(str(n) for n in range(100))

这个报告显示了my_function的每行代码被执行的次数、总时间、单次执行时间和占用的总时间百分比。

  • Line #: 文件中对应的代码行。
  • Hits: 对应代码行执行的次数.
  • Time: 在计时器的单元中执行该行所花费的总时间。在表前的标题信息中,将看到一行“Timer unit:”,给出以秒为单位的转换因子。在不同的系统上可能会有所不同。
  • Per Hit: 在计时器的单元中执行一行所花费的平均时间。
  • % Time: 在该行上花费的时间相对于在函数中花费的记录时间总量的百分比。
  • Line Contents: 实际的源代码。请注意,当查看格式化的结果时,总是从磁盘读取,而不是在执行代码时。如果在此期间编辑了文件,则行将不匹配,格式化程序甚至可能无法定位要显示的函数。

详细的数据可以让开发者能够精确地了解到性能瓶颈的位置,并据此进行优化。

更多详细信息请参考GitHub主页:pyutils/line_profiler: Line-by-line profiling for Python (github.com)

2.6 Python解释器的全局解释器锁(GIL)

GIL是Python解释器用来同步线程的一种机制,以保证同一时间只有一个线程在执行Python字节码。在单核CPU上,GIL可以防止多个线程同时执行,避免了竞争条件和资源争用问题。

但是,在多核CPU上,GIL会限制Python程序的并行执行能力,因为即使有多个CPU核心可用,Python解释器也只能利用一个核心,无法充分利用多核CPU的计算资源。这就是为什么在CPU密集型的Python程序中,使用多线程并不能显著提高性能,反而可能因为GIL的存在而导致性能下降。

GIL占用时间占比较高的原因可能有以下几种:

  1. CPU密集型任务,如果Python程序中有大量的CPU密集型任务,如复杂的数值计算、图像处理等,那么GIL占用时间的比例可能会较高。因为CPU密集型任务会长时间占用CPU,导致GIL锁的争用更加频繁。

  2. 多线程竞争,如果Python程序中有多个线程在竞争GIL,那么GIL的占用时间比例可能会上升。因为当一个线程释放GIL后,其他线程会争抢GIL,这个过程会消耗一定的时间。

  3. 频繁的I/O操作,如果Python程序中有频繁的I/O操作,如读写文件、网络通信等,而这些I/O操作又夹杂在CPU密集型任务中,那么GIL占用时间的比例可能会增加。因为I/O操作会导致当前线程释放GIL,从而触发GIL的争抢。

  4. 外部库的影响,如果Python程序中使用了一些外部库,而这些库的实现没有很好地释放GIL,那么也可能导致GIL占用时间比例升高。

需要注意的是,GIL占用时间比例高并不一定意味着性能问题,还需要结合具体的程序特点和需求来分析。如果程序本身就是单线程的,或者是I/O密集型的,那么GIL的影响可能并不大。但如果程序是CPU密集型的,并且需要充分利用多核CPU的性能,那么就需要考虑使用多进程或者其他并行处理的方式来规避GIL的影响。

4. 总结

本文介绍了5种Python性能分析工具,除了CPU性能之外,还有内存分析,受限于篇幅,这里就不提及了。

Python性能分析相比于C来说,重点是如何结合到Python代码层级,至于汇编层级,则可以使用Perf分析,两者是相互结合的。

Python代码的运行性能较差,但这绝不意味着不做任何性能分析优化。参数量级增加,响应时间可能翻倍增加,在实际环境下,容易处于异常卡顿情况。如果前期就能通过性能测试找出瓶颈点,进行优化,也能避免大多数意外情况。

对于高级Python工程师,优化是必须要掌握的技能。







python之(19)CPU性能分析常见工具-LMLPHP

03-28 13:29