Aller au contenu

Pourquoi la règle `W1203` est importante

cover

Si vous avez utilisé l'outil pylint pour vérifier le format de votre code Python, vous avez peut-être rencontré la règle W1203 : logging-fstring-interpolation mais vous n'avez pas vraiment compris pourquoi c'est important.

L'avertissement ressemble à :

path/to/my/file.py:37:4: W1203: Use lazy % formatting in logging functions (logging-fstring-interpolation)

Il se trouve lorsque vous utilisez la bibliothèque Python logging. La documentation pylint sur cette règle dit que vous ne devez pas utiliser de chaînes formatées de type f-string.

L'exemple donné est :

Code problématique :

import logging
import sys

logging.error(f'Python version: {sys.version}')  # [logging-fstring-interpolation]

Code correct :

import logging
import sys

logging.error('Python version: %s', sys.version)

Mais pourquoi utiliser la chaîne f-string dans le contexte de journalisation est une mauvaise idée et peut avoir un impact énorme sur les performances de votre application ??

La bibliothèque de journalisation

La bibliothèque Python logging est la bibliothèque standard pour implémenter la journalisation dans une application ou un script. Il remplace l'instruction print traditionnelle. Il permet d'avoir un format de sortie de journal unifié et de sélectionner le niveau de verbosité à la volée.

En utilisant la bibliothèque logging vous pouvez affichez les journaux (sur la stdout ou dans un fichier) avec plusieurs niveaux comme : info, warning, error, debug, en savoir plus. Vous pouvez ensuite définir le niveau de verbosité des logs parmi l'un d'entre eux.

Par exemple, si vous avez décidé de ne vouloir que des logs utiles lors de l'exécution en production, vous définirez le niveau de log sur error. Seul les logs avec le niveau error ou critical seront affichées. Mais si vous êtes dans un environnement de développement, vous souhaiterez peut-être être au niveau de log debug pour afficher tous les logs possibles.

Quel est le problème alors ?

Exemple complet

Dans un environnement de production, si vous avez des logs de type debug qui appellent d'autres fonctions, ceux-ci seront interpolés même si elles ne seront jamais affichées.

Par exemple vous avez un code simple :

import logging
import sys
from datetime import datetime

logger = logging.getLogger()
handler = logging.StreamHandler(sys.stdout)
logger.addHandler(handler)

# In production
logger.setLevel("INFO")
# In development
# logger.setLevel("DEBUG")

def handle_incoming_message(message):
  logger.debug(f"[{datetime.now()}] New message received : '{message}'")
  return len(message)

if __name__ == "__main__":
  total = 0
  for i in range(10000000):
    total += handle_incoming_message("my custom message")

  logger.info(f"The total is : {total}")

Vous appelez une fonction handle_incoming_message sur chaque message entrant reçu par votre application. Vous comptez le nombre de lettres dans le message et le renvoyez. Enfin, vous comptez le nombre total de lettres dans tous les messages.

Dans l'environnement de développement, vous souhaitez avoir une log de debug à chaque fois que vous recevez un message (à des fins de débogage). Mais vous ne vous souciez pas de ces logs lors de l'exécution en production.

L'exécution de ce code en développement a pris 116,40s avec 10000001 ligne de logs affichées

L'exécution de ce code en production a pris 16,99s avec uniquement une ligne de log (la dernière)

Peut-on optimiser la durée du script en production ?

Le changement de la ligne :

logger.debug(f"[{datetime.now()}] New message received : '{message}'")

Par :

logger.debug("[%s] New message received : '%s'", datetime.now(), message)

Devrait produire exactement le même résultat mais en moins de temps.

L'exécution de ce code en développement a pris 112,81s avec 10000001 ligne de logs affichées

L'exécution de ce code en production a pris 8,54s avec uniquement une ligne de log (la dernière)

Comment avons-nous gagné du temps ?

Comment le simple fait de changer le format de la chaîne de log peut-il nous permettre d'exécuter le même script en deux fois moins de temps ?

Dans la première solution :

logger.debug(f"[{datetime.now()}] New message received : '{message}'")

Python appellera d'abord la fonction de format de chaîne pour faire le rendu de la chaîne, puis appellera le logger.debug

Dans le deuxième exemple :

logger.debug("[%s] New message received : '%s'", datetime.now(), message)

Nous appelons directement le logger.debug avec plusieurs arguments. Dans l'algorithme de la fonction de logging, la fonction de format de chaîne sera appelée avec tous les arguments passés à la fonction uniquement si la log doit être affichée à l'utilisateur (selon le niveau de log).

En choisissant le deuxième code plutôt que l'autre, nous économisons un appel de fonction et ainsi du temps. Dans l'exemple, l'appel qui prend du temps est datetime.now() mais vous devez imaginer que cet appel pourrait être un autre appel plus lent dans votre application !

Conclusion

En utilisant les capacités de formatage de chaîne intégré bibliothèque Python logging, vous pouvez gagner beaucoup de temps et rendre votre application ou votre script plus rapide et réactif.

Merci pylint pour l'avertissement.