Monday, December 30, 2019

Python Timer Functions: Three Ways to Monitor Your Code

While many developers recognize Python as an effective programming language, pure Python programs may run slower than their counterparts in compiled languages like C, Rust, and Java. Throughout this tutorial, you’ll see how to use a Python timer to monitor how fast your programs are running.

In this tutorial, you’ll learn how to use:

  • time.perf_counter() to measure time in Python
  • Classes to keep state
  • Context managers to work with a block of code
  • Decorators to customize a function

You’ll also gain background knowledge into how classes, context managers, and decorators work. As you see examples of each concept, you’ll be inspired to use one or several of them in your code, both for timing code execution and other applications. Each method has its advantages, and you’ll learn which to use depending on the situation. Plus, you’ll have a working Python timer that you can use to monitor your programs!

Python Timers

First, you’ll take a look at some example code that you’ll use throughout the tutorial. Later, you’ll add a Python timer to this code to monitor its performance. You’ll also see some of the simplest ways to measure the running time of this example.

Python Timer Functions

If you look at the built in time module in Python, then you’ll notice several functions that can measure time:

Python 3.7 introduced several new functions, like thread_time(), as well as nanosecond versions of all the functions above, named with an _ns suffix. For example, perf_counter_ns() is the nanosecond version of perf_counter(). You’ll learn more about these functions later. For now, note what the documentation has to say about perf_counter():

Return the value (in fractional seconds) of a performance counter, i.e. a clock with the highest available resolution to measure a short duration. (Source)

First, you’ll use perf_counter() to create a Python timer. Later, you’ll compare this with other Python timer functions and learn why perf_counter() is usually the best choice.

Example: Download Tutorials

To better compare the different ways you can add a Python timer to your code, you’ll apply different Python timer functions to the same code example throughout this tutorial. If you already have code you’d like to measure, then feel free to follow the examples with that instead.

The example you’ll see in this tutorial is a short function that uses the realpython-reader package to download the latest tutorials available here on Real Python. To learn more about the Real Python Reader and how it works, check out How to Publish an Open-Source Python Package to PyPI. You can install realpython-reader on your system with pip:

$ python -m pip install realpython-reader

Then, you can import the package as reader.

You’ll store the example in a file named latest_tutorial.py. The code consists of one function that downloads and prints the latest tutorial from Real Python:

 1 # latest_tutorial.py
 2 
 3 from reader import feed
 4 
 5 def main():
 6     """Download and print the latest tutorial from Real Python"""
 7     tutorial = feed.get_article(0)
 8     print(tutorial)
 9 
10 if __name__ == "__main__":
11     main()

realpython-reader handles most of the hard work:

  • Line 3 imports feed from realpython-reader. This module contains functionality for downloading tutorials from the Real Python feed.
  • Line 7 downloads the latest tutorial from Real Python. The number 0 is an offset, where 0 means the most recent tutorial, 1 is the previous tutorial, and so on.
  • Line 8 prints the tutorial to the console.
  • Line 11 calls main() when you run the script.

When you run this example, your output will typically look something like this:

$ python latest_tutorial.py
# Python Timer Functions: Three Ways to Monitor Your Code

While many developers recognize Python as an effective programming language,
pure Python programs may run slower than their counterparts in compiled
languages like C, Rust, and Java. Throughout this tutorial, you’ll see how to
use a Python timer to monitor how fast your programs are running.

[ ... The full text of the tutorial ... ]

The code may take a little while to run depending on the network, so you might want to use a Python timer to monitor the performance of the script.

Your First Python Timer

Let’s add a bare-bones Python timer to the example with time.perf_counter(). Again, this is a performance counter that’s well-suited for timing parts of your code.

perf_counter() measures the time in seconds from some unspecified moment in time, which means that the return value of a single call to the function isn’t useful. However, when you look at the difference between two calls to perf_counter(), you can figure out how many seconds passed between the two calls:

>>> 
>>> import time
>>> time.perf_counter()
32311.48899951

>>> time.perf_counter()  # A few seconds later
32315.261320793

In this example, you made two calls to perf_counter() almost 4 seconds apart. You can confirm this by calculating the difference between the two outputs: 32315.26 - 32311.49 = 3.77.

You can now add a Python timer to the example code:

 1 # latest_tutorial.py
 2 
 3 import time
 4 from reader import feed
 5 
 6 def main():
 7     """Print the latest tutorial from Real Python"""
 8     tic = time.perf_counter()
 9     tutorial = feed.get_article(0)
10     toc = time.perf_counter()
11     print(f"Downloaded the tutorial in {toc - tic:0.4f} seconds")
12 
13     print(tutorial)
14 
15 if __name__ == "__main__":
16     main()

Note that you call perf_counter() both before and after downloading the tutorial. You then print the time it took to download the tutorial by calculating the difference between the two calls.

Now, when you run the example, you’ll see the elapsed time before the tutorial:

$ python latest_tutorial.py
Downloaded the tutorial in 0.67 seconds
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of the tutorial ... ]

That’s it! You’ve covered the basics of timing your own Python code. In the rest of the tutorial, you’ll learn how you can wrap a Python timer into a class, a context manager, and a decorator to make it more consistent and convenient to use.

A Python Timer Class

Look back at how you added the Python timer to the example above. Note that you need at least one variable (tic) to store the state of the Python timer before you download the tutorial. After staring at the code a little, you might also note that the three highlighted lines are added only for timing purposes! Now, you’ll create a class that does the same as your manual calls to perf_counter(), but in a more readable and consistent manner.

Throughout this tutorial, you’ll create and update Timer, a class that you can use to time your code in several different ways. The final code is also available on PyPI under the name codetiming. You can install this to your system like so:

$ python -m pip install codetiming

You can find more information about codetiming later on in this tutorial, in the section named The Python Timer Code.

Understanding Classes in Python

Classes are the main building blocks of object-oriented programming. A class is essentially a template that you can use to create objects. While Python doesn’t force you to program in an object-oriented manner, classes are everywhere in the language. For a quick proof, let’s investigate the time module:

>>> 
>>> import time
>>> type(time)
<class 'module'>

>>> time.__class__
<class 'module'>

type() returns the type of an object. Here you can see that modules are in fact objects created from a module class. The special attribute .__class__ can be used to get access to the class that defines an object. In fact, almost everything in Python is a class:

>>> 
>>> type(3)
<class 'int'>

>>> type(None)
<class 'NoneType'>

>>> type(print)
<class 'builtin_function_or_method'>

>>> type(type)
<class 'type'>

In Python, classes are great when you need to model something that needs to keep track of a particular state. In general, a class is a collection of properties (called attributes) and behaviors (called methods). For more background on classes and object-oriented programming, check out Object-Oriented Programming (OOP) in Python 3 or the official docs.

Creating a Python Timer Class

Classes are good for tracking state. In a Timer class, you want to keep track of when a timer starts and how much time has passed since then. For the first implementation of Timer, you’ll add a ._start_time attribute, as well as .start() and .stop() methods. Add the following code to a file named timer.py:

 1 # timer.py
 2 
 3 import time
 4 
 5 class TimerError(Exception):
 6     """A custom exception used to report errors in use of Timer class"""
 7 
 8 class Timer:
 9     def __init__(self):
10         self._start_time = None
11 
12     def start(self):
13         """Start a new timer"""
14         if self._start_time is not None:
15             raise TimerError(f"Timer is running. Use .stop() to stop it")
16 
17         self._start_time = time.perf_counter()
18 
19     def stop(self):
20         """Stop the timer, and report the elapsed time"""
21         if self._start_time is None:
22             raise TimerError(f"Timer is not running. Use .start() to start it")
23 
24         elapsed_time = time.perf_counter() - self._start_time
25         self._start_time = None
26         print(f"Elapsed time: {elapsed_time:0.4f} seconds")

