python - sort - How can you profile a script?




snakeviz (16)

Ever want to know what the hell that python script is doing? Enter the Inspect Shell. Inspect Shell lets you print/alter globals and run functions without interrupting the running script. Now with auto-complete and command history (only on linux).

Inspect Shell is not a pdb-style debugger.

https://github.com/amoffat/Inspect-Shell

You could use that (and your wristwatch).

Project Euler and other coding contests often have a maximum time to run or people boast of how fast their particular solution runs. With python, sometimes the approaches are somewhat kludgey - i.e., adding timing code to __main__.

What is a good way to profile how long a python program takes to run?


pprofile

line_profiler (already presented here) also inspired pprofile, which is described as:

Line-granularity, thread-aware deterministic and statistic pure-python profiler

It provides line-granularity as line_profiler, is pure Python, can be used as a standalone command or a module, and can even generate callgrind-format files that can be easily analyzed with [k|q]cachegrind.

vprof

There is also vprof, a Python package described as:

[...] providing rich and interactive visualizations for various Python program characteristics such as running time and memory usage.


@Maxy's comment on this answer helped me out enough that I think it deserves its own answer: I already had cProfile-generated .pstats files and I didn't want to re-run things with pycallgraph, so I used gprof2dot, and got pretty svgs:

$ sudo apt-get install graphviz
$ git clone https://github.com/jrfonseca/gprof2dot
$ ln -s "$PWD"/gprof2dot/gprof2dot.py ~/bin
$ cd $PROJECT_DIR
$ gprof2dot.py -f pstats profile.pstats | dot -Tsvg -o callgraph.svg

and BLAM!

It uses dot (the same thing that pycallgraph uses) so output looks similar. I get the impression that gprof2dot loses less information though:


A new tool to handle profiling in Python is PyVmMonitor: http://www.pyvmmonitor.com/

It has some unique features such as

  • Attach profiler to a running (CPython) program
  • On demand profiling with Yappi integration
  • Profile on a different machine
  • Multiple processes support (multiprocessing, django...)
  • Live sampling/CPU view (with time range selection)
  • Deterministic profiling through cProfile/profile integration
  • Analyze existing PStats results
  • Open DOT files
  • Programatic API access
  • Group samples by method or line
  • PyDev integration
  • PyCharm integration

Note: it's commercial, but free for open source.


A while ago I made pycallgraph which generates a visualisation from your Python code. Edit: I've updated the example to work with the latest release.

After a pip install pycallgraph and installing GraphViz you can run it from the command line:

pycallgraph graphviz -- ./mypythonscript.py

Or, you can profile particular parts of your code:

from pycallgraph import PyCallGraph
from pycallgraph.output import GraphvizOutput

with PyCallGraph(output=GraphvizOutput()):
    code_to_profile()

Either of these will generate a pycallgraph.png file similar to the image below:


Also worth mentioning is the GUI cProfile dump viewer RunSnakeRun. It allows you to sort and select, thereby zooming in on the relevant parts of the program. The sizes of the rectangles in the picture is proportional to the time taken. If you mouse over a rectangle it highlights that call in the table and everywhere on the map. When you double-click on a rectangle it zooms in on that portion. It will show you who calls that portion and what that portion calls.

The descriptive information is very helpful. It shows you the code for that bit which can be helpful when you are dealing with built-in library calls. It tells you what file and what line to find the code.

Also want to point at that the OP said 'profiling' but it appears he meant 'timing'. Keep in mind programs will run slower when profiled.


I ran into a handy tool called SnakeViz when researching this topic. SnakeViz is a web-based profiling visualization tool. It is very easy to install and use. The usual way I use it is to generate a stat file with %prun and then do analysis in SnakeViz.

The main viz technique used is Sunburst chart as shown below, in which the hierarchy of function calls is arranged as layers of arcs and time info encoded in their angular widths.

The best thing is you can interact with the chart. For example, to zoom in one can click on an arc, and the arc and its descendants will be enlarged as a new sunburst to display more details.


I recently created tuna for visualizing Python runtime and import profiles; this may be helpful here.

Install with

pip3 install tuna

Create a runtime profile

python -mcProfile -o program.prof yourfile.py

or an import profile (Python 3.7+ required)

