Lecture du log SQL : requêtes et SELECT larges

1. Log SQL : la vérité de l’ORM

Quand vous travaillez avec Hibernate, il est très facile de tomber dans l’illusion : « J’ai écrit un beau repository – donc la base va faire quelque chose de beau ». En réalité, Hibernate est un traducteur, et il traduit votre monde objet en SQL comme il le juge correct. Le log SQL est l’impression de cette traduction : sans lui, c’est comme discuter du contenu d’un livre sans en avoir ouvert une seule page.

Soyons honnêtes : l’ORM est bon jusqu’au moment où vous oubliez qu’en dessous il y a toujours une base de données. Et la base de données ne lit pas les annotations – elle lit les requêtes. C’est pourquoi, dans ce cours approfondi, nous maintenons le principe « d’abord observer, ensuite croire ».

Ce qui importe ici, ce n’est pas seulement le log lui-même, mais aussi la façon de l’aborder. D’abord, nous isolons un cas de lecture et, à l’aide du SQL, nous distinguons la requête racine, les selects secondaires, les SELECT larges et les modifications inattendues. Ensuite, nous confirmons le tableau avec les compteurs Hibernate. Et ce n’est que si les requêtes sont déjà peu nombreuses et qu’un SQL particulier reste lourd qu’il vaut la peine d’examiner le SQL généré, EXPLAIN et le raisonnement sur les index. Sinon, il est très facile de commencer à jouer avec read-only, le cache ou les index avant même d’avoir compris la forme du problème.

Il est important de se préparer psychologiquement. Le log SQL n’est pas un « dépotoir de lignes » dont il faut souffrir. C’est une enquête : si vous apprenez à le lire par blocs, vous commencerez rapidement à voir les mêmes motifs. N+1 ressemble à un SELECT ... where id = ? répété. Une requête trop large ressemble à un select sur 40 colonnes et 5 join. Une modification inattendue dans un cas de lecture ressemble à un update soudain là où vous n’attendiez que de la lecture.

Un peu de terminologie pour être plus précis par la suite. Par query shape (forme de la requête), nous entendons « quelles tables participent, quels JOIN, filtres et tris sont réellement appliqués en SQL ». Et par wide SELECT, nous entendons une situation où la requête rapporte plus de données (colonnes/relations/lignes) que nécessaire pour le scénario donné. Un SELECT large, c’est comme aller au magasin chercher du pain et acheter un demi-litre d’huile moteur « au cas où », parce que vous êtes déjà au magasin.

2. Délimitation du scénario pour le log SQL

La première compétence du diagnostic SQL n’est pas la lecture du SQL. Paradoxal, mais vrai. La première compétence est la capacité à limiter le log de manière à analyser un seul cas d’utilisation, et non toute la vie de l’application. Sinon, vous voyez les migrations Flyway, les health‑checks du pool, des opérations de seeding en arrière‑plan, et votre vraie requête se perd comme une chaussette dans une machine à laver.

Dans le cadre du Commerce Persistence Lab, nous exécutons généralement un scénario de lecture spécifique via un service, un test ou un petit lab‑runner. Il est important de pouvoir dire : « Ici commence le scénario, ici il se termine ». Pour cela, de simples marqueurs dans les logs d’application aident. Non pas parce que c’est une « observabilité de pointe », mais parce qu’ainsi vous retrouverez visuellement le morceau entre deux lignes, sans faire semblant d’être un grep.

Par exemple, dans un service de requêtes de catalogue, on peut placer ces marqueurs :

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class CatalogQueryService {
    private static final Logger log = LoggerFactory.getLogger(CatalogQueryService.class);

    public void runCatalogReadCase() {
        // Marqueur de début de scénario : permet de repérer visuellement les limites du cas dans le log d’application.
        log.info("=== DEBUT CAS LECTURE CATALOGUE ===");

        // ... ici appel au repository/EntityManager

        // Marqueur de fin de scénario : entre DEBUT/FIN on cherche la trace SQL de cette lecture.
        log.info("=== FIN CAS LECTURE CATALOGUE ===");
    }
}

