3 Häufige Leistungsprobleme im Ruhezustand und wie Sie sie in Ihrer Protokolldatei finden

1. Einleitung

Sie haben wahrscheinlich einige der Beschwerden über schlechte Leistung im Ruhezustand gelesen oder haben selbst mit einigen von ihnen zu kämpfen. Ich benutze Hibernate seit mehr als 15 Jahren und bin auf mehr als genug dieser Probleme gestoßen.

Im Laufe der Jahre habe ich gelernt, dass diese Probleme vermieden werden können und dass Sie viele davon in Ihrer Protokolldatei finden können. In diesem Beitrag möchte ich Ihnen zeigen, wie Sie 3 davon finden und beheben können.

2. Suchen und Beheben von Leistungsproblemen

2.1. Protokollieren Sie SQL-Anweisungen in der Produktion

Das erste Leistungsproblem ist extrem leicht zu erkennen und wird oft ignoriert. Es ist die Protokollierung von SQL-Anweisungen in einer Produktionsumgebung.

Das Schreiben einiger Protokollanweisungen klingt nicht nach einer großen Sache, und es gibt viele Anwendungen, die genau das tun. Es ist jedoch äußerst ineffizient, insbesondere über System.out.println, wie es Hibernate tut, wenn Sie den Parameter show_sql in Ihrer Hibernate-Konfiguration auf true setzen :

Hibernate: select order0_.id as id1_2_, order0_.orderNumber as orderNum2_2_, order0_.version as version3_2_ from purchaseOrder order0_ Hibernate: select items0_.order_id as order_id4_0_0_, items0_.id as id1_0_0_, items0_.id as id1_0_1_, items0_.order_id as order_id4_0_1_, items0_.product_id as product_5_0_1_, items0_.quantity as quantity2_0_1_, items0_.version as version3_0_1_ from OrderItem items0_ where items0_.order_id=? Hibernate: select items0_.order_id as order_id4_0_0_, items0_.id as id1_0_0_, items0_.id as id1_0_1_, items0_.order_id as order_id4_0_1_, items0_.product_id as product_5_0_1_, items0_.quantity as quantity2_0_1_, items0_.version as version3_0_1_ from OrderItem items0_ where items0_.order_id=? Hibernate: select items0_.order_id as order_id4_0_0_, items0_.id as id1_0_0_, items0_.id as id1_0_1_, items0_.order_id as order_id4_0_1_, items0_.product_id as product_5_0_1_, items0_.quantity as quantity2_0_1_, items0_.version as version3_0_1_ from OrderItem items0_ where items0_.order_id=?

In einem meiner Projekte habe ich die Leistung innerhalb weniger Minuten um 20% verbessert, indem ich show_sql auf false gesetzt habe . Das ist die Art von Leistung, über die Sie beim nächsten Stand-up-Meeting berichten möchten ?

Es ist ziemlich offensichtlich, wie Sie dieses Leistungsproblem beheben können. Öffnen Sie einfach Ihre Konfiguration (z. B. Ihre persistence.xml-Datei) und setzen Sie den Parameter show_sql auf false . Sie benötigen diese Informationen sowieso nicht in der Produktion.

Möglicherweise benötigen Sie sie jedoch während der Entwicklung. Wenn Sie dies nicht tun, verwenden Sie zwei verschiedene Hibernate-Konfigurationen (die Sie nicht sollten). Sie haben dort auch die SQL-Anweisungsprotokollierung deaktiviert. Die Lösung hierfür besteht darin, zwei verschiedene Protokollkonfigurationen für Entwicklung und Produktion zu verwenden, die für die spezifischen Anforderungen der Laufzeitumgebung optimiert sind.

Entwicklungskonfiguration

Die Entwicklungskonfiguration sollte so viele nützliche Informationen wie möglich enthalten, damit Sie sehen können, wie Hibernate mit der Datenbank interagiert. Sie sollten daher mindestens die generierten SQL-Anweisungen in Ihrer Entwicklungskonfiguration protokollieren. Sie können dies tun, indem Sie die DEBUG- Nachricht für die Kategorie org.hibernate.SQL aktivieren . Wenn Sie auch die Werte Ihrer Bindungsparameter anzeigen möchten, müssen Sie die Protokollebene von org.hibernate.type.descriptor.sql auf TRACE setzen :

log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.Target=System.out log4j.appender.stdout.layout=org.apache.log4j.PatternLayout log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%c] - %m%n log4j.rootLogger=info, stdout # basic log level for all messages log4j.logger.org.hibernate=info # SQL statements and parameters log4j.logger.org.hibernate.SQL=debug log4j.logger.org.hibernate.type.descriptor.sql=trace