python -X importprofile yourfile.py 2> import.log

Then just run tuna on the file

tuna program.prof

In Virtaal's source there's a very useful class and decorator that can make profiling (even for specific methods/functions) very easy. The output can then be viewed very comfortably in KCacheGrind.


It would depend on what you want to see out of profiling. Simple time metrics can be given by (bash).

time python python_prog.py

Even '/usr/bin/time' can output detailed metrics by using '--verbose' flag.

To check time metrics given by each function and to better understand how much time is spent on functions, you can use the inbuilt cProfile in python.

Going into more detailed metrics like performance, time is not the only metric. You can worry about memory, threads etc.
Profiling options:
1. line_profiler is another profiler used commonly to find out timing metrics line-by-line.
2. memory_profiler is a tool to profile memory usage.
3. heapy (from project Guppy) Profile how objects in the heap are used.

These are some of the common ones I tend to use. But if you want to find out more, try reading this book It is a pretty good book on starting out with performance in mind. You can move onto advanced topics on using Cython and JIT(Just-in-time) compiled python.


My way is to use yappi (https://code.google.com/p/yappi/). It's especially useful combined with an RPC server where (even just for debugging) you register method to start, stop and print profiling information, e.g. in this way:

@staticmethod
def startProfiler():
    yappi.start()

@staticmethod
def stopProfiler():
    yappi.stop()

@staticmethod
def printProfiler():
    stats = yappi.get_stats(yappi.SORTTYPE_TTOT, yappi.SORTORDER_DESC, 20)
    statPrint = '\n'
    namesArr = [len(str(stat[0])) for stat in stats.func_stats]
    log.debug("namesArr %s", str(namesArr))
    maxNameLen = max(namesArr)
    log.debug("maxNameLen: %s", maxNameLen)

    for stat in stats.func_stats:
        nameAppendSpaces = [' ' for i in range(maxNameLen - len(stat[0]))]
        log.debug('nameAppendSpaces: %s', nameAppendSpaces)
        blankSpace = ''
        for space in nameAppendSpaces:
            blankSpace += space

        log.debug("adding spaces: %s", len(nameAppendSpaces))
        statPrint = statPrint + str(stat[0]) + blankSpace + " " + str(stat[1]).ljust(8) + "\t" + str(
            round(stat[2], 2)).ljust(8 - len(str(stat[2]))) + "\t" + str(round(stat[3], 2)) + "\n"

    log.log(1000, "\nname" + ''.ljust(maxNameLen - 4) + " ncall \tttot \ttsub")
    log.log(1000, statPrint)

Then when your program work you can start profiler at any time by calling the startProfiler RPC method and dump profiling information to a log file by calling printProfiler (or modify the rpc method to return it to the caller) and get such output:

2014-02-19 16:32:24,128-|SVR-MAIN  |-(Thread-3   )-Level 1000: 
name                                                                                                                                      ncall     ttot    tsub
2014-02-19 16:32:24,128-|SVR-MAIN  |-(Thread-3   )-Level 1000: 
C:\Python27\lib\sched.py.run:80                                                                                                           22        0.11    0.05
M:\02_documents\_repos\09_aheadRepos\apps\ahdModbusSrv\pyAheadRpcSrv\xmlRpc.py.iterFnc:293                                                22        0.11    0.0
M:\02_documents\_repos\09_aheadRepos\apps\ahdModbusSrv\serverMain.py.makeIteration:515                                                    22        0.11    0.0
M:\02_documents\_repos\09_aheadRepos\apps\ahdModbusSrv\pyAheadRpcSrv\PicklingXMLRPC.py._dispatch:66                                       1         0.0     0.0
C:\Python27\lib\BaseHTTPServer.py.date_time_string:464                                                                                    1         0.0     0.0
c:\users\zasiec~1\appdata\local\temp\easy_install-hwcsr1\psutil-1.1.2-py2.7-win32.egg.tmp\psutil\_psmswindows.py._get_raw_meminfo:243     4         0.0     0.0
C:\Python27\lib\SimpleXMLRPCServer.py.decode_request_content:537                                                                          1         0.0     0.0
c:\users\zasiec~1\appdata\local\temp\easy_install-hwcsr1\psutil-1.1.2-py2.7-win32.egg.tmp\psutil\_psmswindows.py.get_system_cpu_times:148 4         0.0     0.0
<string>.__new__:8                                                                                                                        220       0.0     0.0
C:\Python27\lib\socket.py.close:276                                                                                                       4         0.0     0.0
C:\Python27\lib\threading.py.__init__:558                                                                                                 1         0.0     0.0
<string>.__new__:8                                                                                                                        4         0.0     0.0
C:\Python27\lib\threading.py.notify:372                                                                                                   1         0.0     0.0
C:\Python27\lib\rfc822.py.getheader:285                                                                                                   4         0.0     0.0
C:\Python27\lib\BaseHTTPServer.py.handle_one_request:301                                                                                  1         0.0     0.0
C:\Python27\lib\xmlrpclib.py.end:816                                                                                                      3         0.0     0.0
C:\Python27\lib\SimpleXMLRPCServer.py.do_POST:467                                                                                         1         0.0     0.0
C:\Python27\lib\SimpleXMLRPCServer.py.is_rpc_path_valid:460                                                                               1         0.0     0.0
C:\Python27\lib\SocketServer.py.close_request:475                                                                                         1         0.0     0.0
c:\users\zasiec~1\appdata\local\temp\easy_install-hwcsr1\psutil-1.1.2-py2.7-win32.egg.tmp\psutil\__init__.py.cpu_times:1066               4         0.0     0.0 

It may not be very useful for short scripts but helps to optimize server-type processes especially given the printProfiler method can be called multiple times over time to profile and compare e.g. different program usage scenarios.


Python includes a profiler called cProfile. It not only gives the total running time, but also times each function separately, and tells you how many times each function was called, making it easy to determine where you should make optimizations.

You can call it from within your code, or from the interpreter, like this:

import cProfile
cProfile.run('foo()')

Even more usefully, you can invoke the cProfile when running a script:

python -m cProfile myscript.py

To make it even easier, I made a little batch file called 'profile.bat':

python -m cProfile %1

So all I have to do is run:

profile euler048.py

And I get this:

1007 function calls in 0.061 CPU seconds

Ordered by: standard name
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.061    0.061 <string>:1(<module>)
 1000    0.051    0.000    0.051    0.000 euler048.py:2(<lambda>)
    1    0.005    0.005    0.061    0.061 euler048.py:2(<module>)
    1    0.000    0.000    0.061    0.061 {execfile}
    1    0.002    0.002    0.053    0.053 {map}
    1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler objects}
    1    0.000    0.000    0.000    0.000 {range}
    1    0.003    0.003    0.003    0.003 {sum}