Ce code est volontairement « bête » et court. Son seul but est de vous donner des repères dans le log, pas d’être un chef‑d’œuvre d’architecture. Ensuite, vous ouvrez le log et vous ne regardez le SQL qu’entre ces lignes. Oui, ce n’est pas une science‑fusée. Mais il est surprenant de voir combien de personnes essaient d’analyser « tout à la fois », puis abandonnent en disant : « Les logs sont inutiles ». Les logs ne sont pas inutiles – c’est la tentative de les lire comme un roman qui est inutile.

Une autre habitude importante : ne pas mélanger dans sa tête le « log d’application » et le « log SQL ». Le log d’application aide à trouver les limites du scénario et à comprendre ce que vous exécutez exactement. Le log SQL montre ce qui est réellement parti vers PostgreSQL. Si vous lisez le SQL sans comprendre le scénario, vous risquez d’optimiser la mauvaise chose (au mieux), ou de guérir le symptôme et de laisser la cause (au pire).

3. Compter les requêtes dans un scénario

Quand un développeur débutant dit « il semble qu’il y ait beaucoup de requêtes », cela ressemble un peu à « il semble que la soupe soit salée ». Peut‑être qu’elle est salée, peut‑être que non, mais « il semble » n’aide pas à corriger la recette. Donc la deuxième compétence, après l’isolation du scénario, est de comprendre rapidement combien de requêtes SQL ont été émises et quel type de charge cela représente : une seule requête racine + une salve de chargements secondaires, ou vraiment beaucoup de requêtes différentes, ou une seule requête gigantesque.

La méthode la plus simple : compter visuellement les select dans le bloc de log concerné. Et oui, au début c’est normal. L’important n’est pas de compter à l’œil, mais de commencer à remarquer la répétition. En général, le problème n’est pas que « 18 requêtes » soit un mal en soi. Le problème, c’est que 17 d’entre elles ont la même forme, ce qui est un signe de N+1 ou de selects secondaires massifs.

Pour faciliter les choses, il est utile de diviser mentalement le SQL d’un même scénario en groupes :

D’abord vient la requête racine – celle qui récupère la « liste principale » (produits du catalogue, liste de commandes, clients). Ensuite viennent les selects secondaires – les chargements des associations paresseuses (par exemple product_details, order_items, customer_address). Et séparément, vous gardez en tête un « drapeau rouge » : tout insert/update/delete dans un cas de lecture. Normalement, ils ne devraient pas s’y trouver. S’ils sont présents, on ne parle plus simplement d’un « SELECT lent » : le scénario est devenu « impur » et l’ORM fait un travail inutile.

Prenons un exemple « innocent » avec des commandes. Supposons que nous lisions une liste de commandes (en tant qu’entités), puis que dans le code nous touchions les lignes de commande plus loin :

import jakarta.persistence.EntityManager;
import java.util.List;

public class OrderQueryService {
    private final EntityManager entityManager;

    public OrderQueryService(EntityManager entityManager) {
        // Important : ici nous analysons le comportement de l’ORM via EntityManager.
        this.entityManager = entityManager;
    }

    public List<?> findRecentOrders() {
        // Requête racine : dans le log, nous nous attendons à voir UN SEUL SELECT sur PurchaseOrder.
        return entityManager.createQuery("""
            select o
            from PurchaseOrder o
            order by o.createdAt desc
            """)
            // Limiter le résultat : pratique pour que le scénario soit stable et lisible dans le log.
            .setMaxResults(20)
            .getResultList();
    }
}

La requête elle‑même est unique. Mais cela ne signifie pas que le scénario est « bon marché ». Si après cela vous faites order.getItems().size(), ou que vous sérialisez la commande en JSON (dans un projet normal), cette unique requête se transforme en « un plus vingt ». Et dans le log SQL, vous devrez voir cela non pas comme une abstraction, mais comme un select ... from order_item ... where order_id = ? répété.

Le critère principal ici est simple : vous n’essayez pas de « réparer » tout de suite. Vous essayez de classifier le problème à partir du log. Et à ce stade, il vous suffit de répondre à deux questions : « Combien de requêtes au total ? » et « Combien d’entre elles se répètent par leur forme ? ».

4. Répétitions de SELECT : N+1 et chargements différés

