cProfile

cProfile.run

此函数接受一个可被传递给exec()函数的单独参数，以及一个可选的文件名。 在所有情况下这个例程都会执行。该函数参数为：

• command：表示需要被执行的Python代码。
• filename：指定输出文件，如果未提供文件名，则此函数会自动创建一个Stats实例并打印一个简单的性能分析报告。
• sort：排序方式，通常为cumulative。

import random
import time
import sys
import cProfile


def calc(matrix_1: list[list[int]], matrix_2: list[list[int]]):
    new_matrix = [[0 for i in range(len(matrix_2[0]))] for j in range(len(matrix_1))]
    for i in range(len(matrix_1)):
        for j in range(len(matrix_2[0])):
            for k in range(len(matrix_2)):
                new_matrix[i][j] += matrix_1[i][k] * matrix_2[k][j]
    return new_matrix


def generate_matrix(x, y):
    return [[random.randint(1, 10) for i in range(y)] for j in range(x)]


def main(x, y, z):
    m1 = generate_matrix(x, y)
    m2 = generate_matrix(y, z)
    calc(m1, m2)


if __name__ == '__main__':
    cProfile.run("main(300, 300, 400)", filename=None, sort="cumulative")

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/test.py
         1296219 function calls in 4.782 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    4.827    4.827 {built-in method builtins.exec}
        1    0.000    0.000    4.827    4.827 <string>:1(<module>)
        1    0.002    0.002    4.826    4.826 test.py:20(main)
        1    4.499    4.499    4.512    4.512 test.py:7(calc)
        2    0.000    0.000    0.313    0.156 test.py:16(generate_matrix)
        2    0.000    0.000    0.313    0.156 test.py:17(<listcomp>)
   210000    0.052    0.000    0.271    0.000 random.py:334(randint)
   210000    0.092    0.000    0.219    0.000 random.py:290(randrange)
   210000    0.088    0.000    0.127    0.000 random.py:237(_randbelow_with_getrandbits)
   335607    0.024    0.000    0.024    0.000 {method 'getrandbits' of '_random.Random' objects}
   210000    0.014    0.000    0.014    0.000 {method 'bit_length' of 'int' objects}
   120602    0.009    0.000    0.009    0.000 {built-in method builtins.len}
        1    0.000    0.000    0.004    0.004 test.py:8(<listcomp>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Process finished with exit code 0

• ncalls：函数被调用的次数。如果这一列有两个值，就表示有递归调用，第二个值是原生调用次数，第一个值是总调用次数。
• tottime：在指定函数中消耗的总时间（不包括调用子函数的时间）
• percall：是tottime除以ncalls的商，一个函数每次调用平均消耗时间。
• cumtime：指定的函数及其所有子函数（从调用到退出）消耗的累积时间。这个数字对于递归函数来说是准确的。
• filename:lineno(function)：被分析函数所在文件名，行号，函数名。

cProfile.runctx

此函数类似于run()，带有为command字符串提供全局和局部字典的附加参数。该函数参数为：

• command：表示需要被执行的Python代码。
• globals：表示全局命名空间（存放全局变量），如果被提供，则必须是一个字典对象。
• locals：表示当前局部命名空间（存放局部变量），如果被提供，可以是任何映射对象。如果该参数被忽- 略，那么它将会取与 globals 相同的值。
• filename：指定输出文件，如果未提供文件名，则此函数会自动创建一个Stats实例并打印一个简单的性能分析报告。
• sort：排序方式，通常为cumulative。

在下例中，就应当传入globals参数

# 错误版本
import random
import time
import sys
import cProfile


def calc(matrix_1: list[list[int]], matrix_2: list[list[int]]):
    new_matrix = [[0 for i in range(len(matrix_2[0]))] for j in range(len(matrix_1))]
    for i in range(len(matrix_1)):
        for j in range(len(matrix_2[0])):
            for k in range(len(matrix_2)):
                new_matrix[i][j] += matrix_1[i][k] * matrix_2[k][j]
    return new_matrix


def generate_matrix(x, y):
    return [[random.randint(1, 10) for i in range(y)] for j in range(x)]


def main_(x, y, z):
    m1 = generate_matrix(x, y)
    m2 = generate_matrix(y, z)
    calc(m1, m2)


def run():
    # 不传入globals参数，runctx找不到全局参数。
    cProfile.runctx("main_(300, 300, 400)", globals=None, locals=None, filename=None, sort="cumulative")


if __name__ == '__main__':
    run()

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/test.py
Traceback (most recent call last):
  File "C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py", line 31, in <module>
    run()
  File "C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py", line 27, in run
    cProfile.runctx("main_(300, 300, 400)", globals=None, locals=None, filename=None, sort="cumulative")
  File "C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\cProfile.py", line 19, in runctx
    return _pyprofile._Utils(Profile).runctx(statement, globals, locals,
  File "C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\profile.py", line 62, in runctx
    prof.runctx(statement, globals, locals)
  File "C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\cProfile.py", line 100, in runctx
    exec(cmd, globals, locals)
  File "<string>", line 1, in <module>
NameError: name 'main_' is not defined
         3 function calls in 0.000 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Process finished with exit code 1

# 正确版本
import random
import time
import sys
import cProfile


def calc(matrix_1: list[list[int]], matrix_2: list[list[int]]):
    new_matrix = [[0 for i in range(len(matrix_2[0]))] for j in range(len(matrix_1))]
    for i in range(len(matrix_1)):
        for j in range(len(matrix_2[0])):
            for k in range(len(matrix_2)):
                new_matrix[i][j] += matrix_1[i][k] * matrix_2[k][j]
    return new_matrix


def generate_matrix(x, y):
    return [[random.randint(1, 10) for i in range(y)] for j in range(x)]


def main_(x, y, z):
    m1 = generate_matrix(x, y)
    m2 = generate_matrix(y, z)
    calc(m1, m2)


def run():
    cProfile.runctx("main_(300, 300, 400)", globals=globals(), locals=None, filename=None, sort="cumulative")


if __name__ == '__main__':
    run()

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/test.py
         1296590 function calls in 5.618 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.672    5.672 {built-in method builtins.exec}
        1    0.001    0.001    5.672    5.672 <string>:1(<module>)
        1    0.002    0.002    5.671    5.671 test.py:20(main_)
        1    5.293    5.293    5.308    5.308 test.py:7(calc)
        2    0.000    0.000    0.362    0.181 test.py:16(generate_matrix)
        2    0.000    0.000    0.362    0.181 test.py:17(<listcomp>)
   210000    0.058    0.000    0.311    0.000 random.py:334(randint)
   210000    0.113    0.000    0.254    0.000 random.py:290(randrange)
   210000    0.101    0.000    0.141    0.000 random.py:237(_randbelow_with_getrandbits)
   335978    0.025    0.000    0.025    0.000 {method 'getrandbits' of '_random.Random' objects}
   210000    0.015    0.000    0.015    0.000 {method 'bit_length' of 'int' objects}
   120602    0.010    0.000    0.010    0.000 {built-in method builtins.len}
        1    0.000    0.000    0.005    0.005 test.py:8(<listcomp>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}



Process finished with exit code 0

cProfile.Profile

这个类通常只在需要比 cProfile.run() 函数所能提供的更精确的性能分析控制时被使用。可以通过 timer 参数提供一个自定义计时器来测量代码运行花费了多长时间。它必须是一个返回代表当前时间的单个数字的函数。如果该数字为整数，则timeunit指定一个表示每个时间单位持续时间的乘数。例如，如果定时器返回以千秒为计量单位的时间值，则时间单位将为 .001。

源码分析

class Profiler(object):
    """
    Profiler(timer=None, timeunit=None, subcalls=True, builtins=True)
    
        Builds a profiler object using the specified timer function.
        The default timer is a fast built-in one based on real time.
        For custom timer functions returning integers, timeunit can
        be a float specifying a scale (i.e. how long each integer unit
        is, in seconds).
    """
    def clear(self): # real signature unknown; restored from __doc__
        """
        clear()
        
        Clear all profiling information collected so far.
        """
        pass

    def disable(self): # real signature unknown; restored from __doc__
        """
        disable()
        
        Stop collecting profiling information. 停止收集分析数据。
        """
        pass

    def enable(self, subcalls=True, builtins=True): # real signature unknown; restored from __doc__
        """
        enable(subcalls=True, builtins=True)
        
        Start collecting profiling information. 开始收集分析数据。
        If 'subcalls' is True, also records for each function
        statistics separated according to its current caller.
        If 'builtins' is True, records the time spent in
        built-in functions separately from their caller.
        """
        pass

    def getstats(self): # real signature unknown; restored from __doc__
        """
        getstats() -> list of profiler_entry objects
        
        Return all information collected by the profiler.
        Each profiler_entry is a tuple-like object with the
        following attributes:
        
            code          code object
            callcount     how many times this was called
            reccallcount  how many times called recursively
            totaltime     total time in this entry
            inlinetime    inline time in this entry (not in subcalls)
            calls         details of the calls
        
        The calls attribute is either None or a list of
        profiler_subentry objects:
        
            code          called code object
            callcount     how many times this is called
            reccallcount  how many times this is called recursively
            totaltime     total time spent in this call
            inlinetime    inline time (not in further subcalls)
        """
        return []

class Profile(_lsprof.Profiler):
    """Profile(timer=None, timeunit=None, subcalls=True, builtins=True)

    Builds a profiler object using the specified timer function.
    The default timer is a fast built-in one based on real time.
    For custom timer functions returning integers, timeunit can
    be a float specifying a scale (i.e. how long each integer unit
    is, in seconds).
    """

    # Most of the functionality is in the base class.
    # This subclass only adds convenient and backward-compatible methods.

    # 根据当前性能分析数据创建一个 Stats 对象并将结果打印到 stdout。
    def print_stats(self, sort=-1):
        import pstats
        pstats.Stats(self).strip_dirs().sort_stats(sort).print_stats()

    # 将当前profile 的结果写入 filename 。
    def dump_stats(self, file):
        import marshal
        with open(file, 'wb') as f:
            self.create_stats()
            marshal.dump(self.stats, f)
    # 停止收集分析数据，并在内部将结果记录为当前 profile。
    def create_stats(self):
        self.disable()
        self.snapshot_stats()
    # 
    def snapshot_stats(self):
        ······

    # The following two methods can be called by clients to use
    # a profiler to profile a statement, given as a string.

    def run(self, cmd):
        import __main__
        dict = __main__.__dict__
        return self.runctx(cmd, dict, dict)

    def runctx(self, cmd, globals, locals):
        self.enable()
        try:
            exec(cmd, globals, locals)
        finally:
            self.disable()
        return self

    # This method is more useful to profile a single function call.
    # 对 func(*args, **kwargs) 进行性能分析
    def runcall(self, func, /, *args, **kw):
        self.enable()
        try:
            return func(*args, **kw)
        finally:
            self.disable()
    
    # 上下文管理器
    def __enter__(self):
        self.enable()
        return self

    def __exit__(self, *exc_info):
        self.disable()

代码案例：

import random
import cProfile
import io
import pstats
from pstats import SortKey


def calc(matrix_1: list[list[int]], matrix_2: list[list[int]]):
    new_matrix = [[0 for i in range(len(matrix_2[0]))] for j in range(len(matrix_1))]
    for i in range(len(matrix_1)):
        for j in range(len(matrix_2[0])):
            for k in range(len(matrix_2)):
                new_matrix[i][j] += matrix_1[i][k] * matrix_2[k][j]
    return new_matrix


def generate_matrix(x, y):
    return [[random.randint(1, 10) for i in range(y)] for j in range(x)]


def main_(x, y, z):
    m1 = generate_matrix(x, y)
    m2 = generate_matrix(y, z)
    calc(m1, m2)



if __name__ == '__main__':
    pr = cProfile.Profile()
    pr.enable()
    main_(100, 400, 200)
    pr.disable()
    s = io.StringIO()
    sortby = SortKey.CUMULATIVE
    ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
    ps.print_stats()
    print(s.getvalue())


# 也可使用上下文管理器
# if __name__ == '__main__':
#     with cProfile.Profile() as pr:
#     # pr = cProfile.Profile()
#         pr.enable()
#         main_(100, 400, 200)
#         pr.disable()
#     s = io.StringIO()
#     sortby = SortKey.CUMULATIVE
#     ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
#     ps.print_stats()
#     print(s.getvalue())

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/test.py
         692137 function calls in 1.356 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.390    1.390 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:55(main_)
        1    1.127    1.127    1.130    1.130 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:42(calc)
        2    0.000    0.000    0.260    0.130 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:51(generate_matrix)
        2    0.001    0.000    0.260    0.130 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:52(<listcomp>)
   120000    0.042    0.000    0.226    0.000 C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\random.py:334(randint)
   120000    0.083    0.000    0.184    0.000 C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\random.py:290(randrange)
   120000    0.073    0.000    0.100    0.000 C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\random.py:237(_randbelow_with_getrandbits)
   191828    0.017    0.000    0.017    0.000 {method 'getrandbits' of '_random.Random' objects}
   120000    0.010    0.000    0.010    0.000 {method 'bit_length' of 'int' objects}
    20202    0.002    0.000    0.002    0.000 {built-in method builtins.len}
      100    0.001    0.000    0.001    0.000 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:43(<listcomp>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


Process finished with exit code 0

pstats.Stats

类构造器会基于 filename (或文件名列表) 或者 Profile 实例创建一个“统计对象”。 输出将被打印到由 stream 所指定的流。

import pstats
# 创建Stats对象
p = pstats.Stats("./test.out")
p.print_stats()

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/analysis.py
Sun Nov 27 15:53:13 2022    ./test.out

         1296789 function calls in 5.290 seconds

   Random listing order was used

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   210000    0.089    0.000    0.128    0.000 C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\random.py:237(_randbelow_with_getrandbits)
   210000    0.094    0.000    0.221    0.000 C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\random.py:290(randrange)
   210000    0.053    0.000    0.275    0.000 C:\Users\ronie\AppData\Local\Programs\Python\Python39\lib\random.py:334(randint)
        1    0.000    0.000    0.004    0.004 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:8(<listcomp>)
        2    0.000    0.000    0.319    0.160 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:17(<listcomp>)
        1    5.004    5.004    5.016    5.016 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:7(calc)
        2    0.000    0.000    0.319    0.160 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:16(generate_matrix)
        1    0.001    0.001    5.337    5.337 C:\Users\ronie\Desktop\program\python\highPerformancePython\test.py:20(main_)
        1    0.000    0.000    5.337    5.337 <string>:1(<module>)
   336177    0.025    0.000    0.025    0.000 {method 'getrandbits' of '_random.Random' objects}
   210000    0.015    0.000    0.015    0.000 {method 'bit_length' of 'int' objects}
        1    0.000    0.000    5.337    5.337 {built-in method builtins.exec}
   120602    0.009    0.000    0.009    0.000 {built-in method builtins.len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Process finished with exit code 0

strip_dirs()

去掉无关的路径信息，如果strip_dirs()导致两个函数名变得无法区分（它们位于相同文件名的相同行，并且具有相同的函数名），那么这两个条目的统计数据将被累积到单个条目中。

import pstats
# 创建Stats对象
p = pstats.Stats("./test.out")
# p.print_stats()
p.strip_dirs().print_stats()

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/analysis.py
Sun Nov 27 15:53:13 2022    ./test.out

         1296789 function calls in 5.290 seconds

   Random listing order was used

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   210000    0.089    0.000    0.128    0.000 random.py:237(_randbelow_with_getrandbits)
   210000    0.094    0.000    0.221    0.000 random.py:290(randrange)
   210000    0.053    0.000    0.275    0.000 random.py:334(randint)
        1    0.000    0.000    0.004    0.004 test.py:8(<listcomp>)
        2    0.000    0.000    0.319    0.160 test.py:17(<listcomp>)
        1    5.004    5.004    5.016    5.016 test.py:7(calc)
        2    0.000    0.000    0.319    0.160 test.py:16(generate_matrix)
        1    0.001    0.001    5.337    5.337 test.py:20(main_)
        1    0.000    0.000    5.337    5.337 <string>:1(<module>)
   336177    0.025    0.000    0.025    0.000 {method 'getrandbits' of '_random.Random' objects}
   210000    0.015    0.000    0.015    0.000 {method 'bit_length' of 'int' objects}
        1    0.000    0.000    5.337    5.337 {built-in method builtins.exec}
   120602    0.009    0.000    0.009    0.000 {built-in method builtins.len}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Process finished with exit code 0

sort_stats()

按照某种方式排序，参数为以下：

import pstats
# 创建Stats对象
p = pstats.Stats("./test.out")
p.strip_dirs().sort_stats("cumulative").print_stats(10)

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/analysis.py
Sun Nov 27 15:53:13 2022    ./test.out

         1296789 function calls in 5.290 seconds

   Ordered by: cumulative time
   List reduced from 14 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.337    5.337 {built-in method builtins.exec}
        1    0.000    0.000    5.337    5.337 <string>:1(<module>)
        1    0.001    0.001    5.337    5.337 test.py:20(main_)
        1    5.004    5.004    5.016    5.016 test.py:7(calc)
        2    0.000    0.000    0.319    0.160 test.py:16(generate_matrix)
        2    0.000    0.000    0.319    0.160 test.py:17(<listcomp>)
   210000    0.053    0.000    0.275    0.000 random.py:334(randint)
   210000    0.094    0.000    0.221    0.000 random.py:290(randrange)
   210000    0.089    0.000    0.128    0.000 random.py:237(_randbelow_with_getrandbits)
   336177    0.025    0.000    0.025    0.000 {method 'getrandbits' of '_random.Random' objects}

Process finished with exit code 0

print_stats()

提供的参数要么是整数（选择行数），要么是介于0.0和1.0之间的小数（包括0.0和1.0）（选择行的百分比），要么就是将被解释为正则表达式的字符串（以模式匹配打印的标准名称）。如果提供了几个限制，则将依次应用这些参数。

import pstats
# 创建Stats对象
p = pstats.Stats("./test.out")
# 前十行的前10%，即一行
p.strip_dirs().sort_stats("cumulative").print_stats(10, 0.1)

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/analysis.py
Sun Nov 27 15:53:13 2022    ./test.out

         1296789 function calls in 5.290 seconds

   Ordered by: cumulative time
   List reduced from 14 to 10 due to restriction <10>
   List reduced from 10 to 1 due to restriction <0.1>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.337    5.337 {built-in method builtins.exec}



Process finished with exit code 0

import pstats
# 创建Stats对象
p = pstats.Stats("./test.out")
# 选择前30%，再进行正则匹配。
p.strip_dirs().sort_stats("cumulative").print_stats(0.3, "exec")

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/analysis.py
Sun Nov 27 15:53:13 2022    ./test.out

         1296789 function calls in 5.290 seconds

   Ordered by: cumulative time
   List reduced from 14 to 4 due to restriction <0.3>
   List reduced from 4 to 1 due to restriction <'exec'>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.337    5.337 {built-in method builtins.exec}

Process finished with exit code 0

print_callers()

查看哪些函数调用了某个函数，可以使用多参数，使用方式同print_stats()。

import pstats
# 创建Stats对象
p = pstats.Stats("./test.out")
# 查看哪些函数调用了generate_matrix。
p.strip_dirs().print_callers("generate_matrix")

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/analysis.py
   Random listing order was used
   List reduced from 14 to 1 due to restriction <'generate_matrix'>

Function                     was called by...
                                 ncalls  tottime  cumtime
test.py:16(generate_matrix)  <-       2    0.000    0.319  test.py:20(main_)

Process finished with exit code 0

print_callees()

查看某函数中调用了哪些函数

import pstats
# 创建Stats对象
p = pstats.Stats("./test.out")
p.strip_dirs().print_callees("main_")

C:\Users\ronie\Desktop\program\myenv\Scripts\python.exe C:/Users/ronie/Desktop/program/python/highPerformancePython/analysis.py
   Random listing order was used
   List reduced from 14 to 1 due to restriction <'main_'>

Function           called...
                       ncalls  tottime  cumtime
test.py:20(main_)  ->       1    5.004    5.016  test.py:7(calc)
                            2    0.000    0.319  test.py:16(generate_matrix)

Process finished with exit code 0