如何逐行分析Python代码?

179 投票
5 回答
130423 浏览
提问于 2025-04-16 05:26

我一直在用cProfile来分析我的代码,效果很好。我还使用gprof2dot.py来可视化结果,这样看起来更清晰一些。

不过,cProfile(还有我见过的大部分Python性能分析工具)似乎只是在函数调用的层面上进行分析。这就导致了一个问题:当某些函数从不同地方被调用时,我不知道是第一个调用还是第二个调用占用了大部分时间。尤其是当这个函数被调用的层级有六层,且从七个其他地方调用时,这个问题就更严重了。

我该如何进行逐行分析呢?

我不想看到这样的结果:

function #12, total time: 2.0s

我希望能看到这样的结果:

function #12 (called from somefile.py:102) 0.5s
function #12 (called from main.py:12) 1.5s

cProfile确实显示了总时间中有多少“转移”到父函数,但当你有很多层和相互连接的调用时,这种联系又会消失。

理想情况下,我希望有一个图形界面,可以解析这些数据,然后显示我的源文件,并给每一行代码一个总时间。像这样:

main.py:

a = 1 # 0.0s
result = func(a) # 0.4s
c = 1000 # 0.0s
result = func(c) # 5.0s

这样我就可以点击第二个“func(c)”的调用,看看在这个调用中占用了多少时间,而不是和“func(a)”的调用混在一起。这样说清楚了吗?

5 个回答

21

为了更好地补充 @Joe Kington 的 上面提到的回答

对于 Python 3.x,可以使用 line_profiler


安装:

pip install line_profiler

使用方法:

假设你有一个程序 main.py,里面有两个函数 fun_a()fun_b(),你想要测量它们的运行时间;你需要在函数定义之前加上装饰器 @profile。比如:

@profile
def fun_a():
    #do something

@profile
def fun_b():
    #do something more

if __name__ == '__main__':
    fun_a()
    fun_b()

可以通过执行以下命令来分析程序:

$ kernprof -l -v main.py

你可以使用 $ kernprof -h 来获取参数信息

Usage: kernprof [-s setupfile] [-o output_file_path] scriptfile [arg] ...

Options:
  --version             show program's version number and exit
  -h, --help            show this help message and exit
  -l, --line-by-line    Use the line-by-line profiler from the line_profiler
                        module instead of Profile. Implies --builtin.
  -b, --builtin         Put 'profile' in the builtins. Use 'profile.enable()'
                        and 'profile.disable()' in your code to turn it on and
                        off, or '@profile' to decorate a single function, or
                        'with profile:' to profile a single section of code.
  -o OUTFILE, --outfile=OUTFILE
                        Save stats to <outfile>
  -s SETUP, --setup=SETUP
                        Code to execute before the code to profile
  -v, --view            View the results of the profile in addition to saving
                        it.

结果会在控制台上显示为:

Total time: 17.6699 s
File: main.py
Function: fun_a at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    5                                           @profile
    6                                           def fun_a():
...


补充:可以使用 TAMPPA 包来解析分析器的结果。通过它,我们可以得到逐行的可视化图表,如下所示:

plot
71

你还可以使用 pprofile(pypi)。如果你想要分析整个程序的执行过程,这个工具不需要你修改源代码。

你还可以用两种方式分析一个大程序中的某一部分:

  • 在代码中的特定位置开启分析,比如:

    import pprofile
    profiler = pprofile.Profile()
    with profiler:
        some_code
    # Process profile content: generate a cachegrind file and send it to user.
    
    # You can also write the result to the console:
    profiler.print_stats()
    
    # Or to a file:
    profiler.dump_stats("/tmp/profiler_stats.txt")
    
  • 通过调用栈异步开启分析(这需要在你考虑的应用中有办法触发这段代码,比如信号处理器或者可用的工作线程),使用统计分析的方法:

    import pprofile
    profiler = pprofile.StatisticalProfile()
    statistical_profiler_thread = pprofile.StatisticalThread(
        profiler=profiler,
    )
    with statistical_profiler_thread:
        sleep(n)
    # Likewise, process profile content
    

代码注释的输出格式和行分析器很相似:

$ 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

需要注意的是,由于 pprofile 不依赖于代码修改,它可以分析顶层模块的语句,这样就能分析程序启动的时间(比如导入模块、初始化全局变量等需要多长时间)。

它还可以生成 cachegrind 格式的输出,这样你就可以使用 kcachegrind 来轻松浏览大量的结果。

声明:我是 pprofile 的作者。

157

我觉得这就是Robert Kern的line_profiler的目的所在。从这个链接可以看到:

File: pystone.py
Function: Proc2 at line 149
Total time: 0.606656 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   149                                           @profile
   150                                           def Proc2(IntParIO):
   151     50000        82003      1.6     13.5      IntLoc = IntParIO + 10
   152     50000        63162      1.3     10.4      while 1:
   153     50000        69065      1.4     11.4          if Char1Glob == 'A':
   154     50000        66354      1.3     10.9              IntLoc = IntLoc - 1
   155     50000        67263      1.3     11.1              IntParIO = IntLoc - IntGlob
   156     50000        65494      1.3     10.8              EnumLoc = Ident1
   157     50000        68001      1.4     11.2          if EnumLoc == Ident1:
   158     50000        63739      1.3     10.5              break
   159     50000        61575      1.2     10.1      return IntParIO

撰写回答