Logs et statitistiques des requêtes Hibernate

show_sql

Pour activer l’affichage des requêtes SQL générées par Hibernate, on connait le classique show_sql, qui peut être configurée dans le fichier persistence.xml.

<property name="hibernate.show_sql">true</property>

Exemple:

Hibernate: select s1_0.id,s1_0.date_debut,s1_0.date_fin,m1_0.id,m1_0.code,m1_0.duree,m1_0.titre,m1_1.taux_pratique from session
s1_0 join cours m1_0 on m1_0.id=s1_0.matiere_id where m1_0.titre like ? order by s1_0.date_debut

Cette option est pratique, mais a quelques défauts importants :

  • Les requêtes sont affichées dans la sortie standard, ce serait mieux de les avoir dans les logs configurés.

  • Il manque la valeur des paramètres passés.

  • Les requêtes sont peu lisibles car sur une ligne.

Pour ce dernier point, on peut avoir une meilleure mise en forme des requêtes. Il faut activer l’option format_sql.

 <property name="hibernate.format_sql">true</property>

Exemple:

Hibernate:
    select
        s1_0.id,
        s1_0.date_debut,
        s1_0.date_fin,
        m1_0.id,
        m1_0.code,
        m1_0.duree,
        m1_0.titre
      from
          session s1_0
      join
          cours m1_0
          on m1_0.id=s1_0.matiere_id
      where
          m1_0.titre like ?
      order by
          s1_0.date_debut

Loggers

Pour envoyer les logs dans Log4J ou Logback, il faut désactiver l’option show_sql et activer le logger org.hibernate.SQL en debug. Les informations sur les paramètres sont envoyées au niveau trace dans le logger org.hibernate.type.descriptor.sql pour Hibernate 5 (ou anvant) et dans le logger org.hibernate.orm.jdbc.bind pour Hibernate 6.

  <logger name="org.hibernate.SQL" level="DEBUG" />
  <logger name="org.hibernate.orm.jdbc.bind" level="TRACE"/>

Exemple:

01:23:45.666 DEBUG o.h.SQL select s1_0.id,s1_0.date_debut,s1_0.date_fin,m1_0.id,m1_0.code,m1_0.duree,m1_0.titre,m1_1.taux_pratique
from session s1_0 join cours m1_0 on m1_0.id=s1_0.matiere_id where m1_0.titre like ? order by s1_0.date_debut
01:23:45.666 TRACE o.h.orm.jdbc.bind: binding parameter (1:VARCHAR) <- [%Cre%]
L’option format_sql fonctionne aussi avec le logger comme avec l’option show_sql.

Slow queries

La durée limite pour le déclenchement du log est configuré par la propriété hibernate.log_slow_query. Sa valeur par défaut est 0, ce qui désactive la fonctionnalité.

Le temps d’exécution ne prend en compte ni le temps de préparation, ni le temps de traitement du résultat.

  <property name="hibernate.log_slow_query" value="20" />

Exemple:

01:23:45.666 INFO o.h.SQL_SLOW SlowQuery: 128 milliseconds.
SQL: 'select s1_0.id,s1_0.date_debut,s1_0.date_fin,m1_0.id,m1_0.code, m1_0.duree,m1_0.titre,m1_1.taux_pratique from session s1_0
join cours m1_0 on m1_0.id=s1_0.matiere_id where m1_0.titre like ? order by s1_0.date_debut'
Jusqu’à la version 6.2, il fallait utiliser hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS. hibernate.log_slow_query est la nouvelle propriété depuis la version 6.3. L’ancien nom reste utilisable pour le moment.

Cache L2

 <logger name="org.hibernate.orm.cache" level="DEBUG"/>

Exemple:

01:23:45.666 DEBUG o.h.orm.cache Checking cached query results in region: default-query-results-region
01:23:45.666 DEBUG o.h.orm.cache Query results were not found in cache
...
01:23:45.666 DEBUG o.h.orm.cache Caching query results in region: default-query-results-region; timestamp=70175456585277
...
01:23:45.666 DEBUG o.h.orm.cache Checking cached query results in region: default-query-results-region
01:23:45.666 DEBUG o.h.orm.cache Returning cached query results

Statistiques

Hibernate peut produire des statiques pour chaque requête ou par session.

Pour les statistiques des requêtes, il suffit d’activer le logger au niveau choisi (TRACE ou DEBUG). Certaines des informations peuvent être redondantes avec les logs des paragraphes précédents, comme pour le cache L2.

 <logger name="org.hibernate.stat" level="TRACE"/>

Exemple:

01:23:45.666 DEBUG o.h.s.i.StatisticsImpl Statistics#queryCacheMiss( [CRITERIA] select ... from session,
default-query-results-region )
01:23:45.666 TRACE o.h.s.i.StatisticsImpl Statistics#queryCachePut( [CRITERIA] select ... from session,
default-query-results-region )
01:23:45.666 DEBUG o.h.s.i.StatisticsImpl HHH000117: HQL: [CRITERIA] select ... from session, time: 3ms, rows: 18
...
01:23:45.666 TRACE o.h.s.i.StatisticsImpl Statistics#queryCacheHit( [CRITERIA] select ... from session,
default-query-results-region )

Pour les statistiques de sessions,

 <property name="hibernate.generate_statistics">true</property>

Exemple:

01:23:45.666 INFO  o.h.e.i.StatisticalLoggingSessionEventListener : Session Metrics {
    38374 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    493919 nanoseconds spent preparing 1 JDBC statements;
    1179672 nanoseconds spent executing 1 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    0 nanoseconds spent performing 0 L2C puts;
    0 nanoseconds spent performing 0 L2C hits;
    0 nanoseconds spent performing 0 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    5190 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Hibernate avec Spring Boot

Quand on utilise Spring Boot, tout ceci peut être configuré dans le fichier application.yml.

spring:
  jpa:
    properties:
      hibernate:
        format_sql: true
        log_slow_query: 20
        generate_statistics: true

logging:
  level:
    "org.hibernate.SQL": DEBUG
    "org.hibernate.orm.jdbc.bind": TRACE
    "org.hibernate.orm.cache": DEBUG
    "org.hibernate.stat": TRACE

Références