profile模块测试性能再优化程序

1.概述

当我们写好了程序后，想要测试下程序中某一部分运行的性能指标，python提供了profile模块可以在任意需要测试的代码上拿到测试的性能数据。

2.profile模块概述

python内置了两种profiler，一种是由profile模块提供的纯python版本，还有一种是由cProfile模块提供的C扩展版本。这个版本在执行测评过程中，对受测程序的影响比较小，测评结果更加准确。相反纯Python版本开销会比较大，测评结果有所偏差。

2.1.使用cProfile测评性能

下面使用cProfile模块提供的profile测评一个函数执行的性能指标，然后使用pstats模块提供的Stats统计输出测试结果。

'''普通的排序方式向列表中插入1万个整数'''
# Example 1
def insertion_sort(data):
    result = []
    for value in data:
    	# 使用普通的排序方式，向列表中插入数据
        insert_value(result, value)
    return result


# Example 2
# array是列表，value是向列表插入的数据
def insert_value(array, value):
	# 获取列表中的值 i是索引，existing是值
    for i, existing in enumerate(array):
    	# 如果列表中的这个值大于传入的值，则将value插入到列表i的位置，
    	# i上原本的值向后移动一位，实现从小到大排序
        if existing > value:
            array.insert(i, value)
            return
    array.append(value)


# Example 3
from random import randint
# 生成10000
max_size = 10**4
# 随机生成1万个整数赋值给data，for是为了循环1万次，randint是产生1万次随机整数，放到列表。
data = [randint(0, max_size) for _ in range(max_size)]
# 调用insertion_sort 排序
test = lambda: insertion_sort(data)


'''使用cProfile测评性能'''
# Example 4
from cProfile import Profile
profiler = Profile()
profiler.runcall(test)


'''使用Stats输出统计结果'''
# Example 5
from pstats import Stats
# 创建stats对象，将测试结果传入构造器
stats = Stats(profiler)
# 过滤无关的路径信息
stats.strip_dirs()
# 排序
stats.sort_stats('cumulative')
# 输出结果
stats.print_stats()

运行上面的示例代码，下面对测试输出结果做一个简单介绍。

  • ncalls：测试期间调用函数次数
  • tottime：执行这个被测函数本身花费的时间，不包含改函数调用其他函数花费时间。
  • percall：执行这个被测函数花费的平均时间，tottime除以ncalls得到平均花费时间。
  • cumtime：执行这个函数，以及该函数调用其他函数所花费的时间
  • percall：执行这个函数，以及该函数调用其他函数花费的平均时间，cumtime除以ncalls得到平均花费时间
  • filename:lineno：被执行的函数名称

从下面的统计结果可以从cumtime列看出，在执行insertion_sort所花费时间中有大部分时间都耗在了insert_value函数上，所以这个函数就是我们优化的重点。

Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.015    2.015 no_70.py:31(<lambda>)
        1    0.004    0.004    2.015    2.015 no_70.py:8(insertion_sort)
    10000    1.999    0.000    2.012    0.000 no_70.py:16(insert_value)
     9988    0.013    0.000    0.013    0.000 {method 'insert' of 'list' objects}
       12    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

2.2.打印调用栈

如果我们测试的代码中调用了工具类函数，使用上面的方式输出的结果显示时间都耗在了工具类函数上，但是不能够证明是哪个业务调用工具类函数消耗的时间，因此我们需要打印它的调用栈信息。通过调用栈可以知道谁调用了工具类，花费了多少时间。

下面通过一个调用工具类函数示例展示，打印调用栈信息。

'''工具类函数'''
# Example 8
def my_utility(a, b):
    c = 1
    for i in range(100):
        c += a * b

'''first_func，second_func 调用了工具类函数'''
def first_func():
    for _ in range(1000):
        my_utility(4, 5)

def second_func():
    for _ in range(10):
        my_utility(1, 3)

'''调用first_func，second_func函数间接调用工具类函数'''
def my_program():
    for _ in range(20):
        first_func()
        second_func()

'''测试性能，输出结果'''
from sys import stdout as STDOUT
profiler = Profile()
profiler.runcall(my_program)
stats = Stats(profiler, stream=STDOUT)
stats.strip_dirs()
stats.sort_stats('cumulative')
stats.print_stats()

运行上面的代码输出了性能测试结果，从结果中看出大部分时间都耗在了my_utility工具类函数，他被调用了20200次。从这个结果中没有告诉我们为什么会被调用这么多次，都是被谁调用的。

Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.175    0.175 no_70.py:67(my_program)
       20    0.005    0.000    0.174    0.009 no_70.py:58(first_func)
    20200    0.170    0.000    0.170    0.000 no_70.py:52(my_utility)
       20    0.000    0.000    0.002    0.000 no_70.py:62(second_func)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

为了解决上面的问题，我们可以改用print_callers方法来统计打印结果，他会输出调用栈信息。

stats = Stats(profiler, stream=STDOUT)
stats.strip_dirs()
stats.sort_stats('cumulative')
# 改用print_callers 输出调用栈信息
stats.print_callers()

运行上面的代码，输出调用栈信息。下面输出信息中，左边是被调用函数，右边是主调用函数。这样就可以看到my_utility函数被两个函数调用，调用次数最多的是first_func函数。

Ordered by: cumulative time

Function                                          was called by...
                                                      ncalls  tottime  cumtime
no_70.py:67(my_program)                           <- 
no_70.py:58(first_func)                           <-      20    0.005    0.174  no_70.py:67(my_program)
no_70.py:52(my_utility)                           <-   20000    0.169    0.169  no_70.py:58(first_func)
                                                         200    0.002    0.002  no_70.py:62(second_func)
no_70.py:62(second_func)                          <-      20    0.000    0.002  no_70.py:67(my_program)
{method 'disable' of '_lsprof.Profiler' objects}  <-