A few different things are happening here, so let’s walk through the code step by step.

In line 5, you define a TimerError class. The (Exception) notation means that TimerError inherits from another class called Exception. Python uses this built-in class for error handling. You don’t need to add any attributes or methods to TimerError. However, having a custom error will give you more flexibility to handle problems inside Timer. For more information, check out Python Exceptions: An Introduction.

The definition of Timer itself starts on line 8. When you first create or instantiate an object from a class, your code calls the special method .__init__(). In this first version of Timer, you only initialize the ._start_time attribute, which you’ll use to track the state of your Python timer. It has the value None when the timer isn’t running. Once the timer is running, ._start_time keeps track of when the timer started.

When you call .start() to start a new Python timer, you first check that the timer isn’t already running. Then you store the current value of perf_counter() in ._start_time. On the other hand, when you call .stop(), you first check that the Python timer is running. If it is, then you calculate the elapsed time as the difference between the current value of perf_counter() and the one you stored in ._start_time. Finally, you reset ._start_time so that the timer can be restarted, and print the elapsed time.

Here’s how you use Timer:

>>> 
>>> from timer import Timer
>>> t = Timer()
>>> t.start()

>>> t.stop()  # A few seconds later
Elapsed time: 3.8191 seconds

Compare this to the earlier example where you used perf_counter() directly. The structure of the code is fairly similar, but now the code is more clear, and this is one of the benefits of using classes. By carefully choosing your class, method, and attribute names, you can make your code very descriptive!

Using the Python Timer Class

Let’s apply Timer to latest_tutorial.py. You only need to make a few changes to your previous code:

# latest_tutorial.py

from timer import Timer
from reader import feed

def main():
    """Print the latest tutorial from Real Python"""
    t = Timer()
    t.start()
    tutorial = feed.get_article(0)
    t.stop()

    print(tutorial)

if __name__ == "__main__":
    main()

Notice that the code is very similar to what you saw earlier. In addition to making the code more readable, Timer takes care of printing the elapsed time to the console, which makes the logging of time spent more consistent. When you run the code, you’ll see pretty much the same output:

$ python latest_tutorial.py
Elapsed time: 0.64 seconds
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of the tutorial ... ]

Printing the elapsed time from Timer may be consistent, but it seems that this approach is not very flexible. In the next section, you’ll see how to customize your class.

Adding More Convenience and Flexibility

So far, you’ve seen that classes are suitable for when you want to encapsulate state and ensure consistent behavior in your code. In this section, you’ll add more convenience and flexibility to your Python timer:

  • Use adaptable text and formatting when reporting the time spent
  • Apply flexible logging, either to the screen, to a log file, or other parts of your program
  • Create a Python timer that can accumulate over several invocations
  • Build an informative representation of a Python timer

First, let’s see how you can customize the text used to report the time spent. In the previous code, the text f"Elapsed time: {elapsed_time:0.4f} seconds" is hard-coded into .stop(). You can add flexibility to classes using instance variables. Their values are normally passed as arguments to .__init__() and stored as self attributes. For convenience, you can also provide reasonable default values.

To add .text as a Timer instance variable, you’ll do something like this:

def __init__(self, text="Elapsed time: {:0.4f} seconds"):
    self._start_time = None
    self.text = text

Note that the default text, "Elapsed time: {:0.4f} seconds", is given as a regular string, not as an f-string. You can’t use an f-string here because they evaluate immediately, and when you instantiate Timer, your code has not yet calculated the elapsed time.

In .stop(), you use .text as a template and .format() to populate the template:

def stop(self):
    """Stop the timer, and report the elapsed time"""
    if self._start_time is None:
        raise TimerError(f"Timer is not running. Use .start() to start it")

    elapsed_time = time.perf_counter() - self._start_time
    self._start_time = None
    print(self.text.format(elapsed_time))

After this update to timer.py, you can change the text as follows:

>>> 
>>> from timer import Timer
>>> t = Timer(text="You waited {:.1f} seconds")
>>> t.start()

>>> t.stop()  # A few seconds later
You waited 4.1 seconds

Next, assume that you don’t just want to print a message to the console. Maybe you want to save your time measurements so you can store them in a database. You can do this by returning the value of elapsed_time from .stop(). Then, the calling code can choose to either ignore that return value or save it for later processing.

Perhaps you want to integrate Timer into your logging routines. To support logging or other outputs from Timer you need to change the call to print() so that the user can supply their own logging function. This can be done similar to how you customized the text earlier:

def __init__(self, text="Elapsed time: {:0.4f} seconds", logger=print):
    self._start_time = None
    self.text = text
    self.logger = logger

def stop(self):
    """Stop the timer, and report the elapsed time"""
    if self._start_time is None:
        raise TimerError(f"Timer is not running. Use .start() to start it")

    elapsed_time = time.perf_counter() - self._start_time
    self._start_time = None

    if self.logger:
        self.logger(self.text.format(elapsed_time))

    return elapsed_time

Instead of using print() directly, you create another instance variable, self.logger, that should refer to a function that takes a string as an argument. In addition to print(), you can use functions like logging.info() or .write() on file objects. Also note the if test, which allows you to turn off printing completely by passing logger=None.

Here are two examples that show the new functionality in action:

>>> 
>>> from timer import Timer
>>> import logging
>>> t = Timer(logger=logging.warning)
>>> t.start()

>>> t.stop()  # A few seconds later
WARNING:root:Elapsed time: 3.1610 seconds
3.1609658249999484

>>> t = Timer(logger=None)
>>> t.start()

>>> value = t.stop()  # A few seconds later
>>> value
4.710851433001153

When you run these examples in an interactive shell, Python prints the return value automatically.

The third improvement you’ll add is the ability to accumulate time measurements. You may want to do this, for instance, when you’re calling a slow function in a loop. You’ll add a bit more functionality in the form of named timers with a dictionary that keeps track of every Python timer in your code.

Assume that you’re expanding latest_tutorial.py to a latest_tutorials.py script that downloads and prints the ten latest tutorials from Real Python. The following is one possible implementation:

# latest_tutorials.py

from timer import Timer
from reader import feed

def main():
    """Print the 10 latest tutorials from Real Python"""
    t = Timer(text="Downloaded 10 tutorials in {:0.2f} seconds")
    t.start()
    for tutorial_num in range(10):
        tutorial = feed.get_article(tutorial_num)
        print(tutorial)
    t.stop()

if __name__ == "__main__":
    main()

The code loops over the numbers from 0 to 9 and uses those as offset arguments to feed.get_article(). When you run the script, you’ll see a lot of information printed to your console:

$ python latest_tutorials.py
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of ten tutorials ... ]
Downloaded 10 tutorials in 0.67 seconds

One subtle issue with this code is that you’re not only measuring the time it takes to download the tutorials, but also the time Python spends printing the tutorials to your screen. This might not be that important since the time spent printing should be negligible compared to the time spent downloading. Still, it would be good to have a way to precisely time what you’re after in these kinds of situations.

There are several ways you can work around this without changing the current implementation of Timer. However, supporting this use case will be quite useful, and can be done with just a few lines of code.

First, you’ll introduce a dictionary called .timers as a class variable on Timer, which means that all instances of Timer will share it. You implement it by defining it outside any methods:

class Timer:
    timers = dict()

Class variables can be accessed either directly on the class, or through an instance of the class:

>>> 
>>> from timer import Timer
>>> Timer.timers
{}

>>> t = Timer()
>>> t.timers
{}

>>> Timer.timers is t.timers
True

In both cases, the code returns the same empty class dictionary.

