在做性能测试平台的优化过程中,由于启动任务相对其他测试任务比较频繁,而目前30次两个包的交叉对比(30次)测试需要耗时30分钟整,因此打算优先对测试流程做一次优化,将测试时间消耗降低到20分钟。
由于一开始估计乐观,认为启动时间,一台设备理论上启动顶多1s,1*2*30也就60s,加上其他开销,5分钟都够了,能减少到20分钟应该小半天就能做完了。
于是就来到了第一步:
1.review代码流程
(1)把启动流程里相关的sleep全部review一遍
确实有一点效果,因为有一部分sleep在启动任务执行阶段,60倍杠杆放大后很可怕,因此去掉部分sleep,居然就减少到了23分钟了。
第二步一时想不出了,方法耦合嵌套相当多,而且适配多个版本的产品,迁一发动全身,第二步想到的就是将可疑方法监控起来
2.将可疑方法的耗时监控起来
为了方便监控,增加了两个个装饰器来统计耗时
def costs(fn):
def _wrapper(*args, **kwargs):
start = time.time()
fn(*args, **kwargs)
print "%s 函数cost %s 秒" % (fn.__name__, time.time() - start)
return _wrapper
def costs_with_info(info):
def _wrapper(fn):
print "info: " + info
return costs(fn)
return _wrapper
当方法需要监控时,则加入@costs或者@costs_with_info("some infomation")
@costs
def configureQuickStart(self, pkg_name):
if self.config.allow_quick_start == "1":
self.logger.info("Disable quick start: %s" % pkg_name)
self.disableQuickStartSnapShot(pkg_name)
else:
self.logger.info("Quick start is enabled: %s" % pkg_name)
推荐大家不要用这样的方法,真心耗时耗力,而且效果差。花了半天优化了一分钟。
于是想到了Android里的traceview,traceview有方法能拿到整个调用栈的性能消耗,包括耗时,python应该也有这样的方法才对,然后我找到了cProfile,于是便愉快地进入了第三步
3.使用cProfile进行分析
(1)直接将入口加入监控,输出result.prof文件,并在log区打印出tottime(不包含子方法的耗时统计)
import cProfile
import pstats
cProfile.run('main()', filename='result.prof', sort="tottime")
p = pstats.Stats('result.prof')
p.sort_stats('time').print_stats()
log区打印出的日志如下
一部分是系统方法,一部分是自己的方法,不是很直观,于是又找到了另一个神器graphviz。
首先需要安装:
sudo apt-get install graphviz
然后下载Gprof2Dot,接着运行
python gprof2dot.py -f pstats result.out | dot -Tpng -o result.png
终于我得到了一张启动测试的方法耗时统计图
局部展示如下:
这样就可以很清晰看到各个函数具体消耗的时间了,但令我震惊的是,启动测试中,30分钟里居然有95.29%的时间是在sleep!但是没关系,因为我知道是哪个方法开始引入的sleep,并且可以知道哪些是可以优化的。