Das folgende Codeausschnitt zeigt einige Beispielprotokollnachrichten, die Hibernate mit dieser Protokollkonfiguration schreibt. Wie Sie sehen können, erhalten Sie detaillierte Informationen über die ausgeführte SQL-Abfrage und alle festgelegten und abgerufenen Parameterwerte:

23:03:22,246 DEBUG SQL:92 - select order0_.id as id1_2_, order0_.orderNumber as orderNum2_2_, order0_.version as version3_2_ from purchaseOrder order0_ where order0_.id=1 23:03:22,254 TRACE BasicExtractor:61 - extracted value ([id1_2_] : [BIGINT]) - [1] 23:03:22,261 TRACE BasicExtractor:61 - extracted value ([orderNum2_2_] : [VARCHAR]) - [order1] 23:03:22,263 TRACE BasicExtractor:61 - extracted value ([version3_2_] : [INTEGER]) - [0]

Hibernate bietet Ihnen viel mehr interne Informationen zu einer Sitzung, wenn Sie die Hibernate-Statistik aktivieren. Sie können dies tun, indem Sie die Systemeigenschaft hibernate.generate_statistics auf true setzen.

Bitte aktivieren Sie jedoch nur die Statistiken Ihrer Entwicklungs- oder Testumgebung. Das Sammeln all dieser Informationen verlangsamt Ihre Anwendung und Sie können Ihre Leistungsprobleme selbst verursachen, wenn Sie diese in der Produktion aktivieren.

Einige Beispielstatistiken finden Sie im folgenden Codeausschnitt:

23:04:12,123 INFO StatisticalLoggingSessionEventListener:258 - Session Metrics { 23793 nanoseconds spent acquiring 1 JDBC connections; 0 nanoseconds spent releasing 0 JDBC connections; 394686 nanoseconds spent preparing 4 JDBC statements; 2528603 nanoseconds spent executing 4 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; 9700599 nanoseconds spent executing 1 flushes (flushing a total of 9 entities and 3 collections); 42921 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections) }

Ich verwende diese Statistiken regelmäßig in meiner täglichen Arbeit, um Leistungsprobleme zu finden, bevor sie in der Produktion auftreten, und ich könnte mehrere Posts darüber schreiben. Konzentrieren wir uns also nur auf die wichtigsten.

Die Zeilen 2 bis 5 zeigen Ihnen, wie viele JDBC-Verbindungen und -Anweisungen im Ruhezustand während dieser Sitzung verwendet wurden und wie viel Zeit dafür aufgewendet wurde. Sie sollten sich diese Werte immer ansehen und sie mit Ihren Erwartungen vergleichen.

Wenn es viel mehr Aussagen gibt als erwartet, haben Sie höchstwahrscheinlich das häufigste Leistungsproblem, das n + 1-Auswahlproblem. Sie finden es in fast allen Anwendungen und es kann zu großen Leistungsproblemen in einer größeren Datenbank kommen. Ich erkläre dieses Problem im nächsten Abschnitt ausführlicher.

Die Zeilen 7 bis 9 zeigen, wie Hibernate mit dem Cache der 2. Ebene interagierte. Dies ist einer der drei Caches von Hibernate und speichert Entitäten sitzungsunabhängig. Wenn Sie die 2. Ebene in Ihrer Anwendung verwenden, sollten Sie diese Statistiken immer überwachen, um festzustellen, ob Hibernate die Entitäten von dort erhält.

Produktionskonfiguration

Die Produktionskonfiguration sollte auf Leistung optimiert sein und keine Nachrichten erfordern, die nicht dringend benötigt werden. Im Allgemeinen bedeutet dies, dass Sie nur Fehlermeldungen protokollieren sollten. Wenn Sie Log4j verwenden, können Sie dies mit der folgenden Konfiguration erreichen:

Wenn Sie Log4j verwenden, können Sie dies mit der folgenden Konfiguration erreichen:

log4j.appender.stdout=org.apache.log4j.ConsoleAppender log4j.appender.stdout.Target=System.out log4j.appender.stdout.layout=org.apache.log4j.PatternLayout log4j.appender.stdout.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%c] - %m%n log4j.rootLogger=info, stdout # basic log level for all messages log4j.logger.org.hibernate=error

2.2. N + 1 Problem auswählen

