How can you profile a Python script?

Question

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?

Answer 1

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.

Answer 2

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.

Answer 3

To add on to https://stackoverflow.com/a/582337/1070617,

I wrote this module that allows you to use cProfile and view its output easily. More here: https://github.com/ymichael/cprofilev

$ python -m cprofilev /your/python/program
# Go to http://localhost:4000 to view collected statistics.

Also see: http://ymichael.com/2014/03/08/profiling-python-with-cprofile.html on how to make sense of the collected statistics.

Answer 4

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.

Answer 5

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