python 性能分析与个人实践

约定不等于承诺〃 2022-07-14 01:58 192阅读 0赞

*premature optimization is the root of all evil*

python 性能分析主要是时间和空间（内存）的分析

这里主要对运行时间进行分析

## 1. 在代码中加入各种log,print： ##

import time
    start_time = time.time()
    
    myfunction()  # 待测试的函数
    
    end_time = time.time()
    print 'time cost:' + str(end_time - start_time)

这种方式比较灵活可控，可以自己控制粒度，可以测试单个语句，也可以测试多个函数。

## 2.或者用装饰器： ##

def fn_timer(function):
        """这个代码来源于 http://www.marinamele.com/7-tips-to-time-python-scripts-and-control-memory-and-cpu-usage"""
        @wraps(function)
        def function_timer(*args, **kwargs):
            t0 = time.time()
            result = function(*args, **kwargs)
            t1 = time.time()
            print ("Total time running %s: %s seconds" %
                   (function.func_name, str(t1 - t0))
                   )
            return result
    
        return function_timer
    
    
    @fn_timer
    def myfunction(...):
        pass

这种方式需要在函数定义的时候就加上，但是可以保持函数的”整洁”。

但是上面的这两种方式有一定的局限性：  
1. 侵入了原有的功能代码。当然有其他方式可以处理，比如在生产中禁用记录时间的log，但记录程序的运行时间并不总是需要的。  
2. 不够灵活。假如项目比较大，核心的函数比较多，我不可能在每个函数上都做上面的操作，这样是个巨大的工程，同时代码也会变的丑陋。

## 3. 使用python的timeit模块 ##

python提供了timeit模块，这个可以在python console中直接使用

$ python -m timeit -n 4 -r 5 -s "import timing_functions" "timing_functions.random_sort(2000000)"

输出为：

4 loops, best of 5: 2.08 sec per loop

不过个人不是太喜欢这种方式，自己要敲的东西太多了，而且输出信息简陋。这个模块在ipython中使用起来相对简洁很多，直接在前面加%timeit即可。

## 4. 使用Unix命令 ##

在shell中输入下面的命令

$ time -p python timing_functions.py

得到输出：

Total time running random_sort: 1.3931210041 seconds
    real         1.49
    user         1.40
    sys          0.08

*  real 表示的是执行脚本的总时间，等于 user + sys
 *  user 表示的是执行脚本消耗的CPU时间
 *  sys 表示的是执行内核函数(操作系统)消耗的时间

## 5. 使用cProfile模块 ##

上面的方法其实还是比较简单粗暴。profile模块是个更好的[cProfile][]是profile的C实现，速度会更快。类似的包有pickle，也有个对应的Cpickle版本。  
这个包可嵌入的代码中，类似下面这种：

import cProfile
    cProfile.run("myfunction()")

我个人最喜欢的还是下面这种（下面的代码可能需要加一下PYTHONPATH）：

$python -m cProfile -o output.pkl my_main_file.py

首先无需更改现有代码结构，其次可以将结果保存到output.pkl中。强烈建议将profile的结果保存起来，因为生产中有些profile可能耗时很长，而且控制台输出的内容有限，当你想从结果里面提取点重要信息，又要重新来过，特别耗时。

当获取上面的output.pkl的时候，可以进入python console，使用pstats得到结果：

import pstats
    p = pstats.Stats('output.pkl')  # 文件名
    p.sort_stats('time')  # 按照时间排序
    p.print_stats(10)  # 最耗时的前10个，如果没有参数，默认输出全部

输出的效果如下：  
![这里写图片描述][20161123151004231]

ncalls: 函数被call的次数  
tottime：函数总的耗时，但是不包括其子函数的耗时  
percall：tottime平均到每次调用的耗时  
cumtime：函数总的耗时，包括了其子函数的耗时（递归函数也不例外）  
percall：cumtime平均到每次调用的耗时  
filename:lineno(function) ：每个函数各自的信息

## 6. 其他的工具 ##

1.  line\_profiler *可以统计每行代码的花费的CPU时间*
2.  memory\_profiler *内存分析工具*
3.  objgraph *可以快速发现内存泄漏的工具*

