python 性能调优一则

最近几天新写的一个日志处理程序深受性能不足所困扰(每5分钟处理一次httpd日志，统计用户的连续访问和停留时间)。显然每5分钟处理过的数据必须至少保留 30 分钟后才能销毁，否则所谓连续访问无从算起。

问题是第一次处理的时候，程序很快就结束了，大概30秒；但第二次时间就增加到60秒左右，第三次时间增加到90秒上下...

很容易想到这是由于数据没有释放，导致在做查找操作的时候时间也随之延长...但我这里明明用的是 dict，应该是 o(1) 的复杂度，为什么这里表现出了线性增长关系呢？？

代码很简单，我检查了又检查，函数封装了一个又一个（为了便于profile），从 hotshot 换到 cProfile，就是找不出程序慢在何处。

从 profile 结果看，最让人惊讶的就是主函数所调用的各个子函数的用时之和远远小于主函数所消耗时间(主函数内的计算量可以忽略不计)，比如这样：

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  180.979  180.979 :1()
        1  114.522  114.522  180.979  180.979 test.py:33(main)
  5521410   32.147    0.000   32.147    0.000 {method 'split' of 'str' objects}
  5521409   16.107    0.000   24.152    0.000 test.py:7(process)
 11042818    6.586    0.000    6.586    0.000 {method 'has_key' of 'dict' objects}
  5521413    4.577    0.000    4.577    0.000 {method 'readline' of 'file' objects}
        3    3.594    1.198    3.602    1.201 test.py:20(commit)
  5521409    1.979    0.000    1.979    0.000 {method 'strip' of 'str' objects}
  3854644    1.459    0.000    1.459    0.000 {method 'append' of 'list' objects}
        3    0.000    0.000    0.008    0.003 {time.strptime}
        1    0.001    0.001    0.006    0.006 /usr/local/lib/python2.5/_strptime.py:12()
       10    0.000    0.000    0.004    0.000 /usr/local/lib/python2.5/re.py:186(compile)

总共 180 秒执行时间，但其它所有函数加起来也不超过 80 秒，另外的那 100 秒去哪里了呢？

然后就去翻 python 手册的 profile 部分，在看 timeit 的时候无意中扫过这么一段：
Note: By default, timeit() temporarily turns off garbage collection during the timing. The advantage of this approach is that it makes independent timings more comparable. This disadvantage is that GC may be an important component of the performance of the function being measured. If so, GC can be re-enabled as the first statement in the setup string.

我突然福至心灵，在代码里面禁止了自动垃圾收集，然后去测试，哈，问题立刻解决。不仅仅是丢掉的 100 秒找回来了，所有的操作速度都大大提高。原来分析5分钟数据要30秒的，现在10秒就搞定了！

这下就明白刚才的问题出在哪里了——在日志分析过程中创建出了大量的对象，而这些对象还都不能销毁，等待以后使用，结果就导致 python 频繁的 gc（陈儒的《Python源码剖析》里介绍是缺省每创建700个对象就执行一次 gc），而gc遍历队列是在线性增长的，这就表现为大量的时间被消耗掉，而且执行时间越来越长。

以前从来没有深入了解过 java，今天是第一次感受 gc 的作用 :PP

附：感觉还是 cProfile 比 hotshot 好，用 hotshot 很多系统内置函数的执行时间(比如字典的has_key, 字符串的 split)是看不到的。