快速调试你的Python程序

Profiling(性能调试)是我一直很感兴趣的一个话题,之前给大家介绍过Datadog这个工具,今天我们来看看Python语言中有哪些方法来做Profiling。

Poorman’s Profiler

最基础的就是使用time.time()来计时,这个方法简单有效,也许所有写过Python代码的人都用过。我们可以创建一个decorator使它用起来更方便。

这个方法的优点是简单,额外开效非常低(大部分情况下可以忽略不计)。但缺点也很明显,除了总用时,没有任何其他信息。

cProfile

cProfile是Python标准库中的一个模块,它可以非常仔细地分析代码执行过程中所有函数调用的用时和次数。cProfile最简单的用法是用cProfile.run来执行一段代码,或是用python -m cProfile myscript.py来执行一个脚本。例如,

以上代码的执行结果如下

完整的结果很长,这里我只截取了一部分。结果中每一行包含一个函数的执行信息,每个字段的含义如下

  • ncalls: 该函数被调用的次数

  • tottime: 该函数的总耗时,子函数的调用时间不计算在内

  • percall: tottime / ncalls

  • cumtime: 该函数加上其所有子函数的总耗时

  • percall: cumtime / ncalls

这里我们看到requests.get的时间主要是花费在_socket.getaddrinfo_socket.socket.recv这两个子函数上,其中_socket.getaddrinfo被调用了一次,而_socket.socket.recv被调用了3次。

虽然cProfile.run用起来非常直观,但在实际调试时并不灵活,并且最后打印出来的信息过于冗长。我们可以通过写一个decorator让cProfile的使用更方便,但这里我想介绍Python中另一个非常好用的特性,那就是contextmanager。Decorator用来包裹一个函数,而contextmanager则用来包裹一个代码块。例如,我们希望用cProfile来调试一个代码块,可以创建如下的contextmanager

这样就可以很方便地用with语法对一段代码进行性能调试,以上代码的执行结果如下

因为这里的结果按tottime排序,并且只显示最费时的5个函数,所以看起来要比之前的结果清晰很多。

Line Profiler

与cProfile相比,Line Profiler的结果更加直观,它可以告诉你一个函数中每一行的耗时。Line
Profiler并不在标准库中,需要用pip来安装

Line Profiler的使用方法与cProfile类似,同样建议为其创建decorator或是contextmanager来方便使用。具体代码可以看这里。

例如,我们用Line Profiler来调试urlparse.parse_qsl函数,其输出结果如下

Line Profiler的结果虽然直观,但由于它不能显示子函数运行的详细信息,所以实际可以使用的场景比较有限。

定制低开销的Profiler

cProfile虽然是非常不错的性能调试工具,应用场景也很广泛,但它最主要的缺点是有很大的额外开销(overhead)。这使cProfile不适合在生产环境中使用,而且过大的额外开销有时会导致Profiler打开与关闭状态下代码的性能瓶颈不一致。

cProfile高开销来自于它对每一个函数调用进行计时,但很多时候,其实我们只关心某些类库的执行时间。以典型的网络移动应用的服务程序为例,它们的大部分时间花费在I/O上,我们在做性能分析时,关心的是在响应用户请求时,服务器在RPC,Cache和DB这些I/O操作上各花费了多少时间。如果更细致一些,我们也许会关心在一次用户请求中,DB的select/insert/update各被调用了多少次,花费了多少时间。

如果大家熟悉如New Relic之类的APM服务(Application Performance
Monitoring),它们可以将每一个web请求的响应时间分解成RPC/Cache/DB的开销,同时它并不会对服务器造成太多额外的负担。我们也可以自己编写这类的Profiler,需要做的就是那一些特定的I/O函数进行monkey-
patch,将原先的函数替换成带有计时器的函数。比如,我们想对所有的requests.get函数计时,但又不能更改requests模块的代码,我们可以这样做

如果你想对requests模块下所有的公有API计时,我们可以写一个patch_module辅助函数

那要是我们想对所有redis的访问计时呢?这时我们需要对redis.StrictRedis这个类下的所有方法进行monkey-
patch,我们可以写一个patch_class辅助函数

在Github上,我们给出了一个完整的自定义Profiler的例子,它可以patch一个模块或是一个类,对不同的方法归类,profiling结束时打印出各个方法的时间,以及各个类别的总耗时。同时这个Profiler也是线程安全的。由于篇幅有限,这里只给出使用这个Profiler的例子,实现部分请查阅源代码

其执行结果如下

小结

性能调试是一个很大的题目,这里介绍的只是非常初级的知识。在最后一小节给出的例子也是希望大家不要局限于现有的工具,而是能根据自己的需求,打造最合适的工具。欢迎大家交流讨论!



阅读原文:http://mp.weixin.qq.com/s?__biz=MzI2MDQ5MjExOA==&mid=2247483724&idx=1&sn=b4fdf827d826dd6f53bfd7c6f7283aa1&chksm=ea699f75dd1e1663316c7138021c7d03b777aa118ef19d3b1a7d9a6d244ab17a2705e32af745#rd
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 212,657评论 6 492
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 90,662评论 3 385
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 158,143评论 0 348
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 56,732评论 1 284
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 65,837评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,036评论 1 291
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,126评论 3 410
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,868评论 0 268
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,315评论 1 303
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,641评论 2 327
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,773评论 1 341
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,470评论 4 333
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,126评论 3 317
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,859评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,095评论 1 267
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 46,584评论 2 362
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 43,676评论 2 351

推荐阅读更多精彩内容