Next, you’ll add optional names to your Python timer. You can use the name for two different purposes:

  1. Looking up the elapsed time later in your code
  2. Accumulating timers with the same name

To add names to your Python timer, you need to make two more changes to timer.py. First, Timer should accept the name as a parameter. Second, the elapsed time should be added to .timers when a timer stops:

class Timer:
    timers = dict()

    def __init__(
        self,
        name=None,
        text="Elapsed time: {:0.4f} seconds",
        logger=print,
    ):
        self._start_time = None
        self.name = name
        self.text = text
        self.logger = logger

        # Add new named timers to dictionary of timers
        if name:
            self.timers.setdefault(name, 0)

    # Other methods are unchanged

    def stop(self):
        """Stop the timer, and report the elapsed time"""
        if self._start_time is None:
            raise TimerError(f"Timer is not running. Use .start() to start it")

        elapsed_time = time.perf_counter() - self._start_time
        self._start_time = None

        if self.logger:
            self.logger(self.text.format(elapsed_time))
        if self.name:
            self.timers[self.name] += elapsed_time

        return elapsed_time

Note that you use .setdefault() when adding the new Python timer to .timers. This is a great feature that only sets the value if name is not already defined in the dictionary. If name is already used in .timers, then the value is left untouched. This allows you to accumulate several timers:

>>> 
>>> from timer import Timer
>>> t = Timer("accumulate")
>>> t.start()

>>> t.stop()  # A few seconds later
Elapsed time: 3.7036 seconds
3.703554293999332

>>> t.start()

>>> t.stop()  # A few seconds later
Elapsed time: 2.3449 seconds
2.3448921170001995

>>> Timer.timers
{'accumulate': 6.0484464109995315}

You can now revisit latest_tutorials.py and make sure only the time spent on downloading the tutorials is measured:

# latest_tutorials.py

from timer import Timer
from reader import feed

def main():
    """Print the 10 latest tutorials from Real Python"""
    t = Timer("download", logger=None)
    for tutorial_num in range(10):
        t.start()
        tutorial = feed.get_article(tutorial_num)
        t.stop()
        print(tutorial)

    download_time = Timer.timers["download"]
    print(f"Downloaded 10 tutorials in {download_time:0.2f} seconds")

if __name__ == "__main__":
    main()

Rerunning the script will give similar output as earlier, although now you are only timing the actual download of the tutorials:

$ python latest_tutorials.py
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of ten tutorials ... ]
Downloaded 10 tutorials in 0.65 seconds

The final improvement that you’ll make to Timer is to make it more informative when you’re working with it interactively. Try the following:

>>> 
>>> from timer import Timer
>>> t = Timer()
>>> t
<timer.Timer object at 0x7f0578804320>

That last line is the default way Python represents objects. While you can glean some information from it, it’s usually not very useful. Instead, it would be nice to see things like the name of the Timer, or how it will report on the timings.

In Python 3.7, data classes were added to the standard library. These provide several conveniences to your classes, including a more informative representation string.

You convert your Python timer to a data class using the @dataclass decorator. You’ll learn more about decorators later in this tutorial. For now, you can think of this as a notation that tells Python that Timer is a data class:

 1 from dataclasses import dataclass, field
 2 from typing import Any, ClassVar
 3 
 4 @dataclass
 5 class Timer:
 6     timers: ClassVar = dict()
 7     name: Any = None
 8     text: Any = "Elapsed time: {:0.4f} seconds"
 9     logger: Any = print
10     _start_time: Any = field(default=None, init=False, repr=False)
11 
12     def __post_init__(self):
13         """Initialization: add timer to dict of timers"""
14         if self.name:
15             self.timers.setdefault(self.name, 0)
16 
17     # The rest of the code is unchanged

This code replaces your earlier .__init__() method. Note how data classes use syntax that looks similar to the class variable syntax you saw earlier for defining all variables. In fact, .__init__() is created automatically for data classes, based on annotated variables in the definition of the class.

You need to annotate your variables to use a data class. You can use this to add type hints to your code. If you don’t want to use type hints, then you can instead annotate all variables with Any, just like you did above. You’ll soon see how to add actual type hints to your data class.

Here are a few notes about the Timer data class:

  • Line 4: The @dataclass decorator defines Timer to be a data class.

  • Line 6: The special ClassVar annotation is necessary for data classes to specify that .timers is a class variable.

  • Lines 7 to 9: .name, .text, and .logger will be defined as attributes on Timer, whose values can be specified when creating Timer instances. They all have the given default values.

  • Line 10: Recall that ._start_time is a special attribute that’s used to keep track of the state of the Python timer, but should be hidden from the user. Using dataclasses.field() you say that ._start_time should be removed from .__init__() and the representation of Timer.

  • Lines 12 to 15: You can use the special .__post_init__() method for any initialization you need to do apart from setting the instance attributes. Here, you use it to add named timers to .timers.

Your new Timer data class works just like your previous regular class, except that it now has a nice representation:

>>> 
>>> from timer import Timer
>>> t = Timer()
>>> t
Timer(name=None, text='Elapsed time: {:0.4f} seconds',
      logger=<built-in function print>)

>>> t.start()

>>> t.stop()  # A few seconds later
Elapsed time: 6.7197 seconds
6.719705373998295

Now you have a pretty neat version of Timer that’s consistent, flexible, convenient, and informative! Many of the improvements you’ve seen in this section can be applied to other types of classes in your projects as well.

Before ending this section, let’s have a look at the complete source code of Timer as it currently stands. You’ll notice the addition of type hints to the code for extra documentation:

# timer.py

from dataclasses import dataclass, field
import time
from typing import Callable, ClassVar, Dict, Optional

class TimerError(Exception):
    """A custom exception used to report errors in use of Timer class"""

@dataclass
class Timer:
    timers: ClassVar[Dict[str, float]] = dict()
    name: Optional[str] = None
    text: str = "Elapsed time: {:0.4f} seconds"
    logger: Optional[Callable[[str], None]] = print
    _start_time: Optional[float] = field(default=None, init=False, repr=False)

    def __post_init__(self) -> None:
        """Add timer to dict of timers after initialization"""
        if self.name is not None:
            self.timers.setdefault(self.name, 0)

    def start(self) -> None:
        """Start a new timer"""
        if self._start_time is not None:
            raise TimerError(f"Timer is running. Use .stop() to stop it")

        self._start_time = time.perf_counter()

    def stop(self) -> float:
        """Stop the timer, and report the elapsed time"""
        if self._start_time is None:
            raise TimerError(f"Timer is not running. Use .start() to start it")

        # Calculate elapsed time
        elapsed_time = time.perf_counter() - self._start_time
        self._start_time = None

        # Report elapsed time
        if self.logger:
            self.logger(self.text.format(elapsed_time))
        if self.name:
            self.timers[self.name] += elapsed_time

        return elapsed_time

Using a class to create a Python timer has several benefits:

  • Readability: Your code will read more naturally if you carefully choose class and method names.
  • Consistency: Your code will be easier to use if you encapsulate properties and behaviors into attributes and methods.
  • Flexibility: Your code will be reusable if you use attributes with default values instead of hardcoded values.

This class is very flexible, and you can use it in almost any situation where you want to monitor the time it takes for code to run. However, in the next sections, you’ll learn about using context managers and decorators, which will be more convenient for timing code blocks and functions.

A Python Timer Context Manager

Your Python Timer class has come a long way! Compared with the first Python timer you created, your code has gotten quite powerful. However, there’s still a bit of boilerplate code necessary to use your Timer:

  1. First, instantiate the class.
  2. Call .start() before the code block that you want to time.
  3. Call .stop() after the code block.

Luckily, Python has a unique construct for calling functions before and after a block of code: the context manager. In this section, you’ll learn what context managers are and how you can create your own. Then you’ll see how to expand Timer so that it can work as a context manager as well. Finally, you’ll see how using Timer as a context manager can simplify your code.

