使用memory_profiler 与 cProfile ，line_profiler 优化Python程序运行时间和内存消耗实例

背景

一个用来分析log（XML格式）的程序，运行起来时间很长，有时候内存消耗也会很高。
使用python profiler工具来分析

使用memory_profiler 分析内存消耗

运行profiler

• 按照memory_profiler guide, 给有可能消耗内存的函数加上decorator @profile
• 开始profiler: mprof run xxx | tee $(date + “%Y%m%d%I%M_%p”).log
• 上面的命令会生成两个文件：
  
  • xxx.dat ：　后续mprof 会利用这个文件来生成内存消耗随着时间变化的曲线图
  • *.log: 这个记录了被profiler的程序的每一行消耗了多少内存

查看结果

• 命令：mprof plot

• 从上图可以看到内存消耗会慢慢上升到３.5G左右，然后会下降，最后会在１Ｇ左右震荡
• 根据时间轴，在xx.log 文件中找到对于的记录：

---

Line # Mem usage Increment Line Contents

================================================

22    115.5 MiB      0.0 MiB   @profile
23                             def adk_test_type(filename):
24    115.5 MiB      0.0 MiB       fd_xml = open(filename, 'rb')
25    115.5 MiB      0.0 MiB       print(filename)
26   3199.7 MiB   3084.1 MiB       bs_obj = BeautifulSoup(fd_xml.read(), 'xml')
27   3199.7 MiB      0.0 MiB       fd_xml.close()

这个地方分配的３０８４MiB内存，会在后续的时候被释放掉，说明python garbage collection是正常工作的, 但是因为我的server 同时开了三个虚拟机用来搭建各种服务，这个程序突然占用这么多内存会对整个server造成很大的压力，所以还是需要想办法降低内存的消耗

解决方法

• 从上面的log可以看到, 这行code　bs_obj = BeautifulSoup(fd_xml.read(), 'xml') 占用了很大的内存，通过查询这个程序的日志，发现这个时候这个 BeautifulSoup 正在处理一个１２８MB的XML 文件，通过查询源码，发现实际上这个函数只需要用到这个XML文件的一小部分

• 通过查询BeautifulSoup的文档Improving Performance by Parsing Only Part of the Document, 发现这个lib提供了一种方法 SoupStrainer,可以让我们在构建BeautifulSoup object的时候指定只构建我们需要的那一部分，在修改了相应的代码后，再次profiler 效果如下:
  

• 最高的内存消耗只有1G左右了，通过查看log，发现内存消耗很大在１Ｇ左右的地方也都是因为同样的原因，所以采用同样的方法解决就可以了。

使用cProfile 优化程序运行时间

内存消耗的原因找到了，接下来分析运行时间很长的问题。

通过cProfile 分析程序

• 命令: python -m cProfile -o “$(date +”%Y_%m_%d_%H_%m”)”.log run.py “/home/scott/temp/WER/LOG”
• 上述命令会生成一个log文件，下面分析这个log文件
  *

使用pstats 分析 cProfile log文件

import pstats
ps = pstats.Stats(“xxxx.log”)
ps.sort_stats(“cumtime”)
ps.print_stats(“dataanalysis”) # 我自己的code放在dataanalysis文件夹下面，行code目的是只打印我自己写的程序，不打印其他python 库，这样输出会更整洁，这个函数的用法参考python官方文档

输出结果如下

---

• 耗时最多的函数主要是如下几个
  
  • S3_standby_analyze_to_db | S3_Standby
  • fastestartup_analyze_to_db | analyzefaststartupfile
  • etc
    我列在同一行函数是是有调用关系的（前面的函数会调用后面的函数），根据调用关系，这些耗时比较多的函数可以分为几组，任选一组使用 line_profiler 来分析

使用 line_profiler 分析每一行代码运行的时间

给需要profile 的函数添加profile decorator: @profile

---

@profile
def S3_Standby(filename):

total_resume_time=[]
total_suspend_time=[]
total = {}

@profile
def s3standby_analyze_to_db(company,model,testrun, image,quarter,filename):
testresult = S3_Standby(filename)
logging.debug(“result for this file:” + str(testresult))

---

运行 line_profiler

kernprof -l run.py “/home/scott/temp/WER/LOG”

分析 line_profiler 的运行结果

• python -m line_profiler run.py.lprof

• 消耗时间的code和上面消耗内存的code是同样的原因，都是因为xml文件过大，导致需要很长的时间在构建这个BeautifulSoup object. 所以做出相应的优化就可以了。