Doctrine sous EXPLAIN : profiler ce blog jusqu'à l'index.

Toute la partie données du site est gérée par Symfony, Doctrine et PostgreSQL 16. Sa volumétrie ferait sourire un Database Analyst : 80 billets, 16 catégories, 128 kB pour la table la plus lourde. On va pourtant le profiler pour de vrai. D'abord poser l'outil : c'est quoi EXPLAIN, comment se lit un plan. Puis compter les requêtes au profiler Symfony, corriger ce qui dépasse, et finir en demandant à la prod, via pg_stat_user_indexes, quels index servent réellement. Au programme : un N+1 que le cache de second niveau masquait, un autre que personne ne cherchait au bon endroit, et un état des lieux honnête : sur les 47 index de cette base, 14 ont déjà servi.

C'est quoi, EXPLAIN

EXPLAIN, c'est la commande PostgreSQL qui montre le plan d'exécution d'une requête : la stratégie que le planificateur choisit pour aller chercher les lignes (parcours complet de la table, passage par un index, type de jointure), avec ses estimations de coût. Seul, EXPLAIN planifie sans exécuter. EXPLAIN (ANALYZE, BUFFERS) exécute réellement la requête et ajoute les temps mesurés, les lignes réelles et les pages lues. C'est la variante utilisée dans tout ce billet, avec une précaution : sur un UPDATE ou un DELETE, ANALYZE écrit pour de vrai, donc on l'emballe dans un BEGIN; ... ROLLBACK;.

Doctrine ne change rien à l'affaire. Le QueryBuilder produit du SQL, et c'est ce SQL qu'on passe sous EXPLAIN : le panel Doctrine du profiler Symfony l'affiche prêt à copier, paramètres inlinés, avec même un bouton « Explain » intégré.

Premier plan, sur la requête qui résout un billet par son slug :

Index Scan using uniq_post_slug on post p0_  (actual time=0.012 rows=1)
  Index Cond: (slug = 'core-web-vitals-mecanique-pieges')
  Filter: (status = 'online')

Deux lignes concentrent 80 % de la lecture d'un plan. Index Cond, c'est ce que l'index résout : le slug. Filter, c'est ce que PostgreSQL vérifie ligne par ligne après coup : le statut. Un Filter qui rejette l'essentiel des lignes ramenées signale un index qui ne porte pas la bonne colonne. Ici tout va bien : une ligne demandée, une ligne servie.

La surprise est ailleurs. Sur la même requête, la catégorie jointe au billet arrive par un Seq Scan de la table category, hashée en entier. Seize lignes, deux pages de 8 kB : parcourir toute la table coûte moins cher que l'aller-retour par l'index. Forcez SET enable_seqscan = off; et PostgreSQL bascule sur l'index de la clé primaire. C'est la logique de tout ce billet : un index n'est pas utilisé parce qu'il existe, il est utilisé quand le planner estime qu'il coûte moins cher que de lire la table.

Le plan du flux RSS du blog ajoute un étage :

Limit
  -> Nested Loop Left Join
       -> Index Scan Backward using idx_post_status_created on post p0_
            Index Cond: (status = 'online')
       -> Memoize  (Hits: 9  Misses: 11)
            -> Index Scan using category_pkey on category c1_

L'index composite idx_post_status_created sert le WHERE et l'ORDER BY d'un même geste, parcouru à l'envers (Backward) pour le tri décroissant. Et PostgreSQL intercale un nœud Memoize (apparu en version 14) : sur les 20 billets du flux, 11 catégories réellement lues, 9 servies par le cache du nœud. Le moteur déduplique de lui-même ce que l'ORM lui envoie en rafale.

Voilà pour la lecture. Reste à choisir les requêtes qui méritent la loupe.

Compter avant d'expliquer

EXPLAIN lit une requête à la fois ; encore faut-il savoir lesquelles regarder. Pour ça, on compte, et le panel Doctrine du profiler Symfony suffit : requêtes exécutées, requêtes distinctes, temps SQL. Le tour des pages du blog, mesuré sur les données de prod du jour :

Deux lignes détonnent : 33 requêtes pour 8 formes distinctes sur la home, 34 pour 7 sur la liste des billets. Quand les exécutions décollent des formes distinctes, une boucle exécute la même requête en série. Et le panel donne la forme répétée :

SELECT COUNT(*) FROM post t0 WHERE t0.category_id = ?;
-- exécutée 26 fois sur la home, 28 fois sur /billets

Le coupable est élégant, c'est pour ça qu'il est passé inaperçu :

#[ORM\OneToMany(targetEntity: Post::class, mappedBy: 'category', fetch: 'EXTRA_LAZY')]
public Collection $posts;

public int $postsCount {
    get => $this->posts->count();
}

Une collection EXTRA_LAZY promet un comptage sans hydratation : count() émet un SELECT COUNT(*) au lieu de charger tous les billets. Promesse tenue, requête par requête. Ce que la doc ne précise pas : le résultat n'est pas mémoïsé, chaque lecture du hook repart en base. Le nuage de catégories lisait postsCount deux fois par catégorie (une pour calibrer la taille des tags, une pour l'afficher), les chips de filtre une fois chacune. Additionnez les composants d'une page : 26 à 28 COUNT par affichage.

