将 cProfile 与 asyncio 代码一起使用的正确方法是啥？

Posted 2023-03-30

【中文标题】将 cProfile 与 asyncio 代码一起使用的正确方法是啥？

【英文标题】：What is correct way to use cProfile with asyncio code?将 cProfile 与 asyncio 代码一起使用的正确方法是什么？

【发布时间】：2019-02-15 23:15:56

【问题描述】：

我正在尝试确定如何通过 asyncio 代码正确使用 cProfile 和 pstats。我正在通过运行cProfile.run('loop.run_until_complete(main())', 'profile.stats') 来分析我的脚本。

使用pstats按SortKeys.TIME排序后，我得到以下输出：

In [9]: sorted_stats.print_stats()
Fri Feb 15 14:40:18 2019    profile.txt

         67411199 function calls (67230882 primitive calls) in 305.899 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     3617  273.162    0.076  273.162    0.076 method 'poll' of 'select.epoll' objects
14094092/14093931    1.527    0.000    1.904    0.000 built-in method builtins.isinstance
    44901    1.166    0.000    1.166    0.000 built-in method posix.stat
   784052    1.028    0.000    1.479    0.000 /usr/lib/python3/dist-packages/soupsieve/util.py:41(lower)
    32070    0.887    0.000    1.565    0.000 /usr/lib/python3/dist-packages/bs4/element.py:620(<genexpr>)
  4554545    0.729    0.000    0.756    0.000 /usr/lib/python3/dist-packages/bs4/element.py:1331(descendants)
  1026560    0.726    0.000    3.358    0.000 /usr/lib/python3/dist-packages/bs4/element.py:1502(search)
   448385    0.716    0.000    1.411    0.000 /usr/lib/python3/dist-packages/bs4/element.py:1528(_matches)
      104    0.689    0.007    4.771    0.046 /usr/lib/python3/dist-packages/bs4/builder/_lxml.py:283(feed)
   255143    0.655    0.000    1.575    0.000 /usr/lib/python3/dist-packages/bs4/__init__.py:391(endData)
   137377    0.520    0.000    3.692    0.000 /usr/lib/python3/dist-packages/html5lib/_tokenizer.py:49(__iter__)
     8574    0.510    0.000    2.392    0.000 /usr/lib/python3.7/traceback.py:318(extract)
   167700    0.494    0.000    1.061    0.000 /usr/lib/python3/dist-packages/bleach/html5lib_shim.py:199(charsUntil)
    53607    0.487    0.000    0.589    0.000 /usr/lib/python3/dist-packages/bs4/builder/__init__.py:158(_replace_cdata_list_attribute_values)
   299357    0.485    0.000    0.485    0.000 /usr/lib/python3/dist-packages/bs4/element.py:258(setup)
    22253    0.467    0.000    5.928    0.000 /usr/lib/python3/dist-packages/bs4/element.py:592(_find_all)
   448385    0.437    0.000    2.225    0.000 /usr/lib/python3/dist-packages/bs4/element.py:1461(search_tag)
    83147    0.424    0.000    2.365    0.000 /usr/lib/python3/dist-packages/bs4/builder/_lxml.py:176(start)
  1293015    0.418    0.000    0.556    0.000 /usr/lib/python3/dist-packages/soupsieve/css_match.py:94(is_tag)
  4824419    0.409    0.000    0.409    0.000 method 'append' of 'list' objects
    73068    0.404    0.000    0.634    0.000 /home/jess/.local/lib/python3.7/site-packages/rfc3986/normalizers.py:127(encode_component)
   868978    0.403    0.000    0.773    0.000 /usr/lib/python3/dist-packages/bleach/html5lib_shim.py:192(char)
   454702    0.385    0.000    0.385    0.000 method 'match' of 're.Pattern' objects
  2326981    0.374    0.000    0.415    0.000 built-in method builtins.hasattr
       52    0.334    0.006    5.732    0.110 /usr/lib/python3/dist-packages/html5lib/html5parser.py:196(mainLoop)


   ...       ...       ...      ...      ...          ... 

如您所见，几乎所有的执行时间都显示为method 'poll' of 'select.epoll' objects。

我对@9​​87654328@ 或asyncio 没有足够的经验，不知道如何解释这个结果。我不知道统计数据是否显示我的程序在poll() 中花费了大部分执行时间，因为（a）cProfile 不能很好地与asyncio 配合使用并且没有给出正确的统计数据，（b）这是正常行为, 我应该忽略第一行或 (c) 这表明我的程序中存在某种错误（由于我尚未确定的原因，现在确实非常慢）...

异步进程在poll() 中花费这么多执行时间是否正常？有没有更好的方法来分析异步代码，无论是使用 cProfile 还是其他东西，都会给我更准确的结果？或者这是否表明我的代码中可能存在某种错误导致这种情况？

---

注意：对于上下文，我分析的代码基本上是获取 50 页，处理 HTML，然后进行一些文本/语言处理。 fetch() 部分可以解释 poll() 的大部分时间。但这是在快速的互联网连接（> 5MB /秒）上，所以我认为它不应该花费那 % 的时间来获取几十个text/html 页面。似乎发生了其他事情，或者统计数据不正确......

【问题讨论】：

完全有可能代码大部分时间都在轮询——但如果没有看到实际代码就无法判断。在这种情况下，有一个名为line_profiler 的插件可能比cProfile 对您更有用（尽管我从未尝试将它与asyncio 一起使用）。

您是否尝试过在不使用asyncio 的情况下仅运行一个实例（例如，下载一个页面），看看效果如何？

@martineau 我遇到的问题是应用程序有几千行代码，我首先尝试使用分析器的原因是找出它慢的地方.但是因为分析器给了我上面的结果，我不能告诉 它在程序中轮询的位置，并且不觉得在这里共享整个应用程序的源是合适的。我要问的是如何使用分析器来找出我自己的代码的哪一部分正在轮询，而不是模糊的“它在 poll() 某处”结果不能帮助我过去“它可能是一个执行 IO 的函数"

J. Taylor：使用链接的 line-profiler 可以让您找出它在代码行级别的缓慢之处，这就是我提到它的原因。您可以有选择地应用分析 - 即仅应用于您感兴趣的代码部分。

我发现此链接在尝试分析我自己的asyncio 代码时很有用：roguelynn.com/words/asyncio-profiling

【参考方案1】：

TL；DR 使用更好的工具

我发现在可重现的情况下对其进行分析更实用，因为这样就可以验证任何代码更改（无论是否提高了性能）。

如果您可以使用pytest 将您的代码转换为测试用例，那么请考虑使用https://pypi.org/project/pytest-profiling/，它易于设置，并且视觉输出[相对] 易于理解。

另一种选择是使用统计分析器，例如https://pypi.org/project/pprofile/

如果您喜欢在生产环境中进行分析，那么另一个方法是使用服务，例如 https://docs.datadoghq.com/tracing/profiler/

最后，要清楚你衡量什么。

大多数/许多分析器允许同时收集挂钟时间和 CPU 使用时间。

一个幼稚的asyncio 程序是单线程的，如果有足够的 CPU 份额，在任何给定时间都处于以下两种状态之一：正在运行，或等待 .如果您的“问题”过于复杂，那么 profiler 就是答案，而且 cpu 时间和 wall 时间通常大致相同。如果“问题”实际上是在等待，那么您可能想看看“谁在等待什么”。无耻的插件：使用我的https://pypi.org/project/awaitwhat/ for Python 3.7~3.9。