Understanding Context Managers in Python

Context managers have been a part of Python for a long time. They were introduced by PEP 343 in 2005, and first implemented in Python 2.5. You can recognize context managers in code by the use of the with keyword:

with EXPRESSION as VARIABLE:
    BLOCK

EXPRESSION is some Python expression that returns a context manager. The context manager is optionally bound to the name VARIABLE. Finally, BLOCK is any regular Python code block. The context manager will guarantee that your program calls some code before BLOCK and some other code after BLOCK executes. The latter will happen, even if BLOCK raises an exception.

The most common use of context managers is probably handling different resources, like files, locks, and database connections. The context manager is then used to free and clean up the resource after you’ve used it. The following example reveals the fundamental structure of timer.py by only printing lines that contain a colon. More importantly, it shows the common idiom for opening a file in Python:

>>> 
>>> with open("timer.py") as fp:
...     print("".join(ln for ln in fp if ":" in ln))
...
class TimerError(Exception):
class Timer:
    timers: ClassVar[Dict[str, float]] = dict()
    name: Optional[str] = None
    text: str = "Elapsed time: {:0.4f} seconds"
    logger: Optional[Callable[[str], None]] = print
    _start_time: Optional[float] = field(default=None, init=False, repr=False)
    def __post_init__(self) -> None:
        if self.name is not None:
    def start(self) -> None:
        if self._start_time is not None:
    def stop(self) -> float:
        if self._start_time is None:
        if self.logger:
        if self.name:

Note that fp, the file pointer, is never explicitly closed because you used open() as a context manager. You can confirm that fp has closed automatically:

>>> 
>>> fp.closed
True

In this example, open("timer.py") is an expression that returns a context manager. That context manager is bound to the name fp. The context manager is in effect during the execution of print(). This one-line code block executes in the context of fp.

What does it mean that fp is a context manager? Technically, it means that fp implements the context manager protocol. There are many different protocols underlying the Python language. You can think of a protocol as a contract that states what specific methods your code must implement.

The context manager protocol consists of two methods:

  1. Call .__enter__() when entering the context related to the context manager.
  2. Call .__exit__() when exiting the context related to the context manager.

In other words, to create a context manager yourself, you need to write a class that implements .__enter__() and .__exit__(). No more, no less. Let’s try a Hello, World! context manager example:

# greeter.py

class Greeter:
    def __init__(self, name):
        self.name = name

    def __enter__(self):
        print(f"Hello {self.name}")
        return self

    def __exit__(self, exc_type, exc_value, exc_tb):
        print(f"See you later, {self.name}")

Greeter is a context manager because it implements the context manager protocol. You can use it like this:

>>> 
>>> from greeter import Greeter
>>> with Greeter("Nick"):
...     print("Doing stuff ...")
...
Hello Nick
Doing stuff ...
See you later, Nick

First, note how .__enter__() is called before you’re doing stuff, while .__exit__() is called after. In this simplified example, you’re not referencing the context manager. In such cases, you don’t need to give the context manager a name with as.

Next, notice how .__enter__() returns self. The return value of .__enter__() is what is bound by as. You usually want to return self from .__enter__() when creating context managers. You can use that return value as follows:

>>> 
>>> from greeter import Greeter
>>> with Greeter("Emily") as grt:
...     print(f"{grt.name} is doing stuff ...")
...
Hello Emily
Emily is doing stuff ...
See you later, Emily

Finally, .__exit__() takes three arguments: exc_type, exc_value, and exc_tb. These are used for error handling within the context manager, and mirror the return values of sys.exc_info(). If an exception happens while the block is being executed, then your code calls .__exit__() with the type of the exception, an exception instance, and a traceback object. Often, you can ignore these in your context manager, in which case .__exit__() is called before the exception is reraised:

>>> 
>>> from greeter import Greeter
>>> with Greeter("Rascal") as grt:
...     print(f"{grt.age} does not exist")
...
Hello Rascal
See you later, Rascal
Traceback (most recent call last):
  File "<stdin>", line 2, in <module>
AttributeError: 'Greeter' object has no attribute 'age'

You can see that "See you later, Rascal" is printed, even though there is an error in the code.

Now you know what context managers are and how you can create your own. If you want to dive deeper, then check out contextlib in the standard library. It includes convenient ways for defining new context managers, as well as ready-made context managers that can be used to close objects, suppress errors, or even do nothing! For even more information, check out Python Context Managers and the “with” Statement and the accompanying tutorial.

Creating a Python Timer Context Manager

You’ve seen how context managers work in general, but how can they help with timing code? If you can run certain functions before and after a block of code, then you can simplify how your Python timer works. So far, you’ve needed to call .start() and .stop() explicitly when timing your code, but a context manager can do this automatically.

Again, for Timer to work as a context manager, it needs to adhere to the context manager protocol. In other words, it must implement .__enter__() and .__exit__() to start and stop the Python timer. All the necessary functionality is already available, so there’s not much new code you need to write. Just add the following methods to your Timer class:

def __enter__(self):
    """Start a new timer as a context manager"""
    self.start()
    return self

def __exit__(self, *exc_info):
    """Stop the context manager timer"""
    self.stop()

Timer is now a context manager. The important part of the implementation is that .__enter__() calls .start() to start a Python timer when the context is entered, and .__exit__() uses .stop() to stop the Python timer when the code leaves the context. Try it out:

>>> 
>>> from timer import Timer
>>> import time
>>> with Timer():
...     time.sleep(0.7)
...
Elapsed time: 0.7012 seconds

You should also note two more subtle details:

  1. .__enter__() returns self, the Timer instance, which allows the user to bind the Timer instance to a variable using as. For example, with Timer() as t: will create the variable t pointing to the Timer object.

  2. .__exit__() expects a triple of arguments with information about any exception that occurred during the execution of the context. In your code, these arguments are packed into a tuple called exc_info and then ignored, which means that Timer will not attempt any exception handling.

.__exit__() doesn’t do any error handling in this case. Still, one of the great features of context managers is that they’re guaranteed to call .__exit__(), no matter how the context exits. In the following example, you purposely create an error by dividing by zero:

>>> 
>>> from timer import Timer
>>> with Timer():
...     for num in range(-3, 3):
...         print(f"1 / {num} = {1 / num:.3f}")
...
1 / -3 = -0.333
1 / -2 = -0.500
1 / -1 = -1.000
Elapsed time: 0.0001 seconds
Traceback (most recent call last):
  File "<stdin>", line 3, in <module>
ZeroDivisionError: division by zero

Note that Timer prints out the elapsed time, even though the code crashed. It’s possible to inspect and suppress errors in .__exit__(). See the documentation for more information.

Using the Python Timer Context Manager

Let’s see how to use the Timer context manager to time the download of Real Python tutorials. Recall how you used Timer earlier:

# latest_tutorial.py

from timer import Timer
from reader import feed

def main():
    """Print the latest tutorial from Real Python"""
    t = Timer()
    t.start()
    tutorial = feed.get_article(0)
    t.stop()

    print(tutorial)

if __name__ == "__main__":
    main()

You’re timing the call to feed.get_article(). You can use the context manager to make the code shorter, simpler, and more readable:

# latest_tutorial.py

from timer import Timer
from reader import feed

def main():
    """Print the latest tutorial from Real Python"""
    with Timer():
        tutorial = feed.get_article(0)

    print(tutorial)

if __name__ == "__main__":
    main()

This code does virtually the same as the code above. The main difference is that you don’t define the extraneous variable t, which keeps your namespace cleaner.

Running the script should give a familiar result:

$ python latest_tutorial.py
Elapsed time: 0.71 seconds
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of the tutorial ... ]

There are a few advantages to adding context manager capabilities to your Python timer class:

  • Low effort: You only need one extra line of code to time the execution of a block of code.
  • Readability: Invoking the context manager is readable, and you can more clearly visualize the code block you’re timing.

Using Timer as a context manager is almost as flexible as using .start() and .stop() directly, while it has less boilerplate code. In the next section, you’ll see how Timer can be used as a decorator as well. This will make it easier to monitor the runtime of complete functions.

A Python Timer Decorator

Your Timer class is now very versatile. However, there’s one use case where it could be even more streamlined. Say that you want to track the time spent inside one given function in your codebase. Using a context manager, you have essentially two different options:

  1. Use Timer every time you call the function:

    with Timer("some_name"):
    do_something()

    If you call do_something() in many places, then this will become cumbersome and hard to maintain.

  2. Wrap the code in your function inside a context manager:

    def do_something():
    with Timer("some_name"):
        ...

    The Timer only needs to be added in one place, but this adds a level of indentation to the whole definition of do_something().

A better solution is to use Timer as a decorator. Decorators are powerful constructs that you use to modify the behavior of functions and classes. In this section, you’ll learn a little about how decorators work, how Timer can be extended to be a decorator, and how that will simplify timing functions. For a more in-depth explanation of decorators, see Primer on Python Decorators.

Understanding Decorators in Python

A decorator is a function that wraps another function to modify its behavior. This technique is possible because functions are first-class objects in Python. In other words, functions can be assigned to variables and used as arguments to other functions, just like any other object. This gives you a lot of flexibility and is the basis for several of Python’s more powerful features.

As a first example, you’ll create a decorator that does nothing:

def turn_off(func):
    return lambda *args, **kwargs: None

First, note that turn_off() is just a regular function. What makes this a decorator is that it takes a function as its only argument and returns a function. You can use this to modify other functions like this:

>>> 
>>> print("Hello")
Hello

>>> print = turn_off(print)
>>> print("Hush")
>>> # Nothing is printed

The line print = turn_off(print) decorates the print statement with the turn_off() decorator. Effectively, it replaces print() with lambda *args, **kwargs: None returned by turn_off(). The lambda statement represents an anonymous function that does nothing except return None.

For you to define more interesting decorators, you need to know about inner functions. An inner function is a function defined inside another function. One common use of inner functions is to create function factories:

def create_multiplier(factor):
    def multiplier(num):
        return factor * num
    return multiplier

multiplier() is an inner function, defined inside create_multiplier(). Note that you have access to factor inside multiplier(), while multiplier() is not defined outside create_multiplier():

>>> 
>>> multiplier
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
NameError: name 'multiplier' is not defined

Instead you use create_multiplier() to create new multiplier functions, each based on a different factor:

>>> 
>>> double = create_multiplier(factor=2)
>>> double(3)
6

>>> quadruple = create_multiplier(factor=4)
>>> quadruple(7)
28

Similarly, you can use inner functions to create decorators. Remember, a decorator is a function that returns a function:

 1 def triple(func):
 2     def wrapper_triple(*args, **kwargs):
 3         print(f"Tripled {func.__name__!r}")
 4         value = func(*args, **kwargs)
 5         return value * 3
 6     return wrapper_triple

triple() is a decorator, because it’s a function that expects a function as it’s only argument, func(), and returns another function, wrapper_triple(). Note the structure of triple() itself:

  • Line 1 starts the definition of triple() and expects a function as an argument.
  • Lines 2 to 5 define the inner function wrapper_triple().
  • Line 6 returns wrapper_triple().

This pattern is prevalent for defining decorators. The interesting parts are those happening inside the inner function:

  • Line 2 starts the definition of wrapper_triple(). This function will replace whichever function triple() decorates. The parameters are *args and **kwargs, which collect whichever positional and keyword arguments you pass to the function. This gives you the flexibility to use triple() on any function.
  • Line 3 prints out the name of the decorated function, and note that triple() has been applied to it.
  • Line 4 calls func(), the function that has been decorated by triple(). It passes on all arguments passed to wrapper_triple().
  • Line 5 triples the return value of func() and returns it.

Let’s try it out! knock() is a function that returns the word Penny. See what happens if it’s tripled:

>>> 
>>> def knock():
...     return "Penny! "
...
>>> knock = triple(knock)
>>> result = knock()
Tripled 'knock'

>>> result
'Penny! Penny! Penny! '

Multiplying a text string by a number is a form of repetition, so Penny repeats three times. The decoration happens at knock = triple(knock).

It feels a bit clunky to keep repeating knock. Instead, PEP 318 introduced a more convenient syntax for applying decorators. The following definition of knock() does the same as the one above:

>>> 
>>> @triple
... def knock():
...     return "Penny! "
...
>>> result = knock()
Tripled 'knock'

>>> result
'Penny! Penny! Penny! '

The @ symbol is used to apply decorators. In this case, @triple means that triple() is applied to the function defined just after it.

One of the few decorators defined in the standard library is @functools.wraps. This one is quite helpful when defining your own decorators. Since decorators effectively replace one function with another, they create a subtle issue with your functions:

>>> 
>>> knock
<function triple.<locals>.wrapper_triple at 0x7fa3bfe5dd90>

@triple decorates knock(), which is then replaced by the wrapper_triple() inner function, as the output above confirms. This will also replace the name, docstring, and other metadata. Often, this will not have much effect, but it can make introspection difficult.

Sometimes, decorated functions must have correct metadata. @functools.wraps fixes exactly this issue:

import functools

def triple(func):
    @functools.wraps(func)
    def wrapper_triple(*args, **kwargs):
        print(f"Tripled {func.__name__!r}")
        value = func(*args, **kwargs)
        return value * 3
    return wrapper_triple

With this new definition of @triple, metadata are preserved:

>>> 
>>> @triple
... def knock():
...     return "Penny! "
...
>>> knock
<function knock at 0x7fa3bfe5df28>

Note that knock() now keeps its proper name, even after being decorated. It’s good form to use @functools.wraps whenever you define a decorator. A blueprint you can use for most of your decorators is the following:

import functools

def decorator(func):
    @functools.wraps(func)
    def wrapper_decorator(*args, **kwargs):
        # Do something before
        value = func(*args, **kwargs)
        # Do something after
        return value
    return wrapper_decorator

To see more examples of how to define decorators, check out the examples listed in Primer on Python Decorators.

Creating a Python Timer Decorator

In this section, you’ll learn how to extend your Python timer so that you can use it as a decorator as well. However, as a first exercise, let’s create a Python timer decorator from scratch.

Based on the blueprint above, you only need to decide what to do before and after you call the decorated function. This is similar to the considerations about what to do when entering and exiting the context manager. You want to start a Python timer before calling the decorated function, and stop the Python timer after the call finishes. A @timer decorator can be defined as follows:

import functools
import time

def timer(func):
    @functools.wraps(func)
    def wrapper_timer(*args, **kwargs):
        tic = time.perf_counter()
        value = func(*args, **kwargs)
        toc = time.perf_counter()
        elapsed_time = toc - tic
        print(f"Elapsed time: {elapsed_time:0.4f} seconds")
        return value
    return wrapper_timer

Note how much wrapper_timer() resembles the early pattern you established for timing Python code. You can apply @timer as follows:

>>> 
>>> @timer
... def latest_tutorial():
...     tutorial = feed.get_article(0)
...     print(tutorial)
...
>>> latest_tutorial()
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of the tutorial ... ]
Elapsed time: 0.5414 seconds

Recall that you can also apply a decorator to a previously defined function:

>>> 
>>> feed.get_article = timer(feed.get_article)

