Je me préparais à pousser quelques changements il y a quelques jours et comme je le fais habituellement, j'ai fait les tests. Je me suis assis dans ma chaise pendant que les points couraient sur l'écran quand soudain j'ai remarqué que l'un des points s'attardait. "Le système d'exploitation exécute probablement des mises à jour en arrière-plan ou quelque chose comme ça", me suis-je dit, et j'ai refait les tests juste pour être sûr. J'ai regardé attentivement les points remplir l'écran et c'était à nouveau - J'ai un test lent !
Nous allons traquer les tests lents en signalant les tests qui prennent plus de temps qu'un certain seuil.
Les bases
Pour commencer, créons un cas de test simple avec un test rapide et un test lent :
import time import unittest class SlowTestCase(unittest.TestCase): def test_should_run_fast(self): self.assertEqual(1, 1) def test_should_run_slow(self): time.sleep(0.5) self.assertEqual(1, 1)
L'exécution de ce script à partir de la ligne de commande produit le résultat suivant :
$ python -m unittest timing.py .. Ran 2 tests in 0.502s OK
Je suis désolé unittest, mais ce n'est définitivement pas OK - 0.5s pour deux tests ?
Pour déterminer quels tests sont lents, nous devons mesurer le temps d'exécution de chaque test .
Un python unittest.TestCase a des hooks qui s'exécutent dans l'ordre suivant :
> setUpClass > setUp > test_* > tearDown > tearDownClass
Si on veut chronométrer un seul test (test_* ) nous devons démarrer une minuterie en setUp et arrêtez-le dans tearDown :
import time
import unittest
class SlowTestCase(unittest.TestCase):
def setUp(self):
self._started_at = time.time()
def tearDown(self):
elapsed = time.time() - self._started_at
print('{} ({}s)'.format(self.id(), round(elapsed, 2)))
def test_should_run_fast(self):
self.assertEqual(1, 1)
def test_should_run_slow(self):
time.sleep(0.5)
self.assertEqual(1, 1)
Cela produit la sortie suivante :
$ python -m unittest timing.py __main__.SlowTestCase.test_should_run_fast (0.0s) .__main__.SlowTestCase.test_should_run_slow (0.5s) . Ran 2 tests in 0.503s OK
Super! Nous avons le timing pour chaque test mais nous ne voulons vraiment que les plus lents .
Disons qu'un test lent est un test qui prend plus de 0,3 s :
SLOW_TEST_THRESHOLD = 0.3
class SlowTestCase(unittest.TestCase):
# ...
def tearDown(self):
elapsed = time.time() - self._started_at
if elapsed > SLOW_TEST_THRESHOLD:
print('{} ({}s)'.format(self.id(), round(elapsed, 2)))
Et le résultat :
> python -m unittest timing.py .__main__.SlowTestCase.test_should_run_slow (0.5s) . Ran 2 tests in 0.503s OK
Impressionnant! Nous avons obtenu exactement ce que nous voulions mais c'est encore incomplet. Nous sommes de bons développeurs, nous sommes donc probablement paresseux. Nous ne voulons pas faire le tour et mettre à jour chaque cas de test - nous avons besoin d'une solution plus robuste .
Le Coureur
Un des rôles du TestRunner consiste à imprimer les résultats des tests dans un flux de sortie. Le coureur utilise un TestResult objet pour formater les résultats. Le module unittest est livré avec un TextTestRunner par défaut et TextTestResult .
Implémentons un TestResult personnalisé pour signaler des tests lents :
import time
from unittest.runner import TextTestResult
SLOW_TEST_THRESHOLD = 0.3
class TimeLoggingTestResult(TextTestResult):
def startTest(self, test):
self._started_at = time.time()
super().startTest(test)
def addSuccess(self, test):
elapsed = time.time() - self._started_at
if elapsed > SLOW_TEST_THRESHOLD:
name = self.getDescription(test)
self.stream.write("\n{} ({:.03}s)\n".format(name, elapsed))
super().addSuccess(test)
Presque identique à ce que nous avons déjà mais en utilisant différents crochets . Au lieu de setUp, nous utilisons testStart et au lieu de tearDown, nous utilisons addSuccess .
Le TextTestRunner intégré utilise TextTestResult . Pour utiliser un TestResult différent nous créons une instance de TextTestRunner avec notre coureur :
from unittest import TextTestRunner if __name__ == '__main__': test_runner = TextTestRunner(resultclass=TimeLoggingTestResult) unittest.main(testRunner=test_runner)
Et le résultat :
$ python runner.py . test_should_run_slow (__main__.SlowTestCase) (0.501s) . Ran 2 tests in 0.501s OK
Nous obtenons un bon rapport sans avoir à apporter de modifications aux cas de test existants.
Pouvons-nous faire mieux ?
En ce moment, nous avons un tas de messages éparpillés à des endroits aléatoires sur l'écran. Et si nous pouvions obtenir un bon rapport avec tous les tests lents ? Eh bien, nous le pouvons !
Commençons par faire en sorte que notre TestResult stocke les horaires sans les signaler :
import time from unittest.runner import TextTestResult class TimeLoggingTestResult(TextTestResult): def __init__(self, *args, **kwargs): super().__init__(*args, **kwargs) self.test_timings = [] def startTest(self, test): self._test_started_at = time.time() super().startTest(test) def addSuccess(self, test): elapsed = time.time() - self._test_started_at name = self.getDescription(test) self.test_timings.append((name, elapsed)) super().addSuccess(test) def getTestTimings(self): return self.test_timings
Le résultat du test contient maintenant une liste de tuples contenant le nom du test et le temps écoulé. Passer à notre TestRunner personnalisé :
# common/test/runner.py
import unittest
class TimeLoggingTestRunner(unittest.TextTestRunner):
def __init__(self, slow_test_threshold=0.3, *args, **kwargs):
self.slow_test_threshold = slow_test_threshold
return super().__init__(resultclass=TimeLoggingTestResult, *args, **kwargs)
def run(self, test):
result = super().run(test)
self.stream.writeln("\nSlow Tests (>{:.03}s):".format(self.slow_test_threshold))
for name, elapsed in result.getTestTimings():
if elapsed > self.slow_test_threshold:
self.stream.writeln("({:.03}s) {}".format(elapsed, name))
return result
Décomposons-le :
- Nous avons remplacé
SLOW_TEST_THRESHOLDavec un paramètre à l'init - Beaucoup plus propre. - Nous avons défini la classe TestResult appropriée.
- Nous avons remplacé l'exécution et ajouté notre rapport personnalisé de "test lent".
Voici à quoi ressemble la sortie (j'ai ajouté quelques tests lents pour illustrer) :
> python timing.py ..... Ran 5 tests in 1.706s OK Slow Tests (>0.3s): (0.501s) test_should_run_slow (__main__.SlowTestCase) (0.802s) test_should_run_very_slow (__main__.SlowTestCase) (0.301s) test_should_run_slow_enough (__main__.SlowTestCase)
Maintenant que nous avons les données temporelles, nous pouvons les utiliser pour générer des rapports intéressants. Nous pouvons trier par temps écoulé, montrer la réduction de temps potentielle et mettre en évidence les tests lents.
Comment l'utiliser avec Django
Django a son propre lanceur de tests, nous devons donc faire quelques ajustements :
# common/test/runner.py from django.test.runner import DiscoverRunner # ... class TimeLoggingTestRunner(DiscoverRunner): def get_resultclass(self): return TimeLoggingTestResult
Et pour que Django utilise notre runner personnalisé, nous définissons ce qui suit :
# settings.py TEST_RUNNER = 'common.tests.runner.TimeLoggingTestRunner'
Allez faire des tests plus vite !
