Python性能分析工具pyinstrument快速定位最慢的代码

时间:2022-02-28 06:10:57

Python性能分析工具pyinstrument快速定位最慢的代码

天下武功,唯快不破。

编程也不例外,你的代码跑的快,你能快速找出代码慢的原因,你的码功就高。

今天分享一个超级实用的 Python 性能分析工具 pyinstrument ,可以快速找到代码运行最慢的部分,帮助提高代码的性能。支持 Python 3.7+ 且能够分析异步代码,仅需一条命令即可显示具体代码的耗时。经常写 Python 的小伙伴一定要用一下。

安装

  1. pip install pyinstrument 

简单的使用

在程序的开始,启动 pyinstrument 的 Profiler,结束时关闭 Profiler 并打印分析结果如下:

  1. from pyinstrument import Profiler 
  2.  
  3. profiler = Profiler() 
  4. profiler.start() 
  5.  
  6. # 这里是你要分析的代码 
  7.  
  8. profiler.stop() 
  9.  
  10. profiler.print() 

比如这段代码 123.py,我们可以清楚的看到是列表推导式比较慢:

  1. from pyinstrument import Profiler 
  2.  
  3. profiler = Profiler() 
  4. profiler.start() 
  5.  
  6. # 这里是你要分析的代码 
  7. a = [i for i in range(100000)] 
  8. b = (i for i in range(100000)) 
  9.  
  10. profiler.stop() 
  11. profiler.print() 

Python性能分析工具pyinstrument快速定位最慢的代码

上述分析需要修改源代码,如果你使用命令行工具,就不需要修改源代码,只需要执行 pyinstrument xxxx.py 即可:

比如有这样一段排序的程序 c_sort.py:

  1. import sys 
  2. import time 
  3.  
  4. import numpy as np 
  5.  
  6. arr = np.random.randint(0, 10, 10) 
  7.  
  8. def slow_key(el): 
  9.     time.sleep(0.01) 
  10.     return el  
  11.  
  12. arr = list(arr) 
  13.  
  14. for i in range(10): 
  15.     arr.sort(key=slow_key) 
  16.  
  17. print(arr) 

这段代码里面故意放了一句 time.sleep(0.01) 来延迟性能,看看 pyinstrument 能否识别,命令行执行 pyinstrument c_sort.py:

Python性能分析工具pyinstrument快速定位最慢的代码

从结果来看,程序运行了 1.313 秒,而 sleep 就运行了 1.219 秒,很明显是瓶颈,现在我们把它删除,再看看结果:

Python性能分析工具pyinstrument快速定位最慢的代码

删除之后,性能最慢的就是 numpy 模块的初始化代码 __init__.py了,不过这些代码不是自己写的,而且并不是特别慢,就不需要去关心了。

分析 Flask 代码

Web 应用也可以使用这个来找出性能瓶颈,比如 flask,只需要在请求之前记录时间,在请求之后统计时间,只需要在 flask 的请求拦截器里面这样写:

  1. from flask import Flask, g, make_response, request 
  2. app = Flask(__name__) 
  3.  
  4. @app.before_request 
  5. def before_request(): 
  6.     if "profile" in request.args: 
  7.         g.profiler = Profiler() 
  8.         g.profiler.start() 
  9.  
  10.  
  11. @app.after_request 
  12. def after_request(response): 
  13.     if not hasattr(g, "profiler"): 
  14.         return response 
  15.     g.profiler.stop() 
  16.     output_html = g.profiler.output_html() 
  17.     return make_response(output_html) 