Les requêtes répétées sont le pain, le beurre et la petite douleur du diagnostic Hibernate. Elles surviennent constamment car les associations paresseuses, les proxies et les collections persistantes font partie intégrante de l’ORM. Le problème commence quand la répétition devient non pas accidentelle, mais massive : une requête racine puis N requêtes identiques suivant le même modèle.

L’exemple pédagogique le plus simple de notre domaine est Product et ProductDetails. Au niveau Java, tout semble assez correct :

import jakarta.persistence.EntityManager;
import java.util.List;

public class CatalogReadCase {
    private final EntityManager entityManager;

    public CatalogReadCase(EntityManager entityManager) {
        this.entityManager = entityManager;
    }

    public void readAndTouchDetails() {
        // Requête racine : on récupère la liste des produits (dans le log il y aura un SELECT sur Product).
        List<Product> products = entityManager.createQuery("""
            select p
            from Product p
            where p.status = :status
            order by p.name
            """, Product.class)
            // Le paramètre est important : dans le log SQL il y aura "where p.status = ?".
            .setParameter("status", ProductStatus.ACTIVE)
            .getResultList();

        for (Product p : products) {
            // Déclencheur important : c’est cette ligne qui génère généralement N SELECT identiques sur product_details.
            p.getDetails().getDescription(); // déclenche le chargement paresseux
        }
    }
}

En Java, la logique est claire : on charge les produits, puis « pour chacun » on regarde la description. Mais le log SQL ressemblera à ceci (simplifié) :

-- requête racine : on lit les produits une fois
select p.id, p.sku, p.name, p.status, p.price_amount, p.price_currency
from product p
where p.status = ?
order by p.name;

-- selects secondaires : le même modèle se répète N fois (écriture classique de N+1)
select d.product_id, d.description, d.technical_specs, d.warranty_months
from product_details d
where d.product_id = ?;

select d.product_id, d.description, d.technical_specs, d.warranty_months
from product_details d
where d.product_id = ?;

-- ... et ainsi N fois

Voilà le symptôme que vous devez être capable de formuler. Pas « on a N+1 », mais plus précisément : « après la requête racine, le même select sur product_details se répète N fois ». C’est déjà presque un diagnostic. Et surtout, ce n’est pas une « impression », c’est une structure observable.

À ce stade, une réaction incorrecte survient souvent : « Bon, on met tout en EAGER ! » Nous avons déjà vu que EAGER n’est pas une « correction du problème », mais une façon de le déplacer ailleurs et de le rendre moins prévisible. Le log est précisément là pour que vous ne traitiez pas le symptôme « tout est lent » avec un marteau universel, mais que vous compreniez la source spécifique de la répétition.

Il existe une variante plus perfide des requêtes répétées : le chargement différé de collections. Par exemple, une liste de commandes, puis getItems() sur chacune :

import jakarta.persistence.EntityManager;
import java.util.List;

public class OrdersReadCase {
    private final EntityManager entityManager;

    public OrdersReadCase(EntityManager entityManager) {
        this.entityManager = entityManager;
    }

    public void readOrdersAndTouchItems() {
        // Requête racine : liste des commandes (idéalement un SELECT sur purchase_order).
        List<PurchaseOrder> orders = entityManager.createQuery("""
            select o
            from PurchaseOrder o
            where o.status = :status
            order by o.createdAt desc
            """, PurchaseOrder.class)
            .setParameter("status", OrderStatus.NEW)
            // Limiter le nombre de commandes rend le N+1 facilement visible dans la trace SQL.
            .setMaxResults(10)
            .getResultList();

        for (PurchaseOrder o : orders) {
            // Déclencheur : l’accès à la collection provoque généralement un SELECT sur order_item pour chaque commande.
            o.getItems().size(); // déclenche le chargement de collection
        }
    }
}

En SQL, cela se transforme généralement en « requête racine + N requêtes sur order_item ». Et ici, votre « enquêteur » doit déjà distinguer : les SELECT répétés sur to‑one (souvent « par id ») et sur to‑many (souvent « where parent_id = ? »). Du point de vue du log, ce sont deux « écritures du criminel » différentes.

Pour faciliter la mémorisation, gardez en tête ce tableau « symptôme → apparence dans le log → signification » :

