跳转到主要内容

行粒度、线程感知的确定性和统计纯Python分析器

项目描述

行粒度、线程感知的确定性和统计纯Python分析器

受到Robert Kern的line_profiler的启发。

使用方法

作为命令

$ pprofile some_python_executable arg1 ...

一旦 some_python_executable 返回,就会打印出涉及执行的所有文件的带注释的代码。

作为命令,忽略默认 sys.path(即,Python模块本身),以缩短输出

$ pprofile --exclude-syspath some_python_executable arg1 ...

执行模块,如python -m。在此模式下,不推荐使用–exclude-syspath,因为它可能会隐藏您想要分析的内容。此外,显式地以结束pprofile参数将防止意外夺取命令的参数

$ pprofile -m some_python_module -- arg1 ...

作为模块

import pprofile

def someHotSpotCallable():
    # Deterministic profiler
    prof = pprofile.Profile()
    with prof():
        # Code to profile
    prof.print_stats()

def someOtherHotSpotCallable():
    # Statistic profiler
    prof = pprofile.StatisticalProfile()
    with prof(
        period=0.001, # Sample every 1ms
        single=True, # Only sample current thread
    ):
        # Code to profile
    prof.print_stats()

对于高级用法,请参阅pprofile --helppydoc pprofile

分析开销

pprofile默认模式(确定性分析)有较大的开销。部分原因是它被编写为尽可能通用(因此没有C扩展)。这种大的开销可能是一个问题,可以通过使用统计分析来避免,但这会以结果可读性降低为代价。

经验法则

要分析的代码运行时间为…

确定性分析

统计分析

几秒钟

[1]

几分钟

可能

更多(例如,守护进程)

[2]

一旦您确定了热点区域,并决定您需要更细粒度的分析来了解哪些需要修复,您应该尝试让-to-profile代码运行更短的时间,以便您可以合理地使用确定性分析:使用更小的数据集来触发相同的代码路径,修改代码以只在小块代码上启用分析…

输出

支持的输出格式。

Callgrind

pprofile最有用的输出模式是Callgrind分析格式,允许使用kcachegrind(或Windows上的qcachegrind)浏览分析结果。

$ pprofile --format callgrind --out cachegrind.out.threads demo/threads.py

如果--out basename以cachegrind.out.开头,Callgrind格式将自动启用,因此上述命令可以简化为

$ pprofile --out cachegrind.out.threads demo/threads.py

如果您在不同的机器上分析callgrind跟踪,您可能希望使用--zipfile选项生成包含所有文件的zip文件

$ pprofile --out cachegrind.out.threads --zipfile threads_source.zip demo/threads.py

生成的文件将使用相对路径,因此您可以在与分析结果相同的路径中提取生成的存档,kcachegrind将加载它们 - 而不是系统范围内的文件,这些文件可能不同。

带注释的代码

是可读的输出,但可能难以用于大型程序。

$ pprofile demo/threads.py

分析模式

确定性分析

在确定性分析模式下,pprofile会通知每次执行到的每一行。这种模式生成非常详细的报告,但代价是开销很大。此外,分析钩子是按线程进行的,因此必须在使用线程之前启用分析(如果您想分析除了当前线程之外的内容),或者被分析的应用程序必须提供在之后启用分析的方法 - 这并不太方便。