EDIT: Updated link to a good video resource from PyCon 2013 titled Python Profiling
Also via YouTube.


There's a lot of great answers but they either use command line or some external program for profiling and/or sorting the results.

I really missed some way I could use in my IDE (eclipse-PyDev) without touching the command line or installing anything. So here it is.

Profiling without command line

def count():
    from math import sqrt
    for x in range(10**5):
        sqrt(x)

if __name__ == '__main__':
    import cProfile, pstats
    cProfile.run("count()", "{}.profile".format(__file__))
    s = pstats.Stats("{}.profile".format(__file__))
    s.strip_dirs()
    s.sort_stats("time").print_stats(10)

See docs or other answers for more info.


There's also a statistical profiler called statprof. It's a sampling profiler, so it adds minimal overhead to your code and gives line-based (not just function-based) timings. It's more suited to soft real-time applications like games, but may be have less precision than cProfile.

The version in pypi is a bit old, so can install it with pip by specifying the git repository:

pip install git+git://github.com/bos/[email protected]

You can run it like this:

import statprof

with statprof.profile():
    my_questionable_function()

See also https://.com/a/10333592/320036


When i'm not root on the server, I use lsprofcalltree.py and run my program like this:

python lsprofcalltree.py -o callgrind.1 test.py

Then I can open the report with any callgrind-compatible software, like qcachegrind


cProfile is great for quick profiling but most of the time it was ending for me with the errors. Function runctx solves this problem by initializing correctly the environment and variables, hope it can be useful for someone:

import cProfile
cProfile.runctx('foo()', None, locals())




time-complexity