在做性能测试平台的优化过程中,由于启动任务相对其他测试任务比较频繁,而目前 30 次两个包的交叉对比 (30 次) 测试需要耗时 30 分钟整,因此打算优先对测试流程做一次优化,将测试时间消耗降低到 20 分钟。
由于一开始估计乐观,认为启动时间,一台设备理论上启动顶多 1s,1*2*30 也就 60s,加上其他开销,5 分钟都够了,能减少到 20 分钟应该小半天就能做完了。
于是就来到了第一步:
(1)把启动流程里相关的 sleep 全部 review 一遍
确实有一点效果,因为有一部分 sleep 在启动任务执行阶段,60 倍杠杆放大后很可怕,因此去掉部分 sleep,居然就减少到了 23 分钟了。
第二步一时想不出了,方法耦合嵌套相当多,而且适配多个版本的产品,迁一发动全身,第二步想到的就是将可疑方法监控起来
为了方便监控,增加了两个个装饰器来统计耗时
- 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,于是便愉快地进入了第三步
(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
然后下载,接着运行
- python gprof2dot.py -f pstats result.out | dot -Tpng -o result.png
终于我得到了一张启动测试的方法耗时统计图
局部展示如下:
这样就可以很清晰看到各个函数具体消耗的时间了,但令我震惊的是,启动测试中,30 分钟里居然有 95.29% 的时间是在 sleep!但是没关系,因为我知道是哪个方法开始引入的 sleep, 并且可以知道哪些是可以优化的。
来源: http://www.cnblogs.com/alexkn/p/6602239.html