Hibernate: Deutlich schneller dank @NamedEntityGraphBemerkenswerte Annotation

Eine Java-Applikation auf schneller Hardware und mit schneller Anbindung an den Datenbank-Cluster - und dennoch scheitert der SOAP-Service immer wieder am Zeitlimit von 60 Sekunden, dann kappt der Load Balancer offene Verbindungen. Wo sind die Zeitfresser?

Die zugrundeliegende Java-Applikation verwaltet Einheiten in einer Datenbank, die per Hibernate (als JPA-Implementierung) an die Java-Applikation angebunden ist. Eine Einheit (Unit) hat eine m:n-Assoziation mit Berechtigungen (Authorizations), welche in einer separaten Tabelle abgelegt sind.

Der SOAP-Service, den es nun zu optimieren galt, führte folgende Schritte aus:

  • Authentifizierung des Benutzers anhand Benutzername und Passwort
  • Abfragen von ca. 22.000 Einheiten-Datensätzen samt deren Berechtigungen aus der Datenbank
  • Konvertieren der Datensätze für den Versand via SOAP
  • Marshalling und Versand der Antwort

Einige dieser Schritte, wie beispielsweise das Marshalling oder die Authentifizierung, wurden in diesem Service natürlich nicht neu implementiert. Die Liste soll nur verdeutlichen, was alles erledigt werden muss, um eine Anfrage abzuarbeiten.

60-Sekunden-Limit

Die vorliegende Applikation ist auf einem Cluster unserer Applikationsplattform appNG installiert. Ein Load Balancer verteilt eingehende Anfragen auf alle Nodes innerhalb des Clusters. Der Load Balancer ist so konfiguriert, dass eine offene Verbindung nach spätestens 60 Sekunden unterbrochen wird.

Das bedeutet, dass die Übertragung der Antwort des Services zwingend innerhalb dieser 60 Sekunden beginnen muss. Genau dieses konnte die Applikation trotz ausreichend schneller Hardware und schneller Anbindung an den Datenbank-Cluster nicht sicherstellen.

Auf meiner (wenn auch bezüglich Laufzeit nicht vergleichbaren) Entwicklungsumgebung habe ich zunächst mit SoapUI ein paar Messungen durchgeführt, um die Ausgangssituation festzuhalten:

[...Soap11.unitExport:Request 8] in 44950ms (17755730 bytes)
[...Soap11.unitExport:Request 8] in 37042ms (17755730 bytes)
[...Soap11.unitExport:Request 8] in 37160ms (17755730 bytes)
[...Soap11.unitExport:Request 8] in 40836ms (17755730 bytes)

Auf meiner Entwicklungsumgebung dauert die Verarbeitung inklusive Übertragung aller Daten im Schnitt 39,975 Sekunden. Das war also der Referenzwert, an dem ich den Erfolg aller Optimierungsmaßnahmen messen konnte. Aufgrund verschiedener Faktoren ist der bei mir lokal gemessene Wert niedriger als der in der produktiven Umgebung, was aber für die qualitative Betrachtung des Erfolgs der Optimierungmaßnahmen keinen Unterschied macht.

Die Suche nach den Zeitfressern

Wenn man einen solchen Service optimieren möchte, gilt es erst einmal herauszufinden, welche Schritte am allermeisten Zeit verbrauchen. Hierzu finde ich es recht praktisch, das Logging mittels einer oder mehrerer StopWatches zu verbessern, um einmal einen groben Überblick zu bekommen. Diese Messung wurde in die Methode integriert, die die SOAP-Anfrage abarbeitet. Hierbei steht authentication für das Anmelden des Benutzers, fetch steht für das Laden aller notwendigen Daten aus der Datenbank und convert steht für das Konvertieren der Daten für den SOAP-Versand:

StopWatch '': running time (millis) = 37444
-----------------------------------------
ms     %     Task name
-----------------------------------------
00875  002%  authentication
36521  098%  fetch
00048  000%  convert

Es stellte sich heraus, dass das Ermitteln der Daten aus der Datenbank den größten Anteil ausmachte. Hier galt es also, einen tieferen Blick hineinzuwerfen.

Wie eingangs erwähnt ist die Applikation mittels Hibernate mit einer MySQL-Datenbank verbunden. Hibernate bietet den Vorteil, dass die Art und Weise, wie Datensätze abgefragt oder geschrieben werden, für den Java-Entwickler erst einmal nicht von Belang ist. Leider kann man, selbst wenn Hibernate seine Sache sehr gut macht, nicht automatisch davon ausgehen, dass die Queries, die sich Hibernate baut, auch immer optimal sind.

Oftmals sind dem unbedarften Entwickler auch wichtige Annotationen und Kniffe nicht vertraut, mit denen Hibernate selbst schon effizientere Abfragen erstellt - der Entwickler sieht ja auch nicht direkt, welche Queries ausgeführt werden. Dies wiederum kann aber auch durch ein erhöhtes Loglevel in der log4j-Konfigurationsdatei sichtbar gemacht werden.

log4j.logger.org.hibernate.SQL=DEBUG
log4j.logger.org.hibernate.type=TRACE

So wird schnell offensichtlich, was dem bequemen Entwickler bis dahin verborgen blieb: Wie oben schon erwähnt, hat eine Einheit eine Liste von Berechtigungen. Berechtigungs-Definitionen werden in einer separaten Tabelle abgelegt. Zwischen Einheit und Berechtigung besteht eine m:n Beziehung.

