背景介绍
前面提到，修复了两个主要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上，访问时需要具备科学上网的能力，祝你顺利。
网友评论