Wie ich bereits erklärt habe, ist das Problem mit der Auswahl von n + 1 das häufigste Leistungsproblem. Viele Entwickler machen das OR-Mapping-Konzept für dieses Problem verantwortlich, und sie liegen nicht völlig falsch. Sie können dies jedoch leicht vermeiden, wenn Sie verstehen, wie Hibernate träge Beziehungen abruft. Der Entwickler ist daher ebenfalls schuld, da es in seiner Verantwortung liegt, solche Probleme zu vermeiden. Lassen Sie mich zunächst erklären, warum dieses Problem besteht, und Ihnen dann einen einfachen Weg zeigen, es zu verhindern. Wenn Sie bereits mit den n + 1-Auswahlproblemen vertraut sind, können Sie direkt zur Lösung springen.

Der Ruhezustand bietet eine sehr bequeme Zuordnung für Beziehungen zwischen Entitäten. Sie benötigen lediglich ein Attribut mit dem Typ der zugehörigen Entität und einige Anmerkungen, um es zu definieren:

@Entity @Table(name = "purchaseOrder") public class Order implements Serializable { @OneToMany(mappedBy = "order", fetch = FetchType.LAZY) private Set items = new HashSet(); ... }

Wenn Sie jetzt eine Order- Entität aus der Datenbank laden , müssen Sie nur die Methode getItems () aufrufen , um alle Artikel dieser Order abzurufen . Im Ruhezustand werden die erforderlichen Datenbankabfragen ausgeblendet , um die zugehörigen OrderItem- Entitäten aus der Datenbank abzurufen .

Als Sie mit dem Ruhezustand begonnen haben, haben Sie wahrscheinlich gelernt, dass Sie FetchType.LAZY für die meisten Beziehungen verwenden sollten und dass dies die Standardeinstellung für zu viele Beziehungen ist. Dadurch wird Hibernate angewiesen, die zugehörigen Entitäten nur abzurufen, wenn Sie das Attribut verwenden, das die Beziehung abbildet. Es ist im Allgemeinen eine gute Sache, nur die Daten abzurufen, die Sie benötigen. Außerdem muss der Ruhezustand eine zusätzliche Abfrage ausführen, um jede Beziehung zu initialisieren. Dies kann zu einer großen Anzahl von Abfragen führen, wenn Sie an einer Liste von Entitäten arbeiten, wie ich es im folgenden Codeausschnitt tue:

List orders = em.createQuery("SELECT o FROM Order o").getResultList(); for (Order order : orders) { log.info("Order: " + order.getOrderNumber()); log.info("Number of items: " + order.getItems().size()); }

Sie würden wahrscheinlich nicht erwarten, dass diese wenigen Codezeilen Hunderte oder sogar Tausende von Datenbankabfragen erstellen können. Dies ist jedoch der Fall, wenn Sie FetchType.LAZY für die Beziehung zur OrderItem- Entität verwenden:

22:47:30,065 DEBUG SQL:92 - select order0_.id as id1_2_, order0_.orderNumber as orderNum2_2_, order0_.version as version3_2_ from purchaseOrder order0_ 22:47:30,136 INFO NamedEntityGraphTest:58 - Order: order1 22:47:30,140 DEBUG SQL:92 - select items0_.order_id as order_id4_0_0_, items0_.id as id1_0_0_, items0_.id as id1_0_1_, items0_.order_id as order_id4_0_1_, items0_.product_id as product_5_0_1_, items0_.quantity as quantity2_0_1_, items0_.version as version3_0_1_ from OrderItem items0_ where items0_.order_id=? 22:47:30,171 INFO NamedEntityGraphTest:59 - Number of items: 2 22:47:30,171 INFO NamedEntityGraphTest:58 - Order: order2 22:47:30,172 DEBUG SQL:92 - select items0_.order_id as order_id4_0_0_, items0_.id as id1_0_0_, items0_.id as id1_0_1_, items0_.order_id as order_id4_0_1_, items0_.product_id as product_5_0_1_, items0_.quantity as quantity2_0_1_, items0_.version as version3_0_1_ from OrderItem items0_ where items0_.order_id=? 22:47:30,174 INFO NamedEntityGraphTest:59 - Number of items: 2 22:47:30,174 INFO NamedEntityGraphTest:58 - Order: order3 22:47:30,174 DEBUG SQL:92 - select items0_.order_id as order_id4_0_0_, items0_.id as id1_0_0_, items0_.id as id1_0_1_, items0_.order_id as order_id4_0_1_, items0_.product_id as product_5_0_1_, items0_.quantity as quantity2_0_1_, items0_.version as version3_0_1_ from OrderItem items0_ where items0_.order_id=? 22:47:30,176 INFO NamedEntityGraphTest:59 - Number of items: 2