Since @ applies when functions are defined, you need to use the more basic form in these cases. One advantage of using a decorator is that you only need to apply it once, and it’ll time the function every time:

>>> 
>>> tutorial = feed.get_article(0)
Elapsed time: 0.5512 seconds

@timer does the job. However, in a sense, you’re back to square one, since @timer does not have any of the flexibility or convenience of Timer. Can you also make your Timer class act like a decorator?

So far, you’ve used decorators as functions applied to other functions, but that’s not entirely correct. Decorators must be callables. There are many callable types in Python. You can make your own objects callable by defining the special .__call__() method in their class. The following function and class behave similarly:

>>> 
>>> def square(num):
...     return num ** 2
...
>>> square(4)
16

>>> class Squarer:
...     def __call__(self, num):
...         return num ** 2
...
>>> square = Squarer()
>>> square(4)
16

Here, square is an instance that is callable and can square numbers, just like the square() function in the first example.

This gives you a way of adding decorator capabilities to the existing Timer class:

def __call__(self, func):
    """Support using Timer as a decorator"""
    @functools.wraps(func)
    def wrapper_timer(*args, **kwargs):
        with self:
            return func(*args, **kwargs)

    return wrapper_timer

.__call__() uses the fact that Timer is already a context manager to take advantage of the conveniences you’ve already defined there. Make sure you also import functools at the top of timer.py.

You can now use Timer as a decorator:

>>> 
>>> @Timer(text="Downloaded the tutorial in {:.2f} seconds")
... def latest_tutorial():
...     tutorial = feed.get_article(0)
...     print(tutorial)
...
>>> latest_tutorial()
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of the tutorial ... ]
Downloaded the tutorial in 0.72 seconds

Before rounding out this section, know that there’s a more straightforward way of turning your Python timer into a decorator. You’ve already seen some of the similarities between context managers and decorators. They’re both typically used to do something before and after executing some given code.

Based on these similarities, there’s a mixin class defined in the standard library called ContextDecorator. You can add decorator abilities to your context manager classes simply by inheriting ContextDecorator:

from contextlib import ContextDecorator

class Timer(ContextDecorator):
    # Implementation of Timer is unchanged

When you use ContextDecorator this way, there’s no need to implement .__call__() yourself, so you can safely delete it from the Timer class.

Using the Python Timer Decorator

Let’s redo the latest_tutorial.py example one last time, using the Python timer as a decorator:

 1 # latest_tutorial.py
 2 
 3 from timer import Timer
 4 from reader import feed
 5 
 6 @Timer()
 7 def main():
 8     """Print the latest tutorial from Real Python"""
 9     tutorial = feed.get_article(0)
10     print(tutorial)
11 
12 if __name__ == "__main__":
13     main()

If you compare this implementation with the original implementation without any timing, then you’ll notice that the only differences are the import of Timer on line 3 and the application of @Timer() on line 6. A significant advantage of using decorators is that they’re usually straightforward to apply, as you see here.

However, the decorator still applies to the whole function. This means your code is taking into account the time it takes to print the tutorial, in addition to the time it takes to download. Let’s run the script one final time:

$ python latest_tutorial.py
# Python Timer Functions: Three Ways to Monitor Your Code

[ ... The full text of the tutorial ... ]
Elapsed time: 0.69 seconds

The location of the elapsed time output is a tell-tale sign that your code is considering the time it takes to print time as well. As you see here, your code prints the elapsed time after the tutorial.

When you use Timer as a decorator, you’ll see similar advantages as you did with context managers:

  • Low effort: You only need one extra line of code to time the execution of a function.
  • Readability: When you add the decorator, you can note more clearly that your code will time the function.
  • Consistency: You only need to add the decorator when the function is defined. Your code will consistently time it every time it’s called.

However, decorators are not as flexible as context managers. You can only apply them to complete functions. It’s possible to add decorators to already defined functions, but this is a bit clunky and less common.

The Python Timer Code

You can expand the code block below to view the final source code for your Python timer:

# timer.py

from contextlib import ContextDecorator
from dataclasses import dataclass, field
import time
from typing import Any, Callable, ClassVar, Dict, Optional

class TimerError(Exception):
    """A custom exception used to report errors in use of Timer class"""

@dataclass
class Timer(ContextDecorator):
    """Time your code using a class, context manager, or decorator"""

    timers: ClassVar[Dict[str, float]] = dict()
    name: Optional[str] = None
    text: str = "Elapsed time: {:0.4f} seconds"
    logger: Optional[Callable[[str], None]] = print
    _start_time: Optional[float] = field(default=None, init=False, repr=False)

    def __post_init__(self) -> None:
        """Initialization: add timer to dict of timers"""
        if self.name:
            self.timers.setdefault(self.name, 0)

    def start(self) -> None:
        """Start a new timer"""
        if self._start_time is not None:
            raise TimerError(f"Timer is running. Use .stop() to stop it")

        self._start_time = time.perf_counter()

    def stop(self) -> float:
        """Stop the timer, and report the elapsed time"""
        if self._start_time is None:
            raise TimerError(f"Timer is not running. Use .start() to start it")

        # Calculate elapsed time
        elapsed_time = time.perf_counter() - self._start_time
        self._start_time = None

        # Report elapsed time
        if self.logger:
            self.logger(self.text.format(elapsed_time))
        if self.name:
            self.timers[self.name] += elapsed_time

        return elapsed_time

    def __enter__(self) -> "Timer":
        """Start a new timer as a context manager"""
        self.start()
        return self

    def __exit__(self, *exc_info: Any) -> None:
        """Stop the context manager timer"""
        self.stop()

The code is also available in the codetiming repository on GitHub.

You can use the code yourself by saving it to a file named timer.py and importing it into your program:

>>> 
>>> from timer import Timer

Timer is also available on PyPI, so an even easier option is to install it using pip:

$ python -m pip install codetiming

Note that the package name on PyPI is codetiming. You’ll need to use this name both when you install the package and when you import Timer:

>>> 
>>> from codetiming import Timer

Apart from this, codetiming.Timer works exactly as timer.Timer. To summarize, you can use Timer in three different ways:

  1. As a class:

    t = Timer(name="class")
t.start()
# Do something
t.stop()

  2. As a context manager:

    with Timer(name="context manager"):
    # Do something

  3. As a decorator:

    @Timer(name="decorator")
def stuff():
    # Do something

This kind of Python timer is mainly useful for monitoring the time your code spends at individual key code blocks or functions. In the next section, you’ll get a quick overview of alternatives you can use if you’re looking to optimize your code.

Other Python Timer Functions

There are many options for timing your code with Python. In this tutorial, you’ve learned how to create a flexible and convenient class that you can use in several different ways. A quick search on PyPI shows that there are already many projects available that offer Python timer solutions.

In this section, you’ll first learn more about the different functions available in the standard library for measuring time, and why perf_counter() is preferable. Then, you’ll see alternatives for optimizing your code, for which Timer is not well-suited.

Using Alternative Python Timer Functions

You’ve been using perf_counter() throughout this tutorial to do the actual time measurements, but Python’s time library comes with several other functions that also measure time. Here are some alternatives:

One of the reasons why there are several functions is that Python represents time as a float. Floating-point numbers are inaccurate by nature. You may have seen results like these before:

>>> 
>>> 0.1 + 0.1 + 0.1
0.30000000000000004

>>> 0.1 + 0.1 + 0.1 == 0.3
False

Python’s float follows the IEEE 754 Standard for Floating-Point Arithmetic, which tries to represent all floating-point numbers in 64 bits. Since there are infinitely many floating-point numbers, you can’t express them all with a finite number of bits.

IEEE 754 prescribes a system where the density of numbers that you can represent varies. The closer you are to 1, the more numbers you can represent. For larger numbers, there’s more space between the numbers that you can express. This has some consequences when you use a float to represent time.

