pprofile, 行粒度线程感知确定性和统计纯 python 分析器

分享于 

17分钟阅读

GitHub

  繁體 雙語
Line-granularity, thread-aware deterministic and statistic pure-python profiler
  • 源代码名称:pprofile
  • 源代码网址:http://www.github.com/vpelletier/pprofile
  • pprofile源代码文档
  • pprofile源代码下载
  • Git URL:
    git://www.github.com/vpelletier/pprofile.git
    Git Clone代码到本地:
    git clone http://www.github.com/vpelletier/pprofile
    Subversion代码到本地:
    $ svn co --depth empty http://www.github.com/vpelletier/pprofile
    Checked out revision 1.
    $ cd repo
    $ svn up trunk
    

    线条粒度。线程感知确定性和统计纯python分析器

    来自kern的罗伯特。com。

    用法

    作为命令:

    $ pprofile some_python_executable arg1.. .

    一旦some_python_executable返回,打印执行中涉及的每个文件的注释代码。

    作为命令,忽略默认 sys.path (。IE,python 模块自身) 中的任何文件,以便缩短输出:

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

    执行 MODULE,如 python -m。 在这种模式下不推荐 --exclude-syspath,因为它可能会隐藏你想要配置的内容。 另外,使用--显式结束pprofile参数将防止意外窃取命令的参数:

    $ pprofile -m some_python_module -- arg1.. .

    作为模块:

    import pprofiledefsomeHotSpotCallable():
     # Deterministic profiler prof = pprofile.Profile()
     with prof():
     # Code to profile prof.print_stats()defsomeOtherHotSpotCallable():
     # Statistic profiler prof = pprofile.StatisticalProfile()
     with prof(
     period=0.001, # Sample every 1mssingle=True, # Only sample current thread ):
     # Code to profile prof.print_stats()

    有关高级用法,请参见 pprofile --helppydoc pprofile

    分析开销

    pprofile默认模式(。确定性配置文件 )的开销很大。 原因是它被写得尽可能的便携。 这种大开销可能是一个问题,可以通过使用统计分析( ) 来避免,代价是降低了某些结果的可读性。

    经验法则:

    要运行的配置文件的代码。 确定性概要文件统计概要文件
    几秒钟是的没有 [1]
    几分钟也许是的
    更多( 例如:守护进程)不是[2]

    确定了热点并确定需要修复的细粒度分析后,应该尝试使配置文件代码更短时间运行。 使用一个较小的数据集触发相同的代码路径,修改代码以只对小段代码启用分析。

    [1]统计分析将没有时间收集足够的样本来产生有用的输出。
    [2]你可能需要考虑从信号处理程序或者其他IPC机制触发pprofile来配置较短的子集。 有关如何使用 zpprofile.py 在运行的( Zope ) 服务( 在这种情况下,IPC机制只是普通的URL处理) 中配置代码的信息,请参阅。

    输出

    支持的输出格式。

    Callgrind

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

    $ 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 % 使用 2线程,整个配置文件的执行时间等)。

    具有 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"里面了。

    另一个分析器?

    标准分析工具具有可以调用级别粒度,这意味着只能指出哪个函数是热点,而不是该函数中哪个行。

    kern Robert是提供行级别分析粒度的不错的替代方案,但在我看来,它有几个缺点,( 除了有吸引力的技术挑战) 使我开始了 pprofile:

    • 这不是纯 python,这种选择对性能很有意义,但是使用rtc很困难并需要安装( 我从结帐中直接执行)。
    • 需要修改源代码以选择应该进行分析的内容。 我更喜欢做一个深入的选择,非入侵性分析。
    • 它的作用是在前面的点上没有单独的可以调用的注释函数,但不是整个文件的概念- 阻止 MODULE 导入概要。
    • 分析递归代码提供意外结果( 递归成本在可以赎回行上累积),因为它不跟踪调用堆栈。 这可能是意外的,并且可能在line_profiler的某一点上固定。

    相关文章