Utilisation de Stopwatch et WebProfiler dans Symfony

Préambule

« Pourrais-tu jeter un œil à cette page sur ce projet ? Les utilisateurs se plaignent de la lenteur. »

Je ne connais pas très bien le projet. Je sais quel est l'objectif dans les grandes lignes, mais je ne maîtrise pas du tout la base de code.
Mais je sais comment m'y prendre techniquement pour aider l'équipe qui le connait bien à savoir vers quelle partie s'orienter.

Pour information, je n'ai pas extrait le code source pour ce billet de blog (question de licence), à la place, j'ai ré-écrit une version simplifiée.

Disclaimer

A priori, si vous avez une licence Blackfire, vous pouvez ne pas lire cet article.
Je connais et apprécie beaucoup cet outil, mais malheureusement, c'est un outil qui a un certain coût, il n'est donc pas disponible quand je fais mon investigation.

Reproduire le problème

Je commence par reproduire les enchaînements d'actions qui mènent à la fameuse page un peu lente, et je constate le problème d'entrée de jeu, en ouvrant le profiler :

Soyons clair, je ne cherche pas une solution au problème pour le moment, mais à analyser les raisons des lenteurs.
Mon objectif est donc de mettre le doigt, le plus précisément possible, sur ce qui prend du temps.

On peut dores et déjà regarder plus en détail l'onglet performance du profiler :

Qu'est-ce-qu'on voit ?
A priori, on passe la totalité du temps dans notre controller, beaucoup de temps à interroger Doctrine, et encore un peu de temps à interroger Elasticsearch.
Cela semble légitime, après tout, ce controller publie un grand nombre de documents depuis une base de données SQL vers un index Elasticsearch.

Premier contact avec le code

Mais ça ne m'aide pas à savoir "qu'est-ce-qui prend vraiment du temps ?".
Pour rentrer plus en détail, pas le choix, il faut que je regarde le code.

Je rentre un peu dedans, et je trouve une classe qui ressemble à ça :

<?php

declare(strict_types=1);

namespace App\Synchronize;

use App\Storage\Database;
use App\Storage\Elastic;

final class ElasticSynchronizer
{
    public function __construct(
        private readonly Database $database,
        private readonly Elastic $elastic,
        private readonly Elastic\PayloadBuilder $payloadBuilder,
    ) {
    }

    public function synchronize(string $entityClass): void
    {
        $entities = $this->database->entities($entityClass);

        foreach ($entities as $entity) {
            $entityId = (string)$this->database->id($entity);
            $entityPayload = $this->payloadBuilder->build($entity);

            $this->elastic->add($entityClass, $entityId, $entityPayload);
        }

        $this->elastic->commit();
    }
}

Là encore, je comprends ce que je lis, on fait une liste d'entités, on normalise chacune de ces entités en un tableau de données structuré.
On ajoute chacun de ces documents à Elasticsearch, et enfin, on commit les changements.

Procéder par dichotomie

Il se passe beaucoup de choses dans cette simple classe, et comme souvent, tout n'est pas également intéressant dans notre recherche.
Pour descendre le plus rapidement possible vers les parties les plus lentes, j'aime bien travailler par dichotomie.
L'idée étant de découper le code en blocs, qui me semblent utiles, les nommer, et analyser le temps passé dans chacun d'entre eux.
On pourra affiner au besoin, donc il n'y a aucun mal à découper gros au début, bien au contraire.

Le composant Stopwatch

Et pour ça, j'utilise le composant Stopwatch.
C'est un composant qui existe depuis la version 2.2 de Symfony, et qui est très simple à utiliser.
En revanche, il faut vous retenir de l'instancier vous-même comme le suggère le README du repository.
Ça marcherait très bien, mais vous ne profiterez pas de l'intégration avec le WebProfilerBundle.
Au lieu de ça, je vous encourage à injecter le service associé dans vos services à vous.

Première itération

Généralement, pour la première itération, j'essaie de rester simple, et je découpe autour des appels de fonctions :

+use Symfony\Component\Stopwatch\Stopwatch;