Consider time(). The main purpose of this function is to represent the actual time right now. It does this as the number of seconds since a given point in time, called the epoch. The number returned by time() is quite big, which means that there are fewer numbers available, and the resolution suffers. Specifically, time() is not able to measure nanosecond differences:

>>> 
>>> import time
>>> t = time.time()
>>> t
1564342757.0654016

>>> t + 1e-9
1564342757.0654016

>>> t == t + 1e-9
True

A nanosecond is one-billionth of a second. Note that adding a nanosecond to t does not affect the result. perf_counter(), on the other hand, uses some undefined point in time as its epoch, allowing it to work with smaller numbers and therefore obtain a better resolution:

>>> 
>>> import time
>>> p = time.perf_counter()
>>> p
11370.015653846

>>> p + 1e-9
11370.015653847

>>> p == p + 1e-9
False

Here, you see that adding a nanosecond to p actually affects the outcome. For more information about how to work with time(), see A Beginner’s Guide to the Python time Module.

The challenges with representing time as a float are well known, so Python 3.7 introduced a new option. Each time measurement function now has a corresponding _ns function that returns the number of nanoseconds as an int instead of the number of seconds as a float. For instance, time() now has a nanosecond counterpart called time_ns():

>>> 
>>> import time
>>> time.time_ns()
1564342792866601283

Integers are unbounded in Python, so this allows time_ns() to give nanosecond resolution for all eternity. Similarly, perf_counter_ns() is a nanosecond variant of perf_counter():

>>> 
>>> import time
>>> time.perf_counter()
13580.153084446

>>> time.perf_counter_ns()
13580765666638

Since perf_counter() already provides nanosecond resolution, there are fewer advantages to using perf_counter_ns().

There are two functions in time that do not measure the time spent sleeping. These are process_time() and thread_time(), which are useful in some settings. However, for Timer, you typically want to measure the full time spent. The final function in the list above is monotonic(). The name alludes to this function being a monotonic timer, which is a Python timer that can never move backward.

All these functions are monotonic except time(), which can go backward if the system time is adjusted. On some systems, monotonic() is the same function as perf_counter(), and you can use them interchangeably. However, this is not always the case. You can use time.get_clock_info() to get more information about a Python timer function. Using Python 3.7 on Linux I get the following information:

>>> 
>>> import time
>>> time.get_clock_info("monotonic")
namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)',
          monotonic=True, resolution=1e-09)

>>> time.get_clock_info("perf_counter")
namespace(adjustable=False, implementation='clock_gettime(CLOCK_MONOTONIC)',
          monotonic=True, resolution=1e-09)

The results could be different on your system.

PEP 418 describes some of the rationale behind introducing these functions. It includes the following short descriptions:

  • time.monotonic(): timeout and scheduling, not affected by system clock updates
  • time.perf_counter(): benchmarking, most precise clock for short period
  • time.process_time(): profiling, CPU time of the process (Source)

As you can see, it’s usually the best choice for you to use perf_counter() for your Python timer.

Estimating Running Time With timeit

Say you’re trying to squeeze the last bit of performance out of your code, and you’re wondering about the most effective way to convert a list to a set. You want to compare using set() and the set literal, {...}. You can use your Python timer for this:

>>> 
>>> from timer import Timer
>>> numbers = [7, 6, 1, 4, 1, 8, 0, 6]
>>> with Timer(text="{:.8f}"):
...     set(numbers)
...
{0, 1, 4, 6, 7, 8}
0.00007373

>>> with Timer(text="{:.8f}"):
...     {*numbers}
...
{0, 1, 4, 6, 7, 8}
0.00006204

This test seems to indicate that the set literal might be slightly faster. However, these results are quite uncertain, and if you rerun the code, you might get wildly different results. That’s because you’re only trying the code once. You could, for instance, get unlucky and run the script just as your computer is becoming busy with other tasks.

A better way is to use the timeit standard library. It’s designed precisely to measure the execution time of small code snippets. While you can import and call timeit.timeit() from Python as a regular function, it is usually more convenient to use the command-line interface. You can time the two variants as follows:

$ python -m timeit --setup "nums = [7, 6, 1, 4, 1, 8, 0, 6]" "set(nums)"
2000000 loops, best of 5: 163 nsec per loop

$ python -m timeit --setup "nums = [7, 6, 1, 4, 1, 8, 0, 6]" "{*nums}"
2000000 loops, best of 5: 121 nsec per loop

timeit automatically calls your code many times to average out noisy measurements. The results from timeit confirm that the set literal is faster than set(). You can find more information about this particular issue at Michael Bassili’s blog.

Finally, the IPython interactive shell and the Jupyter notebook have extra support for this functionality with the %timeit magic command:

>>> 
In [1]: numbers = [7, 6, 1, 4, 1, 8, 0, 6]

In [2]: %timeit set(numbers)
171 ns ± 0.748 ns per loop (mean ± std. dev. of 7 runs, 10000000 loops each)

In [3]: %timeit {*numbers}
147 ns ± 2.62 ns per loop (mean ± std. dev. of 7 runs, 10000000 loops each)

Again, the measurements indicate that using a set literal is faster. In Jupyter Notebooks you can also use the %%timeit cell-magic to measure the time of running a whole cell.

Finding Bottlenecks in Your Code With Profilers

timeit is excellent for benchmarking a particular snippet of code. However, it would be very cumbersome to use it to check all parts of your program and locate which sections take the most time. Instead, you can use a profiler.

cProfile is a profiler that you can access at any time from the standard library. You can use it in several ways, although it’s usually most straightforward to use it as a command-line tool:

$ python -m cProfile -o latest_tutorial.prof latest_tutorial.py

This command runs latest_tutorial.py with profiling turned on. You save the output from cProfile in latest_tutorial.prof, as specified by the -o option. The output data is in a binary format that needs a dedicated program to make sense of it. Again, Python has an option right in the standard library! Runnin the pstats module on your .prof file opens an interactive profile statistics browser:

$ python -m pstats latest_tutorial.prof
Welcome to the profile statistics browser.
latest_tutorial.prof% help

Documented commands (type help <topic>):
========================================
EOF  add  callees  callers  help  quit  read  reverse  sort  stats  strip

To use pstats you type commands at the prompt. Here you can see the integrated help system. Typically you’ll use the sort and stats commands. To get a cleaner output, strip can be useful:

latest_tutorial.prof% strip
latest_tutorial.prof% sort cumtime
latest_tutorial.prof% stats 10
         1393801 function calls (1389027 primitive calls) in 0.586 seconds

 Ordered by: cumulative time
 List reduced from 1443 to 10 due to restriction <10>

 ncalls tottime percall cumtime percall filename:lineno(function)
  144/1   0.001   0.000   0.586   0.586 {built-in method builtins.exec}
      1   0.000   0.000   0.586   0.586 latest_tutorial.py:3(<module>)
      1   0.000   0.000   0.521   0.521 contextlib.py:71(inner)
      1   0.000   0.000   0.521   0.521 latest_tutorial.py:6(read_latest_tutorial)
      1   0.000   0.000   0.521   0.521 feed.py:28(get_article)
      1   0.000   0.000   0.469   0.469 feed.py:15(_feed)
      1   0.000   0.000   0.469   0.469 feedparser.py:3817(parse)
      1   0.000   0.000   0.271   0.271 expatreader.py:103(parse)
      1   0.000   0.000   0.271   0.271 xmlreader.py:115(parse)
     13   0.000   0.000   0.270   0.021 expatreader.py:206(feed)

This output shows that the total runtime was 0.586 seconds. It also lists the ten functions where your code spent most of its time. Here you’ve sorted by cumulative time (cumtime), which means that your code counts time when the given function has called another function.

