使用方法

作为命令：

$ pprofile some_python_executable arg1 ...

当some_python_executable返回时，打印执行过程中涉及的每个文件的带注释代码。

作为命令，忽略默认sys.path中的任何文件（即Python模块本身），以获得更简短的输出：

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

执行模块，类似于:code:python -m。在此模式下不建议使用--exclude-syspath，因为它可能会隐藏您打算分析的内容。此外，明确以--结束pprofile参数将防止意外窃取命令的参数：

$ pprofile -m some_python_module -- arg1 ...

作为模块：

.. code:: python

import pprofile

def someHotSpotCallable(): # 确定性分析器 prof = pprofile.Profile() with prof(): # 要分析的代码 prof.print_stats()

def someOtherHotSpotCallable(): # 统计分析器 prof = pprofile.StatisticalProfile() with prof( period=0.001, # 每1ms采样一次 single=True, # 仅采样当前线程 ): # 要分析的代码 prof.print_stats()

高级用法请参见:code:pprofile --help和:code:pydoc pprofile。

分析开销

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

经验法则：

+-----------------------------+----------------------------+------------------------+ | 要分析的代码运行时间... | 确定性分析_ | 统计分析_ | +=============================+============================+========================+ | 几秒钟 | 是 | 否 [#]_ | +-----------------------------+----------------------------+------------------------+ | 几分钟 | 可能 | 是 | +-----------------------------+----------------------------+------------------------+ | 更长（例如：守护进程） | 否 | 是 [#]_ | +-----------------------------+----------------------------+------------------------+

一旦您确定了热点并决定需要更细粒度的分析来理解需要修复的内容，您应该尝试缩短要分析的代码运行时间，以便可以合理地使用确定性分析：使用触发相同代码路径的较小数据集，修改代码仅在小段代码上启用分析...

.. [#] 统计分析将没有足够的时间收集足够的样本来产生可用的输出。

.. [#] 您可能需要考虑从信号处理程序或其他IPC机制触发pprofile，以分析较短的子集。参见zpprofile.py 了解如何在运行中的（zope）服务内使用它（在这种情况下，IPC机制只是Zope正常的URL处理）。

输出

支持的输出格式。

Callgrind

pprofile最有用的输出模式是Callgrind Profile Format，允许使用kcachegrind（或Windows上的qcachegrind_）浏览分析结果。

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

如果--out的基本名称以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 命令行: ['demo/threads.py'] 总持续时间: 1.0026秒文件: demo/threads.py 文件持续时间: 0秒 (0.00%) 行号| 命中| 时间| 每次命中时间| %|源代码 ------+----------+-------------+-------------+-------+----------- 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()) (调用)| 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() 文件: /usr/lib/python2.7/threading.py 文件持续时间: 0秒 (0.00%) 行号| 命中| 时间| 每次命中时间| %|源代码 ------+----------+-------------+-------------+-------+----------- [...] 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) (调用)| 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() (调用)| 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) (调用)| 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() (调用)| 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() (调用)| 192| 0| 0| 0.00%|# /usr/lib/python2.7/threading.py:750 run

一些细节丢失了（并非所有执行的行都有非零的命中计数），但在这个简单的例子中，热点仍然很容易识别，并且其调用栈仍然可见。

线程感知分析

ThreadProfile类提供与Profile相同的功能，但使用threading.settrace将跟踪传播到在启用分析后启动的threading.Thread线程。

限制

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

这不仅限于同时多线程分析：对多线程应用程序的单个线程进行分析也会受到其他线程所花费时间的污染。

示例（当与另一个线程一起分析时，报告的行执行时间更长 - 尽管另一个线程未被分析）:: $ demo/embedded.py 总持续时间：1.00013秒文件：demo/embedded.py 文件持续时间：1.00003秒（99.99%）行号| 命中| 时间| 每次命中时间| %|源代码 ------+----------+-------------+-------------+-------+----------- 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%| # 忙循环，使上下文切换发生 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%|# 单线程运行 14| 0| 0| 0| 0.00%|prof = pprofile.Profile() 15| 0| 0| 0| 0.00%|with prof: 16| 0| 0| 0| 0.00%| func() (调用)| 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%|# 双线程运行 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) 总持续时间：1.00129秒文件：demo/embedded.py 文件持续时间：1.00004秒（99.88%）行号| 命中| 时间| 每次命中时间| %|源代码 ------+----------+-------------+-------------+-------+----------- [...] 7| 1| 1.50204e-05| 1.50204e-05| 0.00%|def func(): 8| 0| 0| 0| 0.00%| # 忙循环，使上下文切换发生 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%。它可以达到并发线程数（2个线程在整个分析执行时间内都忙碌时为200%，以此类推）。

3个线程的示例：

$ pprofile demo/threads.py 命令行：['demo/threads.py'] 总持续时间：1.00798秒文件：demo/threads.py 文件持续时间：3.00604秒（298.22%）行号| 命中| 时间| 每次命中时间| %|源代码 ------+----------+-------------+-------------+-------+----------- 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) (调用)| 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) (调用)| 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() (调用)| 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() (调用)| 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()) (调用)| 1| 1.00274| 1.00274| 99.48%|# demo/threads.py:4 func (调用)| 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() (调用)| 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() (调用)| 1| 0.000316143| 0.000316143| 0.03%|# /usr/lib/python2.7/threading.py:653 join 请注意，调用时间并未添加到文件总计中:它已经在"func"内部计算过了。