Wer seine Daten in der Persistenzschicht ablegen möchte, hat häufig mit relationalen Datenbanken zu tun. Obwohl Frameworks wie Hibernate und JPA das Hantieren mit lästigen SQL Aufrufen häufig vergessen lassen, muss man hin und wieder schauen, was im Hintergrund geschieht.
Für den folgenden Code-Schnipsel sollen die dazugehörigen SQL Aufrufe geloggt werden. Zuerst wird eine neue Entität gespeichert und dann alle existierenden Entitäten abgerufen.
@Autowired
HolidayRepository repository;
void test() {
repository.save(new Holiday());
repository.findAll();
}
Spring Data JPA stellt eine eigene Property zur Ausgabe der verwendeten SQL Anweisungen bereit. Das ist für einfache Überprüfungen während der Entwicklung sehr angenehm.
spring.jpa.show-sql=true
Wird diese Property z.B. in den application.properties Datei aktiviert, dann erhält der Entwickler folgende kompakte Darstellung serviert.
Hibernate: call next value for hibernate_sequence Hibernate: insert into holiday (name, id) values (?, ?) Hibernate: select holiday0_.id as id1_0_, holiday0_.name as name2_0_ from holiday holiday0_
Wer die Darstellung es etwas gefälliger erleben möchte, verwendet zusätzlich die Property spring.jpa.properties.hibernate.format_sql.
spring.jpa.show-sql=true spring.jpa.properties.hibernate.format_sql=true
Die zusätzliche Property formatiert die SQL Anweisungen wie im folgenden Beispiel.
Hibernate:
call next value for hibernate_sequence
Hibernate:
insert
into
holiday
(name, id)
values
(?, ?)
Hibernate:
select
holiday0_.id as id1_0_,
holiday0_.name as name2_0_
from
holiday holiday0_
Beide Properties sind während der Entwicklung hilfreich, aber leider wird die Ausgabe auf die Standardkonsole geschrieben. Alternativ dazu kann der Hibernate Logger im DEBUG Modus diese Informationen loggen.
logging.level.org.hibernate.SQL=DEBUG
Der Hibernate Logger generiert die folgenden Einträge in der Log-Ausgabe.
org.hibernate.SQL : call next value for hibernate_sequence org.hibernate.SQL : insert into holiday (name, id) values (?, ?) org.hibernate.SQL : select holiday0_.id as id1_0_, holiday0_.name as name2_0_ from holiday holiday0_
Werden etwas mehr Informationen benötigt kann einen weiteren Logger bemühen. Dann werden auch die tatsächlichen Werte zu den Platzhaltern in den SQL Anweisungen zugeordnet.
logging.level.org.hibernate.SQL=DEBUG logging.level.org.hibernate.type.descriptor.sql.BasicBinder=TRACE
Im folgenden Ausschnitt der Logausgabe sind nicht nur die SQL Anweisungen enthalten, sondern auch die beiden Werte für die neue Holiday Entität.
org.hibernate.SQL : call next value for hibernate_sequence org.hibernate.SQL : insert into holiday (name, id) values (?, ?) o.h.type.descriptor.sql.BasicBinder : binding parameter [1] as [VARCHAR] - [null] o.h.type.descriptor.sql.BasicBinder : binding parameter [2] as [BIGINT] - [1] org.hibernate.SQL : select holiday0_.id as id1_0_, holiday0_.name as name2_0_ from holiday holiday0_
Die Informationen des Hibernate Loggers in der Log-Ausgabe sind eine große Hilfe bei der Fehlersuche in der Produktion. Da in Spring Boot die Log-Level einzelner Logger dynamisch über den Actuator geändert werden können., müssen die Logger nicht einmal dauerhaft im DEBUG bzw. im TRACE Level laufen. Wird ein Fehler festgestellt, dann kann dieser mit geänderten Log-Level nachzustellt und analysiert werden.
Einen weiteren Sprung im Nutzen der Log-Ausgabe ist die Einbindung der Bibliothek P6Spy.
<dependency> <groupId>com.github.gavlyukovskiy</groupId> <artifactId>p6spy-spring-boot-starter</artifactId> <version>1.6.1</version> </dependency>
Ist die Bibliothek eingebunden, dann gibt sie nicht nur die SQL Anweisung aus, sondern fügt die aktuellen Anfragewerte direkt in die Anweisung ein. Dies macht die Fehlersuche für den Entwickler sehr viel einfacher, da die tatsächlichen Werte dem SQL Aufruf direkt zugeordnet sind. Bei großen Anweisungen mit vielen Parametern, die auch noch parallel ausgeführt werden, ein Segen beim Debuggen.
p6spy : #1607863392610 | took 1ms | statement | connection 5| url jdbc:h2:mem:7179fcdf-dbce-47b8-9d07-9471d7173502 call next value for hibernate_sequence call next value for hibernate_sequence; p6spy : #1607863392629 | took 0ms | statement | connection 5| url jdbc:h2:mem:7179fcdf-dbce-47b8-9d07-9471d7173502 insert into holiday (name, id) values (?, ?) insert into holiday (name, id) values (NULL, 1); p6spy : #1607863392712 | took 0ms | statement | connection 6| url jdbc:h2:mem:7179fcdf-dbce-47b8-9d07-9471d7173502 select holiday0_.id as id1_0_, holiday0_.name as name2_0_ from holiday holiday0_ select holiday0_.id as id1_0_, holiday0_.name as name2_0_ from holiday holiday0_;
Die Ausgabe von P6Spy liefert auch noch einige weitere nützliche Informationen und kann ähnlich wie der Hibernate Logger über die Log-Level gesteuert werden.