Ce tableau n’est pas une instruction « comment réparer ». C’est un dictionnaire pour que vous compreniez plus vite ce que vous voyez.

5. SELECT large et JOIN gonflés

Après avoir appris à repérer les requêtes répétées, le danger suivant apparaît : « Faisons une seule requête pour que ce soit beau ». Et naît alors un SELECT large – une requête qui en est bien une, mais qui rapporte tellement de données et multiplie tellement les lignes que vous avez gagné en nombre de requêtes mais perdu en volume de travail.

Un candidat typique est JOIN FETCH sur une collection. Il élimine effectivement les selects secondaires, mais peut « gonfler » le result set. Regardons un exemple « charger les commandes avec leurs lignes et le client » :

import jakarta.persistence.EntityManager;
import java.util.List;

public class OrdersFetchJoinReadCase {
    private final EntityManager entityManager;

    public OrdersFetchJoinReadCase(EntityManager entityManager) {
        this.entityManager = entityManager;
    }

    public List<PurchaseOrder> loadWithItems() {
        // Idée : "supprimer N+1" via fetch join (dans le log il y aura un seul gros SELECT).
        return entityManager.createQuery("""
            select distinct o
            from PurchaseOrder o
            left join fetch o.items
            left join fetch o.customer
            where o.status = :status
            order by o.createdAt desc
            """, PurchaseOrder.class)
            // En SQL, cela deviendra un paramètre "where o.status = ?".
            .setParameter("status", OrderStatus.NEW)
            // Important : setMaxResults + fetch join sur une collection donne souvent des effets inattendus.
            .setMaxResults(20)
            .getResultList();
    }
}

Au niveau SQL, cela se transforme en un gros join de cette forme (encore simplifié) :

-- SELECT large : beaucoup de colonnes + des join, et les lignes dupliquent les données de la commande sur chaque ligne de détail
select
  o.id, o.order_number, o.status, o.created_at, o.total_amount_amount, o.total_amount_currency,
  c.id, c.email, c.first_name, c.last_name,
  i.id, i.quantity, i.price_at_purchase_amount, i.price_at_purchase_currency, i.product_sku_snapshot
from purchase_order o
left join customer c on c.id = o.customer_id
left join order_item i on i.order_id = o.id
where o.status = ?
order by o.created_at desc;

Formellement, une seule requête. Mais au niveau du résultat, la base renverra une ligne pour chaque combinaison « commande × ligne ». Si vous avez 20 commandes, chacune avec 10 lignes, la base renverra 200 lignes, et Hibernate devra ensuite « reconstruire » 20 PurchaseOrder et 200 OrderItem. Cela peut être un compromis acceptable. Ou un problème inattendu : si vous faisiez cela pour une liste et non pour un détail, et que les lignes ne sont en réalité pas nécessaires.

C’est ici que la compétence clé de lecture du log SQL entre en jeu : vous devez remarquer la « largeur » de la requête. Non seulement le nombre de JOIN, mais aussi le fait que le SELECT ramène un tas de colonnes et que les lignes dupliquent les données de l’entité racine. Dans le log, un SELECT large se « trahit » généralement ainsi :

Vous voyez un long select (beaucoup de colonnes), plusieurs join, et souvent un distinct en JPQL qui, au niveau SQL, peut ne pas empêcher la duplication des lignes (il peut éviter la duplication des entités racines dans le résultat Hibernate, mais ne réduit pas toujours le travail de la base).

Il est utile de garder en tête une question saine : « Combien de données voulais‑je réellement lire dans ce scénario ? ». Pour une liste administrative de commandes, vous pouvez vous contenter de : id, orderNumber, email, totalAmount, status, createdAt. Point. Les lignes de commande y sont souvent superflues. Et dès que vous saurez reconnaître un SELECT large dans le log, vous cesserez de traiter les requêtes répétées par des « jointures monstrueuses ».

Pour ne pas transformer cela en débat religieux « une requête vs plusieurs requêtes », il est commode de raisonner ainsi : nous avons deux coûts – le coût des allers‑retours (nombre de requêtes) et le coût du volume de données (largeur/duplication du résultat). Le log permet de voir les deux.

6. Modifications dans un cas de lecture : UPDATE/DELETE

