在做性能测试平台的优化过程中,由于启动任务相对其他测试任务比较频繁,而目前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,并且可以知道哪些是可以优化的。