某测试模拟器性能优化-用yappi对Python程序性能调优

背景介绍

前面提到，修复了两个主要bug以后，log_generator组件的性能并没有显著的改善，这让人很郁闷。要想解决这个问题，必须要知道到底是哪些代码的执行占用了过多的CPU资源，但是这个恰恰是vprof这个工具不能做到的。因为，vprof只能显示主程序代码文件中的函数名，对于那些主程序调用的函数名就无法显示出来了。

更要命的是，之前的调优其实都不在道上，没法对主程序所有的线程进行统计。所以我们必须找到一个办法，能够对多线程程序进行profile。通过搜索，一个Python库浮出了水面，它就是yappi.

yappi介绍

其实，CPython自带三个调优工具，它们是cProfile，Profile和hotshot。他们都对多线程的性能剖析支持的不好，你必须想办法分别对线程进行profile，然后再把结果合并。而yappi的出现就是为了解决多线程程序profile问题的。

下面是一个使用yappi库，对多线程程序进行profile的代码例子。注意如果，yappi.set_clock_type函数的参数，如果是cpu，代表统计的是在CPU上执行的时间，如果是wall，代表统计的是运行的时间。

import yappi
if __name__ == "__main__":
    # yappi.set_clock_type("wall")
    yappi.set_clock_type("cpu")
    yappi.start()
    for i in range(10):
        t = threading.Thread(target=sum, args=(100, i,), name="hello"+str(i))
        t.start()
    main_thread = threading.currentThread()

    for t in threading.enumerate():
        if t is not main_thread:
            t.join()
    yappi.get_func_stats().print_all()
    yappi.get_thread_stats().print_all()

你可以按上面这个例子改造你自己多线程程序，然后运行，就会得到如下的分析结果。

Clock type: CPU
Ordered by: totaltime, desc

name                                                ncall            tsub                ttot                tavg                
..ns/2.7/lib/python2.7/threading.py:752 Thread.run  10               0.000137            2.428557            0.242856          
..thub/Asgard/samples/yappi/yappi_sample.py:16 sum  10               0.000089            2.428420            0.242842          
..ub/Asgard/samples/yappi/funcs.py:5 consumer_time  10               0.414581            2.428331            0.242833          
..s/2.7/lib/python2.7/random.py:238 Random.randint  109362           0.729320            1.926393            0.000018          
..2.7/lib/python2.7/random.py:175 Random.randrange  109362           0.860899            1.197073            0.000011          
../2.7/lib/python2.7/threading.py:726 Thread.start  10               0.000224            0.001801            0.000180          
..7/lib/python2.7/threading.py:656 Thread.__init__  10               0.000283            0.001404            0.000140          
..s/2.7/lib/python2.7/threading.py:603 _Event.wait  10               0.000152            0.001217            0.000122          
..7/lib/python2.7/threading.py:309 _Condition.wait  12               0.000423            0.001210            0.000101          
..2.7/lib/python2.7/threading.py:866 Thread.__stop  10               0.000255            0.000956            0.000096          
..s/2.7/lib/python2.7/threading.py:911 Thread.join  10               0.000257            0.000761            0.000076          
..ersions/2.7/lib/python2.7/threading.py:542 Event  10               0.000068            0.000587            0.000059          
../python2.7/threading.py:400 _Condition.notifyAll  10               0.000143            0.000580            0.000058          
..ons/2.7/lib/python2.7/threading.py:242 Condition  20               0.000169            0.000523            0.000026          
..7/lib/python2.7/threading.py:561 _Event.__init__  10               0.000153            0.000519            0.000052          
..lib/python2.7/threading.py:373 _Condition.notify  10               0.000191            0.000403            0.000040          
..b/python2.7/threading.py:260 _Condition.__init__  20               0.000286            0.000354            0.000018          
../python2.7/threading.py:300 _Condition._is_owned  22               0.000156            0.000292            0.000013          
..ib/python2.7/threading.py:709 Thread._set_daemon  10               0.000111            0.000242            0.000024          
...7/lib/python2.7/threading.py:1152 currentThread  21               0.000137            0.000205            0.000010          
..s/2.7/lib/python2.7/threading.py:64 Thread._note  54               0.000201            0.000201            0.000004          
...7/lib/python2.7/threading.py:59 Thread.__init__  40               0.000135            0.000135            0.000003          
..2.7/threading.py:297 _Condition._acquire_restore  12               0.000087            0.000130            0.000011          
..hon2.7/threading.py:294 _Condition._release_save  12               0.000071            0.000108            0.000009          
../2.7/lib/python2.7/threading.py:570 _Event.isSet  20               0.000061            0.000061            0.000003          
..b/python2.7/threading.py:1008 _MainThread.daemon  10               0.000037            0.000037            0.000004          
..ns/2.7/lib/python2.7/threading.py:1183 enumerate  1                0.000016            0.000021            0.000021          

name           id     tid              ttot      scnt        
Thread         3      123145399676928  0.087168  37        
Thread         1      123145391263744  0.087128  138       
Thread         8      123145420709888  0.087124  140       
Thread         9      123145424916480  0.087121  40        
Thread         2      123145395470336  0.087109  27        
Thread         6      123145412296704  0.087088  92        
Thread         5      123145408090112  0.087084  125       
Thread         7      123145416503296  0.087072  51        
Thread         4      123145403883520  0.087069  139       
Thread         10     123145429123072  0.087030  132       
_MainThread    0      140735541031744  0.023092  13     

上半部分是函数调用统计。

• ncall: 调用次数
• tsub: 不包含子函数所占用的CPU时间
• ttot: 包含子函数所占用的CPU时间
• tavg: 包含子函数时平均占用CPU时间

下半部分是所有线程的统计结果。

• tid 线程id
• ttot 线程总的CPU占用时间
• scnt 线程被调度到CPU上的次数

有了yappi后，我们如虎添翼，立即重新做了一轮profile。结果发现最占用CPU的果然是kafka写操作和redis读操作，这都是调用的第三方的库，基本上很难再进行优化。

那怎么办呢？当然是且听下回分解啦。

提前预告下:我们已经成功地将该组件调优到支持同时模拟100w节点在线了。

总结

读到这里，您应该已经基本了解如何使用yappi对Python多线程程序进行性能调优了吧。
另外提醒下，yappi的参考资料在googledoc上，访问时需要具备科学上网的能力，祝你顺利。