Autre effet : ce comptage ignore le statut de publication, les compteurs publics incluaient donc les brouillons. La catégorie Symfony annonçait 21 billets, elle en a 16 en ligne.

L'ironie, c'est que les contrôleurs calculaient déjà les comptes justes : une seule requête GROUP BY, hydratée dans une propriété mémoïsée publishedPostsCount... que les templates ne lisaient pas. Le correctif tient en deux lignes de Twig. Résultat mesuré : /billets passe de 34 requêtes à 6, la home de 33 à 8.

Le N+1 que le cache absorbait

Le second N+1 est plus intéressant, parce qu'il illustre un piège de mesure. Le bloc « À lire » de la home charge dix billets par id, sans joindre leur catégorie ; le template lit ensuite post.category.title en boucle. Un lazy-load par catégorie distincte : le N+1 du manuel.

Le profiler ne le montrait pourtant pas. Post et Category portent un cache de second niveau Doctrine (région Redis, NONSTRICT_READ_WRITE). À cache chaud, les catégories sortent de Redis : zéro SQL, panel propre. Videz Redis et rechargez la home : 41 requêtes au lieu de 33, 22,1 ms de SQL au lieu de 11. Le delta de 8 requêtes correspond, au compteur près, aux Cache misses du même panel.

En dev, ce cache est chaud en permanence, donc le N+1 y est invisible. En prod, il se vide à chaque déploiement et à chaque éviction Redis, et le N+1 revient facturer ses requêtes à ce moment-là. Le correctif est le plus vieux du monde, une jointure (leftJoin + addSelect) dans la méthode de chargement. La home à cache froid passe de 41 à 10 requêtes.

La leçon vaut plus que le correctif : profiler une page à cache chaud, c'est profiler le cache. Le chiffre honnête se prend à froid.

pg_stat contre EXPLAIN : les deux ont raison

Jusqu'ici, théorie et pratique s'alignent. Voici l'endroit où elles divergent. En prod, pg_stat_user_indexes cumule l'usage réel de chaque index depuis la création de la base. Le champion toutes catégories est idx_post_category_status : 946 554 lectures, sur une table de 79 lignes.

Sauf qu'en local, sur les mêmes données, EXPLAIN ANALYZE de la requête correspondante (compter les billets en ligne d'une catégorie) choisit un Seq Scan. L'index que la prod lit 946 554 fois, le planner refuse de le toucher quand on lui demande son avis.

Les deux ont raison, et la clé est dans PREPARE. En ad hoc, PostgreSQL construit un plan sur mesure : il voit les valeurs, estime que la catégorie contient 16 lignes sur 79, et conclut que lire la table coûte moins cher. Via un prepared statement (ce que PDO fait sous Doctrine), le jeu change à la sixième exécution : le planner bascule sur un plan générique, calculé sans connaître les valeurs. Sélectivité par défaut, estimation 3 lignes, et l'index devient attractif :

-- 6e EXECUTE d'un prepared statement :
Aggregate
  -> Bitmap Heap Scan on post  (rows estimées=3, rows réelles=16)
       -> Bitmap Index Scan on idx_post_category_status

Reproductible en une minute : PREPARE, cinq EXECUTE, puis EXPLAIN sur le sixième. Ou d'un coup : SET plan_cache_mode = force_generic_plan;. D'où la phrase à retenir : pg_stat jure que l'index a servi 946 554 fois, EXPLAIN refuse de l'utiliser, et les deux ont raison. Ils ne regardent pas le même plan.

47 index, 14 utilisés

Le même pg_stat_user_indexes, lu en entier, donne l'état des lieux complet. Cette base déclare 47 index ; 14 ont un idx_scan supérieur à zéro. Sur la table post, la plus sollicitée, 8 des 10 index posés à la main travaillent. Les deux autres dorment depuis leur création :

Le doublon slug se retrouve à l'identique sur les tables category et page : un index nommé posé à côté d'une contrainte unique sur la même colonne. L'un des deux ne servira jamais.

Le reste de la base est plus radical. Sur page, redirect_rule, user, media et contact_message : aucun index n'a jamais servi, clés primaires comprises. Ces tables font 16 à 32 kB, une à trois pages : le Seq Scan y gagne toujours, et il gagnera tant que la volumétrie restera celle d'un blog. Mention pour redirect_rule, dont le lookup tourne deux fois par page vue (le matching des redirections) : 111 lignes parcourues séquentiellement à chaque fois, 0,017 ms. L'index posé dessus attend un trafic qui justifierait son existence.

La suite

Les deux correctifs N+1 sont mergés, mesures à l'appui. Les index morts, eux, sont encore en place : les supprimer est une migration à part entière, avec son rollback, et elle mérite sa propre décision. La prochaine migration de schéma de ce blog retirera donc plus d'index qu'elle n'en créera.

Il manque un outil au tableau : pg_stat_statements, absent de cette prod, aurait donné les volumes d'appels par requête en trente secondes au lieu d'une séance de déduction. Il rejoint la liste des chantiers.

Et vous ? La requête tient sur une ligne :

SELECT indexrelname, idx_scan FROM pg_stat_user_indexes ORDER BY idx_scan;

Lancez-la sur votre prod, comptez les zéros, et venez me dire votre score.