$ pprofile --threads 0 demo/threads.py
Command line: ['demo/threads.py']
Total duration: 1.00573s
File: demo/threads.py
File duration: 1.00168s (99.60%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         2|  3.21865e-05|  1.60933e-05|  0.00%|import threading
     2|         1|  5.96046e-06|  5.96046e-06|  0.00%|import time
     3|         0|            0|            0|  0.00%|
     4|         2|   1.5974e-05|  7.98702e-06|  0.00%|def func():
     5|         1|      1.00111|      1.00111| 99.54%|  time.sleep(1)
     6|         0|            0|            0|  0.00%|
     7|         2|  2.00272e-05|  1.00136e-05|  0.00%|def func2():
     8|         1|  1.69277e-05|  1.69277e-05|  0.00%|  pass
     9|         0|            0|            0|  0.00%|
    10|         1|  1.81198e-05|  1.81198e-05|  0.00%|t1 = threading.Thread(target=func)
(call)|         1|  0.000610828|  0.000610828|  0.06%|# /usr/lib/python2.7/threading.py:436 __init__
    11|         1|  1.52588e-05|  1.52588e-05|  0.00%|t2 = threading.Thread(target=func)
(call)|         1|  0.000438929|  0.000438929|  0.04%|# /usr/lib/python2.7/threading.py:436 __init__
    12|         1|  4.79221e-05|  4.79221e-05|  0.00%|t1.start()
(call)|         1|  0.000843048|  0.000843048|  0.08%|# /usr/lib/python2.7/threading.py:485 start
    13|         1|  6.48499e-05|  6.48499e-05|  0.01%|t2.start()
(call)|         1|   0.00115609|   0.00115609|  0.11%|# /usr/lib/python2.7/threading.py:485 start
    14|         1|  0.000205994|  0.000205994|  0.02%|(func(), func2())
(call)|         1|      1.00112|      1.00112| 99.54%|# demo/threads.py:4 func
(call)|         1|  3.09944e-05|  3.09944e-05|  0.00%|# demo/threads.py:7 func2
    15|         1|  7.62939e-05|  7.62939e-05|  0.01%|t1.join()
(call)|         1|  0.000423908|  0.000423908|  0.04%|# /usr/lib/python2.7/threading.py:653 join
    16|         1|  5.26905e-05|  5.26905e-05|  0.01%|t2.join()
(call)|         1|  0.000320196|  0.000320196|  0.03%|# /usr/lib/python2.7/threading.py:653 join

请注意,time.sleep调用不会被计算。由于某种原因,python没有生成c_call/c_return/c_exception事件(这些事件被当前代码忽略,因此结果如此)。

统计分析

在统计分析模式下,pprofile定期快照当前进程的当前调用栈以查看正在执行的内容。因此,分析开销可以大大减少,使得分析实际工作负载成为可能。此外,由于统计分析在整个进程级别上操作,它可以独立于被分析代码进行切换。

统计分析的一个缺点是输出缺乏时间信息,这使得理解更加困难。

$ pprofile --statistic .01 demo/threads.py
Command line: ['demo/threads.py']
Total duration: 1.0026s
File: demo/threads.py
File duration: 0s (0.00%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         0|            0|            0|  0.00%|import threading
     2|         0|            0|            0|  0.00%|import time
     3|         0|            0|            0|  0.00%|
     4|         0|            0|            0|  0.00%|def func():
     5|       288|            0|            0|  0.00%|  time.sleep(1)
     6|         0|            0|            0|  0.00%|
     7|         0|            0|            0|  0.00%|def func2():
     8|         0|            0|            0|  0.00%|  pass
     9|         0|            0|            0|  0.00%|
    10|         0|            0|            0|  0.00%|t1 = threading.Thread(target=func)
    11|         0|            0|            0|  0.00%|t2 = threading.Thread(target=func)
    12|         0|            0|            0|  0.00%|t1.start()
    13|         0|            0|            0|  0.00%|t2.start()
    14|         0|            0|            0|  0.00%|(func(), func2())
(call)|        96|            0|            0|  0.00%|# demo/threads.py:4 func
    15|         0|            0|            0|  0.00%|t1.join()
    16|         0|            0|            0|  0.00%|t2.join()
File: /usr/lib/python2.7/threading.py
File duration: 0s (0.00%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
[...]
   308|         0|            0|            0|  0.00%|    def wait(self, timeout=None):
[...]
   338|         0|            0|            0|  0.00%|            if timeout is None:
   339|         1|            0|            0|  0.00%|                waiter.acquire()
   340|         0|            0|            0|  0.00%|                if __debug__:
[...]
   600|         0|            0|            0|  0.00%|    def wait(self, timeout=None):
[...]
   617|         0|            0|            0|  0.00%|            if not self.__flag:
   618|         0|            0|            0|  0.00%|                self.__cond.wait(timeout)
(call)|         1|            0|            0|  0.00%|# /usr/lib/python2.7/threading.py:308 wait
[...]
   724|         0|            0|            0|  0.00%|    def start(self):
[...]
   748|         0|            0|            0|  0.00%|        self.__started.wait()
(call)|         1|            0|            0|  0.00%|# /usr/lib/python2.7/threading.py:600 wait
   749|         0|            0|            0|  0.00%|
   750|         0|            0|            0|  0.00%|    def run(self):
[...]
   760|         0|            0|            0|  0.00%|            if self.__target:
   761|         0|            0|            0|  0.00%|                self.__target(*self.__args, **self.__kwargs)
(call)|       192|            0|            0|  0.00%|# demo/threads.py:4 func
   762|         0|            0|            0|  0.00%|        finally:
[...]
   767|         0|            0|            0|  0.00%|    def __bootstrap(self):
[...]
   780|         0|            0|            0|  0.00%|        try:
   781|         0|            0|            0|  0.00%|            self.__bootstrap_inner()
(call)|       192|            0|            0|  0.00%|# /usr/lib/python2.7/threading.py:790 __bootstrap_inner
[...]
   790|         0|            0|            0|  0.00%|    def __bootstrap_inner(self):
[...]
   807|         0|            0|            0|  0.00%|            try:
   808|         0|            0|            0|  0.00%|                self.run()
(call)|       192|            0|            0|  0.00%|# /usr/lib/python2.7/threading.py:750 run

一些细节丢失(并非所有执行的行都有非空的命中数),但在这个简单的例子中,热点仍然容易识别,其调用栈仍然可见。

线程感知分析

ThreadProfile类提供了与Profile相同的特性,但使用threading.settrace将跟踪传播到分析启用后启动的threading.Thread线程。

局限性

在另一个线程中花费的时间不会从中断的行中扣除。从长远来看,如果切换在行之间均匀分布,则不应成为问题,但执行较少行的线程将显示比实际更多的CPU时间。

这不仅仅适用于同时多线程分析:分析多线程应用程序的单个线程也将受到其他线程花费的时间的干扰。

示例(当与另一个线程一起分析时,行报告为执行时间更长 - 尽管另一个线程没有被分析)

$ demo/embedded.py
Total duration: 1.00013s
File: demo/embedded.py
File duration: 1.00003s (99.99%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         0|            0|            0|  0.00%|#!/usr/bin/env python
     2|         0|            0|            0|  0.00%|import threading
     3|         0|            0|            0|  0.00%|import pprofile
     4|         0|            0|            0|  0.00%|import time
     5|         0|            0|            0|  0.00%|import sys
     6|         0|            0|            0|  0.00%|
     7|         1|   1.5974e-05|   1.5974e-05|  0.00%|def func():
     8|         0|            0|            0|  0.00%|  # Busy loop, so context switches happen
     9|         1|  1.40667e-05|  1.40667e-05|  0.00%|  end = time.time() + 1
    10|    146604|     0.511392|  3.48826e-06| 51.13%|  while time.time() < end:
    11|    146603|      0.48861|  3.33288e-06| 48.85%|    pass
    12|         0|            0|            0|  0.00%|
    13|         0|            0|            0|  0.00%|# Single-treaded run
    14|         0|            0|            0|  0.00%|prof = pprofile.Profile()
    15|         0|            0|            0|  0.00%|with prof:
    16|         0|            0|            0|  0.00%|  func()
(call)|         1|      1.00003|      1.00003| 99.99%|# ./demo/embedded.py:7 func
    17|         0|            0|            0|  0.00%|prof.annotate(sys.stdout, __file__)
    18|         0|            0|            0|  0.00%|
    19|         0|            0|            0|  0.00%|# Dual-threaded run
    20|         0|            0|            0|  0.00%|t1 = threading.Thread(target=func)
    21|         0|            0|            0|  0.00%|prof = pprofile.Profile()
    22|         0|            0|            0|  0.00%|with prof:
    23|         0|            0|            0|  0.00%|  t1.start()
    24|         0|            0|            0|  0.00%|  func()
    25|         0|            0|            0|  0.00%|  t1.join()
    26|         0|            0|            0|  0.00%|prof.annotate(sys.stdout, __file__)
Total duration: 1.00129s
File: demo/embedded.py
File duration: 1.00004s (99.88%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
[...]
     7|         1|  1.50204e-05|  1.50204e-05|  0.00%|def func():
     8|         0|            0|            0|  0.00%|  # Busy loop, so context switches happen
     9|         1|  2.38419e-05|  2.38419e-05|  0.00%|  end = time.time() + 1
    10|     64598|     0.538571|  8.33728e-06| 53.79%|  while time.time() < end:
    11|     64597|     0.461432|  7.14324e-06| 46.08%|    pass
[...]

这也意味着所有行的百分比总和可能超过100%。它可以达到并发线程的数量(如果有两个线程在整个分析执行时间都很忙,则为200%等)。

3个线程的示例

$ pprofile demo/threads.py
Command line: ['demo/threads.py']
Total duration: 1.00798s
File: demo/threads.py
File duration: 3.00604s (298.22%)
Line #|      Hits|         Time| Time per hit|      %|Source code
------+----------+-------------+-------------+-------+-----------
     1|         2|  3.21865e-05|  1.60933e-05|  0.00%|import threading
     2|         1|  6.91414e-06|  6.91414e-06|  0.00%|import time
     3|         0|            0|            0|  0.00%|
     4|         4|  3.91006e-05|  9.77516e-06|  0.00%|def func():
     5|         3|      3.00539|       1.0018|298.16%|  time.sleep(1)
     6|         0|            0|            0|  0.00%|
     7|         2|  2.31266e-05|  1.15633e-05|  0.00%|def func2():
     8|         1|  2.38419e-05|  2.38419e-05|  0.00%|  pass
     9|         0|            0|            0|  0.00%|
    10|         1|  1.81198e-05|  1.81198e-05|  0.00%|t1 = threading.Thread(target=func)
(call)|         1|  0.000612974|  0.000612974|  0.06%|# /usr/lib/python2.7/threading.py:436 __init__
    11|         1|  1.57356e-05|  1.57356e-05|  0.00%|t2 = threading.Thread(target=func)
(call)|         1|  0.000438213|  0.000438213|  0.04%|# /usr/lib/python2.7/threading.py:436 __init__
    12|         1|  6.60419e-05|  6.60419e-05|  0.01%|t1.start()
(call)|         1|  0.000913858|  0.000913858|  0.09%|# /usr/lib/python2.7/threading.py:485 start
    13|         1|   6.8903e-05|   6.8903e-05|  0.01%|t2.start()
(call)|         1|   0.00167513|   0.00167513|  0.17%|# /usr/lib/python2.7/threading.py:485 start
    14|         1|  0.000200272|  0.000200272|  0.02%|(func(), func2())
(call)|         1|      1.00274|      1.00274| 99.48%|# demo/threads.py:4 func
(call)|         1|  4.19617e-05|  4.19617e-05|  0.00%|# demo/threads.py:7 func2
    15|         1|  9.58443e-05|  9.58443e-05|  0.01%|t1.join()
(call)|         1|  0.000411987|  0.000411987|  0.04%|# /usr/lib/python2.7/threading.py:653 join
    16|         1|  5.29289e-05|  5.29289e-05|  0.01%|t2.join()
(call)|         1|  0.000316143|  0.000316143|  0.03%|# /usr/lib/python2.7/threading.py:653 join

请注意,调用时间不会添加到文件总时间:它已经在“func”内部计算过了。

为什么还需要另一个分析器?

Python的标准分析工具具有可调用级别的粒度,这意味着只能知道哪个函数是热点,但不能知道该函数中的哪一行。

Robert Kern的line_profiler是一个非常好的替代方案,它提供了行级别的分析粒度,但在我看来,它有几个缺点(除了吸引人的技术挑战之外),这促使我开始编写pprofile

  • 它不是纯Python。这个选择对于性能是有意义的,但使得与pypy的使用变得困难,并且需要安装(我重视直接从检查点执行)。

  • 它需要修改源代码来选择要分析的内容。我更喜欢有一个深入、非侵入式的分析选项。

  • 由于前一个原因,它没有对单个可调用对象之上的概念,只注释函数而不注释整个文件 - 阻止了模块导入分析。

  • 对递归代码的分析提供了意外的结果(递归成本累积在可调用对象的第一行),因为它没有跟踪调用栈。这可能是不预期的,并且可能在line_profiler的某个版本中得到修复。

项目详情


下载文件

下载您平台上的文件。如果您不确定要选择哪个,请了解更多关于安装软件包的信息。

源分发

pprofile-2.2.0.tar.gz (56.0 kB 查看哈希)

上传时间

支持者

AWS AWS 云计算和安全赞助商 Datadog Datadog 监控 Fastly Fastly CDN Google Google 下载分析 Microsoft Microsoft PSF 赞助商 Pingdom Pingdom 监控 Sentry Sentry 错误记录 StatusPage StatusPage 状态页面