Wenn Hibernate nun angewiesen wird, 22.000 Datensätze von Einheiten samt deren Berechtigungen aus der Datenbank zu holen, so wird erst ein Query abgesetzt, welcher die Einheiten samt ihrer direkten Attribute ausliest, und dann noch pro Datensatz (also 22.000 mal) ein Query, der die Berechtigungen der jeweiligen Einheit ermittelt. Das kostet Zeit! Man nennt das auch das n+1-Select-Problem. Ehe man aber nun die Schuld bei Hibernate sucht, sollte man sich ein wenig Zeit nehmen, um potenzielle Fehler oder Nachlässigkeiten auf Entwicklerseite zu ergründen.

An dieser Stelle hatten wir schon, mit sehr wenig Aufand, einen recht hohen Erkenntnisgewinn, sodass erst einmal keine weiteren Messungen und Untersuchungen notwendig waren. Dennoch soll hier der JDBC-Performance-Logger nicht unerwähnt bleiben, der eine weitere, gute Option für genauere Untersuchungen in Bezug auf das Optimierungspotenzial von Datenbankabfragen ist. Er bietet zudem weit mehr Möglichkeiten, einzelne Queries auch im Hinblick auf Dauer und Häufigkeit zu analysieren. Außerdem kann man damit, im Gegensatz zum Log-Output von Hibernate, auch den wirklich abgesetzten Query samt seiner konkret verwendeten Daten sehen.

Named Entity Graphs

Würde man eine oben beschriebene Abfrage selbst neu entwickeln und ohne Hilfe von Abstraktionsebenen und Frameworks neu formulieren, so würde man sich mit einem mehr oder weniger komplexen Join behelfen, um das unnötig häufige Absetzen von Queries an die Datenbank zu vermeiden. Durch geschicktes Formulieren von Annotationen kann man auch Hibernate dazu bewegen, seine Abfragen zu optimieren. Das verwendete Feature heißt in diesem Fall @NamedEntityGraph.

@NamedEntityGraph(
    name = "unitWithAuthorizations",
    attributeNodes = { @NamedAttributeNode("authorizations") })
public class Unit {
...
}

Diese Annotation an unserer Klasse "Unit" definiert einen Abfragemodus, in dem Hibernate die Berechtigungen direkt mit ausliest. An der entsprechenden Abfragemethode der Spring Data JPA Repository Interface-Klasse wird Hibernate mitgeteilt, diesen Entity Graph auch zu verwenden:

public interface UnitRepository extends JpaRepository<Unit,Integer> {
    @EntityGraph("unitWithAuthorizations")
    List<Unit> findUnitsByCountry(Country c);
}

 Hibernate verwendet nun nur noch einen Query für die Abfrage aller Daten - und das spart Zeit:

[...Soap11.unitExport:Request 8] in 11357ms (17755730 bytes)
[...Soap11.unitExport:Request 8] in 6258ms (17755730 bytes)
[...Soap11.unitExport:Request 8] in 5019ms (17755730 bytes)
[...Soap11.unitExport:Request 8] in 5928ms (17755730 bytes)

Persistence Context

Nach der oben getätigten Optimierung fiel aber noch ein Weiteres auf. Eine StopWatch maß die einzelnen Schritte innerhalb der Methode, die die SOAP-Anfrage abarbeitet; eine weitere ausschließlich das Ausführen der Datenbankabfrage. Der Unterschied lag bei 300ms. Das klingt nicht nach viel, aber hier passiert nichts, außer dass die Methode verlassen wird.

Grund hierfür ist, dass die Methode, die die Daten aus der Datenbank ausliest, zu einer Klasse gehört, die mit @Transactional annotiert ist. Dadurch findet jeder Aufruf einer Methode in einem sogenannten Persistence Context statt. Bei Verlassen der Methode muss sichergestellt werden, dass Änderungen an einem der Objekte, die aus der Datenbank gelesen wurden, auch in die Datenbank geschrieben werden. Also muss jedes einzelne Objekt daraufhin untersucht werden.

Da diese Methode ausschließlich die Daten aus der Datenbank ausliest und weiterreicht, ist es sinnvoll, dies dem EntityManager mitzuteilen. In diesem Fall kann die Überprüfung der Objekte entfallen. Die richtige Annotation hierfür ist:

@Transactional(readOnly = true)
public List<Unit> getUnits() {
...
}

Wenn man dieses Thema weiter recherchiert, findet man in der Spring Dokumentation die Empfehlung, grundsätzlich die ganze Klasse mit dieser Annotation zu versehen. Nur dann, wenn man eine Methode hat, die definitiv Daten verändern soll, solle man das entsprechend kenntlich machen. Diesen Ansatz finde ich gut und werde ihn in meinem nächsten Projekt auf jeden Fall berücksichtigen.

Fazit

Während ich mich etwas tiefgreifender mit der Materie beschäftigte, habe ich durchaus noch Raum für Optimierungen gefunden, den ich vorher nicht für möglich gehalten hatte. Zum Einen, weil es bis dahin nicht notwendig war, die höchstmögliche Performance herauszuholen, weil in unserem Fall bisher nur ein paar dutzend Units auf einmal abgefragt wurden; zum Anderen, weil die bestehenden Frameworks einen guten und einfachen Einstieg bieten, der von vornherein für die meisten Use-Cases sehr gut funktioniert.

Wir haben durch die oben beschriebenen Maßnahmen die Zeit für das Abarbeiten und Übertragen der SOAP-Anfrage im Schnitt von 39,975 Sekunden auf 7,12 Sekunden reduziert - also eine Verbesserung um den Faktor 5,6.

Viel wichtiger ist in diesem Zusammenhang aber, dass dadurch im produktiven System die Nutzbarkeit des Services unter Beibehaltung der bestehenden Infrastruktur erst ermöglicht wurde.

Sie sind interessiert? Bitte melden Sie sich!

Tweet

@aiticon

Besuchen Sie uns

Frankfurt