Hibernate performs one query to get all Order entities and an additional one for each of the n Order entities to initialize the orderItem relationship. So you now know why this kind of issue is called n+1 select issue and why it can create huge performance problems.

What makes it even worse is, that you often don’t recognize it on a small test database, if you haven’t checked your Hibernate statistics. The code snippet requires only a few dozen queries if the test database doesn’t contain a lot of orders. But that will be completely different if you use your productive database which contains several thousand of them.

I said earlier that you can easily avoid these issues. And that’s true. You just have to initialize the orderItem relationship when you select the Order entities from the database.

But please, only do that, if you use the relationship in your business code and don’t use FetchType.EAGER to always fetch the related entities. That just replaces your n+1 issue with another performance problem.

Initialize a Relationships with a @NamedEntityGraph

There are several different options to initialize relationships. I prefer to use a @NamedEntityGraph which is is one of my favorite features introduced in JPA 2.1. It provides a query independent way to specify a graph of entities which Hibernate shall fetch from the database. In following code snippet, you can see an example of a simple graph that lets Hibernate eagerly fetch the items attribute of an entity:

@Entity @Table(name = "purchase_order") @NamedEntityGraph( name = "graph.Order.items", attributeNodes = @NamedAttributeNode("items")) public class Order implements Serializable { ... }

There isn’t much you need to do to define an entity graph with a @NamedEntityGraph annotation. You just have to provide a unique name for the graph and one @NamedAttributeNode annotation for each attribute Hibernate shall fetch eagerly. In this example, it’s only the items attribute which maps the relationship between an Order and several OrderItem entities.

Now you can use the entity graph to control the fetching behaviour or a specific query. You, therefore, have to instantiate an EntityGraph based on the @NamedEntityGraph definition and provide it as a hint to the EntityManager.find() method or your query. I do this in the following code snippet where I select the Order entity with id 1 from the database:

EntityGraph graph = this.em.getEntityGraph("graph.Order.items"); Map hints = new HashMap(); hints.put("javax.persistence.fetchgraph", graph); return this.em.find(Order.class, 1L, hints);

Hibernate uses this information to create one SQL statement which gets the attributes of the Order entity and the attributes of the entity graph from the database:

17:34:51,310 DEBUG [org.hibernate.loader.plan.build.spi.LoadPlanTreePrinter] (pool-2-thread-1) LoadPlan(entity=blog.thoughts.on.java.jpa21.entity.graph.model.Order) - Returns - EntityReturnImpl( entity=blog.thoughts.on.java.jpa21.entity.graph.model.Order, querySpaceUid=, path=blog.thoughts.on.java.jpa21.entity.graph.model.Order) - CollectionAttributeFetchImpl( collection=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items, querySpaceUid=, path=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items) - (collection element) CollectionFetchableElementEntityGraph( entity=blog.thoughts.on.java.jpa21.entity.graph.model.OrderItem, querySpaceUid=, path=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items.) - EntityAttributeFetchImpl(entity=blog.thoughts.on.java.jpa21.entity.graph.model.Product, querySpaceUid=, path=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items..product) - QuerySpaces - EntityQuerySpaceImpl(uid=, entity=blog.thoughts.on.java.jpa21.entity.graph.model.Order) - SQL table alias mapping - order0_ - alias suffix - 0_ - suffixed key columns - {id1_2_0_} - JOIN (JoinDefinedByMetadata(items)) :  ->  - CollectionQuerySpaceImpl(uid=, collection=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items) - SQL table alias mapping - items1_ - alias suffix - 1_ - suffixed key columns - {order_id4_2_1_} - entity-element alias suffix - 2_ - 2_entity-element suffixed key columns - id1_0_2_ - JOIN (JoinDefinedByMetadata(elements)) :  ->  - EntityQuerySpaceImpl(uid=, entity=blog.thoughts.on.java.jpa21.entity.graph.model.OrderItem) - SQL table alias mapping - items1_ - alias suffix - 2_ - suffixed key columns - {id1_0_2_} - JOIN (JoinDefinedByMetadata(product)) :  ->  - EntityQuerySpaceImpl(uid=, entity=blog.thoughts.on.java.jpa21.entity.graph.model.Product) - SQL table alias mapping - product2_ - alias suffix - 3_ - suffixed key columns - {id1_1_3_} 17:34:51,311 DEBUG [org.hibernate.loader.entity.plan.EntityLoader] (pool-2-thread-1) Static select for entity blog.thoughts.on.java.jpa21.entity.graph.model.Order [NONE:-1]: select order0_.id as id1_2_0_, order0_.orderNumber as orderNum2_2_0_, order0_.version as version3_2_0_, items1_.order_id as order_id4_2_1_, items1_.id as id1_0_1_, items1_.id as id1_0_2_, items1_.order_id as order_id4_0_2_, items1_.product_id as product_5_0_2_, items1_.quantity as quantity2_0_2_, items1_.version as version3_0_2_, product2_.id as id1_1_3_, product2_.name as name2_1_3_, product2_.version as version3_1_3_ from purchase_order order0_ left outer join OrderItem items1_ on order0_.id=items1_.order_id left outer join Product product2_ on items1_.product_id=product2_.id where order0_.id=?