You can see that your code spends virtually all its time inside the latest_tutorial module, and in particular, inside read_latest_tutorial(). While this might be useful confirmation of what you already know, it’s often more interesting to find where your code actually spends time.

The total time (tottime) column indicates how much time your code spent inside a function, excluding time in sub-functions. You can see that none of the functions above really spend any time doing this. To find where the code spent most of its time, issue another sort command:

latest_tutorial.prof% sort tottime
latest_tutorial.prof% stats 10
         1393801 function calls (1389027 primitive calls) in 0.586 seconds

 Ordered by: internal time
 List reduced from 1443 to 10 due to restriction <10>

 ncalls tottime percall cumtime percall filename:lineno(function)
     59   0.091   0.002   0.091   0.002 {method 'read' of '_ssl._SSLSocket'}
 114215   0.070   0.000   0.099   0.000 feedparser.py:308(__getitem__)
 113341   0.046   0.000   0.173   0.000 feedparser.py:756(handle_data)
      1   0.033   0.033   0.033   0.033 {method 'do_handshake' of '_ssl._SSLSocket'}
      1   0.029   0.029   0.029   0.029 {method 'connect' of '_socket.socket'}
     13   0.026   0.002   0.270   0.021 {method 'Parse' of 'pyexpat.xmlparser'}
 113806   0.024   0.000   0.123   0.000 feedparser.py:373(get)
   3455   0.023   0.000   0.024   0.000 {method 'sub' of 're.Pattern'}
 113341   0.019   0.000   0.193   0.000 feedparser.py:2033(characters)
    236   0.017   0.000   0.017   0.000 {method 'translate' of 'str'}

You can now see that latest_tutorial.py actually spends most of its time working with sockets or handling data inside feedparser. The latter is one of the dependencies of the Real Python Reader that’s used to parse the tutorial feed.

You can use pstats to get some idea on where your code is spending most of its time and see if you can optimize any bottlenecks you find. You can also use the tool to understand the structure of your code better. For instance, the commands callees and callers will show you which functions call and are called by a given function.

You can also investigate certain functions. Let’s see how much overhead Timer causes by filtering the results with the phrase timer:

latest_tutorial.prof% stats timer
         1393801 function calls (1389027 primitive calls) in 0.586 seconds

 Ordered by: internal time
 List reduced from 1443 to 8 due to restriction <'timer'>

 ncalls tottime percall cumtime percall filename:lineno(function)
      1   0.000   0.000   0.000   0.000 timer.py:13(Timer)
      1   0.000   0.000   0.000   0.000 timer.py:35(stop)
      1   0.000   0.000   0.003   0.003 timer.py:3(<module>)
      1   0.000   0.000   0.000   0.000 timer.py:28(start)
      1   0.000   0.000   0.000   0.000 timer.py:9(TimerError)
      1   0.000   0.000   0.000   0.000 timer.py:23(__post_init__)
      1   0.000   0.000   0.000   0.000 timer.py:57(__exit__)
      1   0.000   0.000   0.000   0.000 timer.py:52(__enter__)

Luckily, Timer causes only minimal overhead. Use quit to leave the pstats browser when you’re done investigating.

For a more powerful interface into profile data, check out KCacheGrind. It uses its own data format, but you can convert data from cProfile using pyprof2calltree:

$ pyprof2calltree -k -i latest_tutorial.prof

This command will convert latest_tutorial.prof and open KCacheGrind to analyze the data.

The last option you’ll see here for timing your code is line_profiler. cProfile can tell you which functions your code spends the most time in, but it won’t give you insights into which lines inside that function are the slowest. That’s where line_profiler can help you.

Note that line profiling takes time and adds a fair bit of overhead to your runtime. A more standard workflow is first to use cProfile to identify which functions to look at and then run line_profiler on those functions. line_profiler is not part of the standard library, so you should first follow the installation instructions to set it up.

Before you run the profiler, you need to tell it which functions to profile. You do this by adding a @profile decorator inside your source code. For example, to profile Timer.stop() you add the following inside timer.py:

@profile
def stop(self) -> float:
    # The rest of the code is unchanged

Note that you don’t import profile anywhere. Instead, it’s automatically added to the global namespace when you run the profiler. You need to delete the line when you’re done profiling, though. Otherwise, you’ll get a NameError.

Next, run the profiler using kernprof, which is part of the line_profiler package:

$ kernprof -l latest_tutorial.py

This command automatically saves the profiler data in a file called latest_tutorial.py.lprof. You can see those results using line_profiler:

$ python -m line_profiler latest_tutorial.py.lprof
Timer unit: 1e-06 s

Total time: 1.6e-05 s
File: /home/realpython/timer.py
Function: stop at line 35

# Hits Time PrHit %Time Line Contents
=====================================
35                      @profile
36                      def stop(self) -> float:
37                          """Stop the timer, and report the elapsed time"""
38  1   1.0   1.0   6.2     if self._start_time is None:
39                              raise TimerError(f"Timer is not running. ...")
40
41                          # Calculate elapsed time
42  1   2.0   2.0  12.5     elapsed_time = time.perf_counter() - self._start_time
43  1   0.0   0.0   0.0     self._start_time = None
44
45                          # Report elapsed time
46  1   0.0   0.0   0.0     if self.logger:
47  1  11.0  11.0  68.8         self.logger(self.text.format(elapsed_time))
48  1   1.0   1.0   6.2     if self.name:
49  1   1.0   1.0   6.2         self.timers[self.name] += elapsed_time
50
51  1   0.0   0.0   0.0     return elapsed_time

First, note that the time unit in this report is microseconds (1e-06 s). Usually, the most accessible number to look at is %Time, which tells you the percentage of the total time your code spends inside a function at each line. In this example, you can see that your code spends almost 70% of the time on line 47, which is the line that formats and prints the result of the timer.

Conclusion

In this tutorial, you’ve seen several different approaches to adding a Python timer to your code:

  • You used a class to keep state and add a user-friendly interface. Classes are very flexible, and using Timer directly gives you full control over how and when to invoke the timer.

  • You used a context manager to add features to a block of code and, if necessary, to clean up afterward. Context managers are straightforward to use, and adding with Timer() can help you more clearly distinguish your code visually.

  • You used a decorator to add behavior to a function. Decorators are concise and compelling, and using @Timer() is a quick way to monitor your code’s runtime.

You’ve also seen why you should prefer time.perf_counter() over time.time() when benchmarking code, as well as what other alternatives are useful when you’re optimizing your code.

Now you can add Python timer functions to your own code! Keeping track of how fast your program runs in your logs will help you monitor your scripts. Do you have ideas for other use cases where classes, context managers, and decorators play well together? Leave a comment down below!

Resources

For a deeper dive into Python timer functions, check out these resources:

  • codetiming is the Python timer available on PyPI.
  • time.perf_counter() is a performance counter for precise timings.
  • timeit is a tool for comparing the runtimes of code snippets.
  • cProfile is a profiler for finding bottlenecks in scripts and programs.
  • pstats is a command-line tool for looking at profiler data.
  • KCachegrind is a GUI for looking at profiler data.
  • line_profiler is a profiler for measuring individual lines of code.
  • memory-profiler is a profiler for monitoring memory usage.

[ Improve Your Python With 🐍 Python Tricks 💌 – Get a short & sweet Python Trick delivered to your inbox every couple of days. >> Click here to learn more and see examples ]



from Real Python
read more
at
Labels: ,

No comments:

Post a Comment

Subscribe to: Post Comments (Atom)

TestDriven.io: Working with Static and Media Files in Django

This article looks at how to work with static and media files in a Django project, locally and in production. from Planet Python via read...