Mesurer le temps d’exécution de code en python

Aujourd’hui, on chronomètre. J’imagine que, comme pour moi, c’est un besoin pour beaucoup que de savoir combien de temps tel ou tel bout de code prend à se dérouler. Je vous propose de voir comment j’ai fait.

La méthode naïve

À l’origine des temps, il y avait… time, évidemment. Imaginons un appel serveur et un traitement sur les données reçues qu’on aimerait chronométrer, par exemple. Le plus instinctif serait de faire comme suit:

import time

start_time = time.time()
content = call_server(argument)
result = process_data(content)
interval = time.time() - start_time
print 'Total time in seconds:', interval

Mais procéder comme ci-dessus signifie qu’il faut copier-coller le même code à tous les endroits où je souhaite faire des mesures. Si on factorisait tout ça?

Moins de code = joli code

Écrivons donc une classe qui va masquer les appels à time.time() et la soustraction.

import time
class Timer(object):
    def start(self):
        if hasattr(self, 'interval'):
            del self.interval
        self.start_time = time.time()

    def stop(self):
        if hasattr(self, 'start_time'):
            self.interval = time.time() - self.start_time
            del self.start_time # Force timer reinit

timer = Timer()
timer.start()
content = call_server(argument)
result = process_data(content)
timer.stop()
print 'Total time in seconds for first call:', timer.interval

timer.start()
content = call_server(argument_2)
result = process_data(content)
timer.stop()
print 'Total time in seconds for second call:', timer.interval

Il y a déjà un mieux! Je suis déjà sûr de ne pas me tromper entre mes copier-coller sur la façon de commencer et arrêter mes mesures. Mais encore une fois, comme je n’aime pas me répéter, je suis gêné de devoir appeler « à la main » les fonctions start() et stop().

Est-ce qu’il n’y aurait pas un moyen pour que ces appels soient faits automatiquement pour moi? Justement, il existe un design pattern en python appelé « context manager« .

Un contexte est une sorte d’isolation au runtime d’un morceau de code, utilisant le mot-clé with. Le context manager exécute automatiquement des instructions en entrée et sortie du contexte. C’est exactement ce que je cherche!

Une classe peut servir de context manager si elle implémente __enter__ et __exit__.

Ma classe devient donc la suivante:

class Timer(object):
    def __enter__(self):
        self.start()
        # __enter__ must return an instance bound with the "as" keyword
        return self
    
    # There are other arguments to __exit__ but we don't care here
    def __exit__(self, *args, **kwargs): 
        self.stop()
    
    def start(self):
        if hasattr(self, 'interval'):
            del self.interval
        self.start_time = time.time()

    def stop(self):
        if hasattr(self, 'start_time'):
            self.interval = time.time() - self.start_time
            del self.start_time # Force timer reinit

with Timer() as timer:
    content = call_server()
    result = process_data(content)
print 'Total time in seconds for first call:', timer.interval

De mieux en mieux!

Maintenant, j’aimerais aussi me passer d’écrire le print final! Je pourrais très bien ajouter un print dans la fonction stop, ou encore dans la fonction __exit__. Mais j’ai envie d’être plus malin, pour prévoir d’envoyer ma donnée vers une fonction de « log » quelconque.

Je vais donc construire une classe dérivée qui prendra en paramètre une fonction ainsi qu’un message afin de mieux qualifier ce que je vais écrire. Pour rendre ça plus facile au quotidien, je prévois aussi une valeur par défaut pour la fonction à appeler.

class LoggerTimer(Timer):
    @staticmethod
    def default_logger(msg):
        print msg

    def __init__(self, prefix='', func=None):
        # Use func if not None else the default one
        self.f = func or LoggerTimer.default_logger
        # Format the prefix if not None or empty, else use empty string
        self.prefix = '{0}:'.format(prefix) if prefix else ''

    def stop(self):
        # Call the parent method
        super(LoggerTimer, self).stop()
        # Call the logging function with the message
        self.f('{0}{1}'.format(self.prefix, self.interval))

Ainsi, je peux utiliser mon nouveau timer comme suit:

# With default print function
with LoggerTimer('Server call and processing'):
    content = call_server()
    result = process_data(content)

# With custom logging function
import logging
logger = logging.getLogger('loggertimer.test')
with LoggerTimer('Server call and processing', logger.debug):
    content = call_server()
    result = process_data(content)

Une corde de plus à cet arc?

Il me vient soudain une idée saugrenue. Et si je souhaitais chronométrer une certaine fonction à chaque appel, sans avoir besoin d’insérer le code de LoggerTimer dans le corps de la fonction?

J’aimerais pouvoir utiliser un décorateur pour avoir ça:

@LoggerTimer('The function', logger.debug)
def the_function(argument):
    content = server_call(argument)
    return process_data(content)

Je ne reviens pas en détail sur le principe de décorateur. Je rappellerai simplement qu’un décorateur est une fonction qui prend pour paramètre la fonction à décorer, et qui renvoie cette même fonction ou une version modifiée (dite décorée).

Mais mon instance de LoggerTimer est un objet, et pas une fonction! Pour simuler la capacité d’être « appelé », je lui implémente la méthode __call__

Ma classe devient donc:

class LoggerTimer(Timer):
    @staticmethod
    def default_logger(msg):
        print msg

    def __init__(self, prefix='', func=None)
        # Use func if not None else the default one
        self.f = func or LoggerTimer.default_logger
        # Format the prefix if not None or empty, else use empty string
        self.prefix = '{0}:'.format(prefix) if prefix else ''

    def stop(self):
        # Call the parent method
        super(LoggerTimer, self).stop()
        # Call the logging function with the message
        self.f('{0}{1}'.format(self.prefix, self.interval))

    def __call__(self, func):
        # Use self as context manager in a decorated function
        def decorated_func(*args, **kwargs):
            with self: return func(*args, **kwargs)
        return decorated_func

Et voilà une belle classe utilitaire qui peut servir dans de nombreux cas. Si vous avez d’autres idées de ce qu’on pourrait tirer de ce principe, avec d’autres dérivations possibles, n’hésitez pas à les soumettre ci-dessous!