Initializing only one relationship is good enough for a blog post but in a real project, you will most likely want to build more complex graphs. So let's do that.

You can, of course, provide an array of @NamedAttributeNode annotations to fetch multiple attributes of the same entity and you can use @NamedSubGraph to define the fetching behaviour for an additional level of entities. I use that in the following code snippet to fetch not only all related OrderItem entities but also the Product entity for each OrderItem:

@Entity @Table(name = "purchase_order") @NamedEntityGraph( name = "graph.Order.items", attributeNodes = @NamedAttributeNode(value = "items", subgraph = "items"), subgraphs = @NamedSubgraph(name = "items", attributeNodes = @NamedAttributeNode("product"))) public class Order implements Serializable { ... }

As you can see, the definition of a @NamedSubGraph is very similar to the definition of a @NamedEntityGraph. You can then reference this subgraph in a @NamedAttributeNode annotation to define the fetching behaviour for this specific attribute.

The combination of these annotations allows you to define complex entity graphs which you can use to initialize all relationships you use in your use case and avoid n+1 select issues. If you want to specify your entity graph dynamically at runtime, you can do this also via a Java API.

2.3. Update Entities One by One

Updating entities one by one feels very natural if you think in an object oriented way. You just get the entities you want to update and call a few setter methods to change their attributes like you do it with any other object.

This approach works fine if you only change a few entities. But it gets very inefficient when you work with a list of entities and is the third performance issues you can easily spot in your log file. You just have to look for a bunch SQL UPDATE statements that look completely the same, as you can see in the following log file:

22:58:05,829 DEBUG SQL:92 - select product0_.id as id1_1_, product0_.name as name2_1_, product0_.price as price3_1_, product0_.version as version4_1_ from Product product0_ 22:58:05,883 DEBUG SQL:92 - update Product set name=?, price=?, version=? where id=? and version=? 22:58:05,889 DEBUG SQL:92 - update Product set name=?, price=?, version=? where id=? and version=? 22:58:05,891 DEBUG SQL:92 - update Product set name=?, price=?, version=? where id=? and version=? 22:58:05,893 DEBUG SQL:92 - update Product set name=?, price=?, version=? where id=? and version=? 22:58:05,900 DEBUG SQL:92 - update Product set name=?, price=?, version=? where id=? and version=?

The relational representation of the database records is a much better fit for these use cases than the object oriented one. With SQL, you could just write one SQL statement that updates all the records you want to change.

You can do the same with Hibernate if you use JPQL, native SQL or the CriteriaUpdate API. All 3 of very similar, so let’s use JPQL in this example.

You can define a JPQL UPDATE statement in a similar way as you know it from SQL. You just define which entity you want to update, how to change the values of its attributes and limit the affected entities in the WHERE statement.

You can see an example of it in the following code snippet where I increase the price of all products by 10%:

em.createQuery("UPDATE Product p SET p.price = p.price*0.1").executeUpdate();

Hibernate creates an SQL UPDATE statement based on the JPQL statement and sends it to the database which performs the update operation.

It’s pretty obvious that this approach is a lot faster if you have to update a huge number entities. But it also has a drawback. Hibernate doesn’t know which entities are affected by the update operation and doesn’t update its 1st level cache. You should, therefore, make sure not to read and update an entity with a JPQL statement within the same Hibernate Session or you have to detach it to remove it from the cache.

3. Summary

Within this post, I've shown you 3 Hibernate performance issues which you can find in your log files.

2 von ihnen wurden durch eine große Anzahl von SQL-Anweisungen verursacht. Dies ist ein häufiger Grund für Leistungsprobleme, wenn Sie mit Hibernate arbeiten. Im Ruhezustand wird der Datenbankzugriff hinter der API ausgeblendet, sodass es häufig schwierig ist, die tatsächliche Anzahl der SQL-Anweisungen zu erraten. Sie sollten daher immer die ausgeführten SQL-Anweisungen überprüfen, wenn Sie eine Änderung an Ihrer Persistenzschicht vornehmen.