Une classe particulière de problèmes : vous êtes apparemment « en train de lire », et soudain un update apparaît dans la trace SQL. À ce moment, le cerveau du développeur débutant tire généralement deux conclusions à la suite. La première : « Hibernate est devenu fou ». La seconde : « il faut désactiver Hibernate ». Les deux sont généralement prématurées.

Rappelons le mécanisme : si vous avez chargé une entité managée et modifié son état (même accidentellement), Hibernate doit synchroniser les changements lors du flush/commit. Et le flush peut avoir lieu non seulement « à la fin », mais aussi « avant une requête », si Hibernate estime que la requête serait incorrecte autrement (nous l’avons déjà vu dans le module sur le flush). Par conséquent, dans un cas de lecture, il est important de surveiller le log non seulement pour les SELECT, mais aussi pour les « modifications inattendues ».

L’exemple le plus trivial – « on a légèrement modifié une chaîne » :

import jakarta.persistence.EntityManager;

public class ProductReadCaseWithAccidentalUpdate {
    private final EntityManager entityManager;

    public ProductReadCaseWithAccidentalUpdate(EntityManager entityManager) {
        this.entityManager = entityManager;
    }

    public void readAndNormalize(long productId) {
        // Lecture : dans la trace SQL il y aura SELECT ... where id = ?
        Product p = entityManager.find(Product.class, productId);

        // Piège : même une normalisation "innocente" modifie l’état managé
        // et peut conduire à un UPDATE lors du flush/commit.
        p.setName(p.getName().trim()); // semble "sûr", mais c’est une modification d’entité managée
    }
}

Si le nom était déjà sans espaces, vous pouvez penser que « rien n’a changé ». Mais dans de nombreux cas, vous avez quand même activé le dirty checking (ou réellement modifié la chaîne), et à la fin de la transaction, Hibernate enverra un UPDATE. Dans la trace SQL, cela ressemblera à ceci :

-- d’abord la lecture
select p.id, p.name, p.sku, p.status
from product p
where p.id = ?;

-- ensuite la modification (drapeau rouge pour un cas de lecture)
update product
set name = ?
where id = ?;

Et si dans votre cas de lecture il y a encore une autre requête après cela (par exemple, vous lisez la liste des produits après avoir normalisé un produit), alors l’UPDATE peut apparaître avant ce SELECT, à cause d’un flush before query. Et c’est particulièrement sournois : vous lisez le log et vous pensez que l’UPDATE « s’est produit tout seul ». Il ne s’est pas produit tout seul. Il est la conséquence du fait que vous avez modifié l’état managé avant la requête suivante.

C’est pourquoi la règle de lecture du log SQL pour un cas de lecture est simple et légèrement paranoïaque (dans le bon sens) : si vous analysez un scénario de lecture, vous devez vous assurer qu’à l’intérieur de son bloc SQL il n’y a pas d’INSERT/UPDATE/DELETE. S’ils sont présents, c’est un sous‑problème distinct. Même si vous vous « fichez » de ce qu’il met à jour, cela affecte le flush, les verrous, le plan d’exécution et, globalement, la prévisibilité du scénario.

7. Schéma de lecture du log SQL

La trace SQL ressemble au début à une correspondance entre deux personnes qui adorent se citer abondamment. Mais la bonne nouvelle est que, pour le diagnostic, nous n’avons pas besoin de tout le texte. Nous avons besoin de la structure. Et cette structure peut presque toujours être reconstituée si vous regardez le log par blocs de manière disciplinée.

Je propose le schéma mental suivant (simple mais qui sauve les nerfs) : tout scénario de lecture peut être décomposé en « racine », « chargements différés » et « modifications ». La racine est la requête racine qui détermine l’ensemble de données principal. Les chargements différés sont les selects secondaires qui apparaissent à cause des associations paresseuses, des collections, du batch fetching ou simplement de requêtes supplémentaires. Les modifications sont tout ce qui change la base : insert/update/delete. Dans un cas de lecture pur, le troisième bloc doit être vide.

Représentons‑le sous forme d’un petit organigramme pour que le cerveau « voit » plus facilement l’ordre :