另外还有图形化的方式：  
1. [gprof2dot.py][]  
2. [vprof ][vprof]

## 7. 记录一次自己python性能分析历程 ##

1.  有个项目第一次上线，在上生产的过程中，我发现程序在生产环境的速度比在QA环境的要慢很多。首先猜测：我的生产环境是台物理机，QA是台虚机，应该不是CPU的问题。
2.  我检查了两个环境依赖python包的版本是否一致，其中有个numpy的小版本不一样，虽然可能性不大，但是还是调整到小版本号也一致，发现生产的速度还是慢，所以版本不一致不是原因。
3.  这个时候不能做无头苍蝇了，赶紧cprofile跑一下，得到上面的截图。可以看到，大部分的时间都在底层运算上面。因为大量依赖numpy和pandas两个包做运算，所以我猜测问题还是在这两个包上。
4.  突然想到，包安装的方式有可能造成这个情况（以前有同事遇到过这个问题）。因为conda默认安装的是已经编译好的包，而pip默认从源编译安装。使用pip这个编译的过程，能更好的跟系统兼容，提升性能。于是生产上改用pip安装了numpy，但是然并卵～～
5.  上面的可能也排除后，有点捉急。我在想既然大概率是numpy的问题，那我先不用numpy做复杂的事情，直接做简单的除法。于是写了下面的脚本，分别在QA和生产跑一下，时间还是差距很大！！！ 这个时候我有点动摇我在刚开始的认知了，我觉得有可能是CPU性能的差距！

import numpy as np
    import time
    
    t = time.time()
    for _ in range(1000):
        a = np.random.random((100, 1000))
        b = np.random.random((100, 1000))
        c = a / b
    print time.time() - t

为了验证是否是CPU的问题，我进一步写了一个小脚本，剔除numpy的影响：

import time
    import random
    
    t = time.time()
    for _ in xrange(10000000):
        a = random.random()
        b = random.random()
        c = a / b
    print time.time() - t

上面这个脚本使用纯python，没有第三方的包。对比两个环境后，我进一步确认了问题所在，是CPU的问题。

Last： 对比了两个环境的CPU型号，终于确认。虽然我的QA是虚机，但是虚机底层的物理机是最近刚采购的新机器，性能特别好，而且现在虚机资源比较充裕，没人跟我争夺资源，这个虚机基本上可以发挥物理机单核CPU的性能。反观生产环境虽然是物理机，型号却是3年前的旧机器，高下立判。我的代码是高密集的运算，在大量的循环计算后，单次计算性能的差距被放大了，导致某些函数慢了将近一倍！

## 一些补充的连接： ##

1.  [http://selfboot.cn/2016/06/13/python\_performance\_analysis/][http_selfboot.cn_2016_06_13_python_performance_analysis]
2.  [https://www.huyng.com/posts/python-performance-analysis][https_www.huyng.com_posts_python-performance-analysis]
3.  [https://segmentfault.com/a/1190000000616798][https_segmentfault.com_a_1190000000616798]
4.  [http://www.marinamele.com/7-tips-to-time-python-scripts-and-control-memory-and-cpu-usage][http_www.marinamele.com_7-tips-to-time-python-scripts-and-control-memory-and-cpu-usage]

[cProfile]: https://docs.python.org/2/library/profile.html
[20161123151004231]: /images/20220714/6a9a2e93bad64fbc81422a0569361423.png
[gprof2dot.py]: http://blog.csdn.net/u012927281/article/details/51132064
[vprof]: https://github.com/nvdv/vprof
[http_selfboot.cn_2016_06_13_python_performance_analysis]: http://selfboot.cn/2016/06/13/python_performance_analysis/
[https_www.huyng.com_posts_python-performance-analysis]: https://www.huyng.com/posts/python-performance-analysis
[https_segmentfault.com_a_1190000000616798]: https://segmentfault.com/a/1190000000616798
[http_www.marinamele.com_7-tips-to-time-python-scripts-and-control-memory-and-cpu-usage]: http://www.marinamele.com/7-tips-to-time-python-scripts-and-control-memory-and-cpu-usage