假如有这样一个 API:

  1. @app.route("/dosomething"
  2. def do_something(): 
  3.     import requests 
  4.     requests.get("http://google.com"
  5.     return "Google says hello!" 

为了测试这个 API 的瓶颈,我们可以在 url 上加一个参数 profile 就可以:http://127.0.0.1:5000/dosomething?profile,哪一行代码执行比较慢,结果清晰可见:

Python性能分析工具pyinstrument快速定位最慢的代码

分析 Django 代码

分析 Django 代码也非常简单,只需要在 Django 的配置文件的 MIDDLEWARE 中添加

  1. "pyinstrument.middleware.ProfilerMiddleware"

然后就可以在 url 上加一个参数 profile 就可以:

Python性能分析工具pyinstrument快速定位最慢的代码

如果你不希望所有人都能看到,只希望管理员可以看到,settings.py 可以添加这样的代码:

  1. def custom_show_pyinstrument(request): 
  2.     return request.user.is_superuser 
  3.  
  4. PYINSTRUMENT_SHOW_CALLBACK = "%s.custom_show_pyinstrument" % __name__ 

如果不想通过 url 后面加参数的方式查看性能分析,可以在 settings.py 文件中添加:

  1. PYINSTRUMENT_PROFILE_DIR = 'profiles' 

这样,每次访问一次 Django 接口,就会将分析结果以 html 文件形式保存在 项目目录下的 profiles 文件夹中。

分析异步代码

简单的异步代码分析:

  1. import asyncio 
  2.  
  3. from pyinstrument import Profiler 
  4.  
  5.  
  6. async def main(): 
  7.     p = Profiler() 
  8.     with p: 
  9.         print("Hello ..."
  10.         await asyncio.sleep(1) 
  11.         print("... World!"
  12.     p.print() 
  13.  
  14.  
  15. asyncio.run(main()) 

复杂一些的异步代码分析:

  1. import asyncio 
  2. import time 
  3.  
  4. import pyinstrument 
  5.  
  6.  
  7. def do_nothing(): 
  8.     pass 
  9.  
  10.  
  11. def busy_wait(duration): 
  12.     end_time = time.time() + duration 
  13.  
  14.     while time.time() < end_time: 
  15.         do_nothing() 
  16.  
  17.  
  18. async def say(what, when, profile=False): 
  19.     if profile: 
  20.         p = pyinstrument.Profiler() 
  21.         p.start() 
  22.  
  23.     busy_wait(0.1) 
  24.     sleep_start = time.time() 
  25.     await asyncio.sleep(when
  26.     print(f"slept for {time.time() - sleep_start:.3f} seconds"
  27.     busy_wait(0.1) 
  28.  
  29.     print(what) 
  30.     if profile: 
  31.         p.stop() 
  32.         p.print(show_all=True
  33.  
  34.  
  35. loop = asyncio.get_event_loop() 
  36.  
  37. loop.create_task(say("first hello", 2, profile=True)) 
  38. loop.create_task(say("second hello", 1, profile=True)) 
  39. loop.create_task(say("third hello", 3, profile=True)) 
  40.  
  41. loop.run_forever() 
  42. loop.close() 

工作原理

Pyinstrument 每 1ms 中断一次程序,并在该点记录整个堆栈。它使用 C 扩展名和 PyEval_SetProfile 来做到这一点,但只每 1 毫秒读取一次读数。你可能觉得报告的样本数量有点少,但别担心,它不会降低准确性。默认间隔 1ms 是记录堆栈帧的下限,但如果在单个函数调用中花费了很长时间,则会在该调用结束时进行记录。如此有效地将这些样本“打包”并在最后记录。

Pyinstrument 是一个统计分析器,并不跟踪,它不会跟踪您的程序进行的每个函数调用。相反,它每 1 毫秒记录一次调用堆栈。与其他分析器相比,统计分析器的开销比跟踪分析器低得多。

比如说,我想弄清楚为什么 Django 中的 Web 请求很慢。如果我使用 cProfile,我可能会得到这个:

  1. 151940 function calls (147672 primitive calls) in 1.696 seconds 
  2.  
  3.    Ordered by: cumulative time 
  4.  
  5.    ncalls  tottime  percall  cumtime  percall filename:lineno(function
  6.         1    0.000    0.000    1.696    1.696 profile:0(<code object <module> at 0x1053d6a30, file "./manage.py", line 2>) 
  7.         1    0.001    0.001    1.693    1.693 manage.py:2(<module>) 
  8.         1    0.000    0.000    1.586    1.586 __init__.py:394(execute_from_command_line) 
  9.         1    0.000    0.000    1.586    1.586 __init__.py:350(execute
  10.         1    0.000    0.000    1.142    1.142 __init__.py:254(fetch_command) 
  11.        43    0.013    0.000    1.124    0.026 __init__.py:1(<module>) 
  12.       388    0.008    0.000    1.062    0.003 re.py:226(_compile) 
  13.       158    0.005    0.000    1.048    0.007 sre_compile.py:496(compile) 
  14.         1    0.001    0.001    1.042    1.042 __init__.py:78(get_commands) 
  15.       153    0.001    0.000    1.036    0.007 re.py:188(compile) 
  16.   106/102    0.001    0.000    1.030    0.010 __init__.py:52(__getattr__) 
  17.         1    0.000    0.000    1.029    1.029 __init__.py:31(_setup) 
  18.         1    0.000    0.000    1.021    1.021 __init__.py:57(_configure_logging) 
  19.         2    0.002    0.001    1.011    0.505 log.py:1(<module>) 

看完是不是还是一脸懵逼,通常很难理解您自己的代码如何与这些跟踪相关联。Pyinstrument 记录整个堆栈,因此跟踪昂贵的调用要容易得多。它还默认隐藏库框架,让您专注于影响性能的应用程序/模块:

  1.   _     ._   __/__   _ _  _  _ _/_   Recorded: 14:53:35  Samples:  131 
  2.  /_//_/// /_\ / //_// / //_'/ //    Duration: 3.131     CPU time: 0.195 
  3. /   _/                    v3.0.0b3 
  4.  
  5. Program: examples/django_example/manage.py runserver --nothreading --noreload 
  6.  
  7. 3.131 <module>  manage.py:2 
  8. └─ 3.118 execute_from_command_line  django/core/management/__init__.py:378 
  9.       [473 frames hidden]  django, socketserver, selectors, wsgi... 
  10.          2.836 select  selectors.py:365 
  11.          0.126 _get_response  django/core/handlers/base.py:96 
  12.          └─ 0.126 hello_world  django_example/views.py:4 

最后的话

 

本文分享了 pyinstrument 的用法,有了这个性能分析神器,以后优化代码可以节省很多时间了,这样的效率神器很值得分享,毕竟人生苦短,能多点时间干点有意思的不香么?

原文链接:https://mp.weixin.qq.com/s/d_3PBrwk-s34W_RzVsJ21A