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

Question

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

使用pstatsto sort by 后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}.

我没有足够的经验cProfile或asyncio不知道如何解释这个结果。我无法判断统计数据是否显示我的程序花费了大部分执行时间，poll()因为 (a) cProfile 不能很好地工作并且asyncio没有提供正确的统计数据，(b) 这是正常行为，我应该忽略第一行或 (c) 这是我程序中某种错误的指标（由于我尚未确定的原因，现在确实非常慢）......

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

---

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

Answer 1

TL;DR 使用更好的工具

\n

我发现，当某些内容可重现时，对其进行分析更为实用，因为这样，任何代码更改都可以得到验证（如果它提高了性能或没有提高性能）。

\n

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

\n

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

\n

还有一个，如果您喜欢在生产中进行分析，可以使用服务，例如https://docs.datadoghq.com/tracing/profiler/

\n

最后，明确你衡量的是什么。

\n

大多数/许多探查器允许收集挂钟时间和 CPU 使用时间。

\n

na\xc3\xafveasyncio程序是单线程的，并且给予足够的 CPU 份额，在任何给定时间都处于两种状态之一：要么crunching，要么waiting。如果您的“问题”太多，那么分析器就是答案，并且通常情况下，cpu 时间和 wall time 大致相同。如果“问题”实际上是在等待，那么您可能想看看“谁在等待什么”。无耻插件：使用我的https://pypi.org/project/awaitwhat/ for Python 3.7~3.9。

\n