flowchart TD
    A[Début du cas de lecture] --> B[Requête racine : SELECT principal]
    B --> C{Y a‑t‑il des selects secondaires ?}
    C -->|Oui| D[SELECT répétés : to‑one / to‑many]
    C -->|Non| E[Une seule requête : vérifier SELECT large]
    D --> F{Y a‑t‑il des modifications ?}
    E --> F{Y a‑t‑il des modifications ?}
    F -->|Oui| G[Drapeau rouge : UPDATE/DELETE/flush before query]
    F -->|Non| H[Formuler le symptôme : N+1 ou SELECT large ou normal]

Notez qu’à cette étape nous ne « traitons » toujours pas. Nous formulons le symptôme. Une bonne formulation du symptôme tient généralement en une ligne et ressemble à ceci :

« Scénario de liste de produits : 1 requête racine + 30 SELECT product_details par product_id répétés »

ou

« Scénario de liste de commandes : 1 gros JOIN avec order_item, result set gonflé, données racines dupliquées sur chaque ligne »

ou

« Un cas de lecture fait inopinément un UPDATE sur product, donc à l’intérieur du scénario il y a une modification d’entité managée et un flush ».

Si vous savez formuler ainsi, vous êtes déjà à mi‑chemin d’un véritable audit de performance. Car alors l’action suivante devient évidente et vérifiable. Et « l’évidence » dans Hibernate est une ressource rare et très précieuse.

8. Erreurs typiques lors de la lecture du log SQL

Erreur n°1 : « une seule requête est toujours meilleure que plusieurs requêtes ».
C’est une pensée humaine très compréhensible : un, c’est moins, donc plus rapide. Mais le log SQL montre régulièrement l’inverse : un seul SELECT large avec un tas de JOIN peut faire chuter les performances plus qu’une poignée de petites requêtes, surtout si la requête large multiplie les lignes et ramène des colonnes inutiles.

Erreur n°2 : lire le log ligne par ligne, et non par scénarios.
Une autre erreur est de lire le log ligne par ligne, comme si chaque ligne était un problème en soi. Ainsi, on perd rapidement de vue le scénario dans son ensemble. La bonne méthode : d’abord trouver les limites du cas d’utilisation, ensuite voir la requête racine, puis remarquer la répétition des selects secondaires, et seulement ensuite examiner les détails de chaque select. Cela ressemble un peu à la lecture d’une carte : d’abord les continents, puis les pays, puis les rues.

Erreur n°3 : ignorer les UPDATE dans un cas de lecture.
Une erreur très gênante : ne regarder que les SELECT et ignorer les UPDATE dans un cas de lecture. Cela arrive souvent parce que le cerveau « s’attend » à de la lecture et ne remarque pas les écritures. Mais ce sont précisément ces UPDATE qui deviennent souvent la cause d’un flush before query inattendu, de verrous superflus et d’effets secondaires étranges. Si vous voyez une écriture là où elle ne devrait pas être, considérez‑la comme un bug distinct du scénario.

Erreur n°4 : « soigner la base » avant d’avoir diagnostiqué l’ORM.
Un autre piège est de « diagnostiquer la base » avant d’avoir diagnostiqué l’ORM. C’est‑à‑dire voir un scénario lent et dire immédiatement : « Il faut un index ». Parfois un index est nécessaire, mais le log SQL doit d’abord répondre à la question : le problème vient‑il de la forme de la lecture (requêtes répétées, select large, overfetching) ou bien est‑ce vraiment la façon dont la base exécute une requête correcte, étroite et nécessaire ? Si vous sautez cette étape, vous risquez de créer un schéma d’index qui soigne le symptôme mais laisse le cas de lecture sale.

Erreur n°5 : conclure « Hibernate est nul » sans formuler le symptôme.
Et enfin, l’erreur du débutant, que j’affectionne particulièrement (car j’y suis passé moi‑même) : conclure « Hibernate est nul » sans avoir été capable de formuler le symptôme en une phrase. Dès que vous vous forcez à écrire « requête racine + N selects identiques sur details » ou « un seul gros join sur items », la moitié de la magie disparaît. Hibernate n’est pas nul. Il fait exactement ce que vous (ou votre code) lui avez indirectement dit de faire.