Hibernate Debugging

by ·Keine Kommentare

Wer hat sich nicht schon Mal gefragt, was die Blackbox Hibernate im Hintergrund so alles macht?

Statistiken

Statistiken von Hibernate

Hibernate umfangreiche Statistiken für uns erstellen, um zum Beispiel besser zur verstehen warum es an der einen oder anderen Stelle klemmt. Die automatische Erstellung der Statistiken im Hintergrund nagt natürlich an der Performance der Anwendung und sollte daher nur in der Entwicklung verwendet werden. Zu Testzwecken kann das Feature gegebenenfalls auch auf einem PreProduktion System aktiviert werden, damit man eine realere Umgebung Simulieren kann.

Um das Feature zu aktivieren muss man generate_statistics auf true setzen. Dieses kann über die persistence.xml erledigt werden.

<?xml version="1.0" encoding="UTF-8"?>
<persistence version="2.0"
    ...
    <persistence-unit name="default" >
         <properties>
         ...
             <property name="hibernate.generate_statistics" value="true" />
         ...
         </properties>
    </persistence-unit> 
</persistence>

Um nicht die persistence.xml zu modifizierem, welche mit deployt wird, sollte man für die Testfälle besser die System Properties anpassen. Diese über das Kommandozeilenparameter -D…

java -jar app.jar -Dhibernate.generate_statistics=true

oder in der IDE angegeben werden:

Spring Boot

Möchte man das Feature unter Spring Boot verwenden und trägt das so in die application.properties ein, dann wird das nicht funktionieren. Um die Properties an den JPA Provider (hier also Hibernate) zu übergeben, muss dieses in einen Prefix in der application.properties bekommen. In dem Fall von Hibernate ist das spring.jpa.properties.hibernate.

# Generate additional statistics. Do not use in production
spring.jpa.properties.hibernate.generate_statistics=true

Statistiken

Wenn man wie oben beschrieben die Generierung der Statistiken aktiviert hat, dann bekommt man eine nette Ausgabe auf der Konsole zu den abgesetzten Queries zur Datenbank.

40999 nanoseconds spent acquiring 2 JDBC connections;
25173 nanoseconds spent releasing 1 JDBC connections;
327100 nanoseconds spent preparing 3 JDBC statements;
1215257 nanoseconds spent executing 3 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;
901269 nanoseconds spent executing 1 flushes (flushing a total of 1 entities and 0 collections);
0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)

Queries

Queries formatieren

Normalerweise werden die Queries inline geloggt. D.h. je Zeile ein Query. Das macht insgesamt das Log gut lesbar, aber dafür sind die SQL Queries um so schlechter zu lesen. Auch hierfür bietet Hibernate eine Lösung an. Man kann die Ausgabe der Queries im Log formatieren lassen. Auch hier gilt natürlich der Grundsatz, dieses nicht in Produktion zu verwenden. Setzt man format_sql auf true, dann erhält man eine Mehrzeilige, formatierte Ausgabe der Queries in dem Log.

Hibernate: 
   create table customer (
       id bigint not null,
        lastname varchar(50),
        name varchar(50),
        primary key (id)
    ) engine=MyISAM

In der application.properties trägt man analog zu dem obigen Beispiel es mit dem Prefix spring.jpa.properties.hibernate ein.

# Prettify Hibernate SQL Queries in log
spring.jpa.properties.hibernate.format_sql=tru

Binding Parameter

Parameter der Queries

Mit den beiden oben genannten Methoden kann man schon sehr viel Informationen aus dem Log von Hibernate entnehmen. Eine wichtige Zutat um das Geheimnis der Blackbox Hibernate zu lüften fehlt allerdings noch. Man kann zwar jetzt die konkreten Queries im Log sehen, aber man kann nicht erkennen welche Parameterwerte gebunden sind.

Konfiguration von Spring Boot

Mit dem sogenannten Tracing kann man sich die Werte der Parameter mit in dem Log ausgeben lassen. Gesteuert wird das Ganze über den Hibernate Type. Dieser muss auf Trace gestellt werden:

# Show binding parameter values
logging.level.org.hibernate.type=trace

Die Ausgabe im Log erscheint dann wie folgt:

Hibernate: 
    insert 
    into
        customer
        (lastname, name, id) 
    values
        (?, ?, ?)
2018-11-15 12:54:47.652 TRACE 6971 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [1] as [VARCHAR] - [Bernhard]
2018-11-15 12:54:47.652 TRACE 6971 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [2] as [VARCHAR] - [Lisa]
2018-11-15 12:54:47.652 TRACE 6971 --- [  restartedMain] o.h.type.descriptor.sql.BasicBinder      : binding parameter [3] as [BIGINT] - [11]