final class ElasticSynchronizer
{
    public function __construct(
+        private readonly Stopwatch $stopwatch,
    ) {
    }

    public function synchronize(string $entityClass): void
    {
+        $this->stopwatch->start(__FUNCTION__ . '$entities');
        $entities = $this->database->entities($entityClass);
+        $this->stopwatch->stop(__FUNCTION__ . '$entities');

        foreach ($entities as $entity) {
            $entityId = (string)$this->database->id($entity);
+            $this->stopwatch->start(__FUNCTION__ . '$entityPayload');
            $entityPayload = $this->payloadBuilder->build($entity);
+            $this->stopwatch->stop(__FUNCTION__ . '$entityPayload');

+            $this->stopwatch->start(__FUNCTION__ . 'elastic->add');
            $this->elastic->add($entityClass, $entityId, $entityPayload);
+            $this->stopwatch->stop(__FUNCTION__ . 'elastic->add');
        }

+        $this->stopwatch->start(__FUNCTION__ . 'elastic->commit');
        $this->elastic->commit();
+        $this->stopwatch->stop(__FUNCTION__ . 'elastic->commit');
    }
}

Rendez-vous dans l'onglet performance du WebProfiler pour voir les changements :

Ici, on remarque en un coup d'œil où on passe le plus clair de notre temps : dans la fabrication du payload.

Deuxième itération

Souvent, vous ne serez pas satisfait du premier coup, notamment dans les algorithmes itératifs.
Car ce découpage technique ne tient pas compte de quelque chose d'important : le temps passé dépend souvent de la quantité de données.
Et dans ce genre d'algorithme, comme chaque tour de boucle traite un objet différent, il se peut que certains objets soient plus lourds que d'autres.
Mais là encore, le composant va vous aider, puisqu'il suffit de jouer sur le nom du timer pour changer ce qu'on veut mesurer.

+use Symfony\Component\Stopwatch\Stopwatch;

final class ElasticSynchronizer
{
    public function __construct(
+        private readonly Stopwatch $stopwatch,
    ) {
    }

    public function synchronize(string $entityClass): void
    {
        $entities = $this->database->entities($entityClass);

        foreach ($entities as $entity) {
            $entityId = (string)$this->database->id($entity);
+            $this->stopwatch->start(__FUNCTION__ . '.entity#' . $entityId);
            $entityPayload = $this->payloadBuilder->build($entity);
+            $this->stopwatch->stop(__FUNCTION__ . '.entity#' . $entityId);

            $this->elastic->add($entityClass, $entityId, $entityPayload);
        }

        $this->elastic->commit();
    }
}

Là encore, l'onglet performance du WebProfiler nous affiche tout ce dont on a besoin :

Diagnostic

La première itération montre que, techniquement, ce qui prend du temps, c'est la construction du payload que l'on envoie à ElasticSearch.
En revanche, cette information est à affiner d'un point de vue métier, car la deuxième itération a montré que cela prend plus de temps pour certains objets que d'autres.
Ce n'est donc pas un problème généralisé, mais qui est particulier aux données (objets plus volumineux, avec plus de relations, etc...)

Conclusion

Le composant Stopwatch m'a toujours plu, c'est notamment dû à sa simplicité et sa puissance.
Pourquoi est-ce-que je voudrais encore faire du debug à base de microtime(true) et var_dump ?
Depuis qu'il est intégré au WebProfiler, c'est encore mieux, on peut se contenter de mettre nos traceurs, et la visualisation de l'analyse se fait seule (et sans perturber l'output de notre page).
Enfin, maintenant que l'on sait que le WebProfiler sera disponible aussi pour les appels de commandes, cette technique sera utilisable dans tous les contextes !

Il y a encore quelques subtilités d'usage qui sont exposées dans la documentation officielle, dont vous voudriez peut-être profiter, alors n'hésitez pas à y faire un tour.

Et un petit tip pour la route, si vous êtes sous PhpStorm, vous pouvez utiliser ce live template pour vous faciliter le travail :

$this->stopwatch->start(__FUNCTION__ . '$NAME$');
$this->stopwatch->stop(__FUNCTION__ . '$NAME$');