3 Problemi comuni di prestazioni di Hibernate e come trovarli nel file di registro

1. Introduzione

Probabilmente hai letto alcune delle lamentele sulle cattive prestazioni di Hibernate o forse hai lottato con alcune di esse da solo. Uso Hibernate da più di 15 anni e ho riscontrato più che abbastanza di questi problemi.

Negli anni ho imparato che questi problemi possono essere evitati e che puoi trovarne molti nel tuo file di registro. In questo post, voglio mostrarti come puoi trovare e sistemare 3 di loro.

2. Trova e risolvi i problemi di prestazioni

2.1. Registra istruzioni SQL in produzione

Il primo problema di prestazioni è estremamente facile da individuare e spesso ignorato. È la registrazione delle istruzioni SQL in un ambiente di produzione.

Scrivere alcune istruzioni di registro non sembra un grosso problema e ci sono molte applicazioni là fuori che fanno esattamente questo. Ma è estremamente inefficiente, specialmente tramite System.out.println come Hibernate lo fa se si imposta il parametro show_sql nella configurazione di Hibernate su true :

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 uno dei miei progetti, ho migliorato le prestazioni del 20% in pochi minuti impostando show_sql su false . Questo è il tipo di risultato che ti piace riportare nella prossima riunione in piedi ?

È abbastanza ovvio come risolvere questo problema di prestazioni. Basta aprire la configurazione (ad esempio il file persistence.xml) e impostare il parametro show_sql su false . Non hai comunque bisogno di queste informazioni in produzione.

Ma potresti averne bisogno durante lo sviluppo. Se non lo fai, usi 2 diverse configurazioni di Hibernate (cosa che non dovresti) e hai disattivato anche la registrazione dell'istruzione SQL. La soluzione è utilizzare 2 diverse configurazioni di log per lo sviluppo e la produzione ottimizzate per i requisiti specifici dell'ambiente di runtime.

Configurazione di sviluppo

La configurazione di sviluppo dovrebbe fornire quante più informazioni utili possibili in modo da poter vedere come Hibernate interagisce con il database. È quindi necessario registrare almeno le istruzioni SQL generate nella configurazione di sviluppo. Puoi farlo attivando il messaggio DEBUG per la categoria org.hibernate.SQL . Se vuoi vedere anche i valori dei tuoi parametri di bind, devi impostare il livello di log di org.hibernate.type.descriptor.sql su TRACE :

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

Il frammento di codice seguente mostra alcuni messaggi di registro di esempio che Hibernate scrive con questa configurazione di registro. Come puoi vedere, ottieni informazioni dettagliate sulla query SQL eseguita e tutti i valori dei parametri impostati e recuperati:

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 ti fornisce molte più informazioni interne su una sessione se attivi le statistiche di Hibernate. Puoi farlo impostando la proprietà di sistema hibernate.generate_statistics su true.

Ma per favore, attiva le statistiche solo sul tuo ambiente di sviluppo o di test. La raccolta di tutte queste informazioni rallenta la tua applicazione e potresti creare tu stesso i tuoi problemi di prestazioni se la attivi in ​​produzione.

Puoi vedere alcune statistiche di esempio nel seguente snippet di codice:

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) }

Uso regolarmente queste statistiche nel mio lavoro quotidiano per trovare problemi di prestazioni prima che si verifichino in produzione e potrei scrivere diversi post proprio su questo. Quindi concentriamoci solo su quelli più importanti.

Le righe da 2 a 5 mostrano quante connessioni JDBC e istruzioni Hibernate ha utilizzato durante questa sessione e quanto tempo ha impiegato su di essa. Dovresti sempre dare un'occhiata a questi valori e confrontarli con le tue aspettative.

Se ci sono molte più affermazioni di quelle che ti aspettavi, molto probabilmente hai il problema di prestazioni più comune, il problema di selezione n + 1. Puoi trovarlo in quasi tutte le applicazioni e potrebbe creare enormi problemi di prestazioni su un database più grande. Spiego questo problema in modo più dettagliato nella prossima sezione.

Le righe da 7 a 9 mostrano come Hibernate ha interagito con la cache di 2 ° livello. Questa è una delle 3 cache di Hibernate e memorizza le entità in modo indipendente dalla sessione. Se utilizzi il 2 ° livello nella tua applicazione, dovresti sempre monitorare queste statistiche per vedere se Hibernate ottiene le entità da lì.

Configurazione di produzione

La configurazione di produzione dovrebbe essere ottimizzata per le prestazioni ed evitare messaggi non urgenti. In generale, ciò significa che dovresti registrare solo i messaggi di errore. Se usi Log4j, puoi ottenerlo con la seguente configurazione:

Se usi Log4j, puoi ottenerlo con la seguente configurazione:

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 Seleziona problema

Come ho già spiegato, il problema di selezione n + 1 è il problema di prestazioni più comune. Molti sviluppatori incolpano il concetto di OR-Mapping per questo problema e non si sbagliano completamente. Ma puoi facilmente evitarlo se capisci come Hibernate tratta le relazioni pigramente recuperate. La colpa è quindi anche dello sviluppatore perché è sua responsabilità evitare questo tipo di problemi. Quindi lascia che ti spieghi prima perché questo problema esiste e poi ti mostri un modo semplice per prevenirlo. Se hai già familiarità con i problemi di selezione n + 1, puoi passare direttamente alla soluzione.

Hibernate fornisce una mappatura molto conveniente per le relazioni tra le entità. Hai solo bisogno di un attributo con il tipo dell'entità correlata e alcune annotazioni per definirla:

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

Quando ora carichi un'entità Order dal database, devi solo chiamare il metodo getItems () per ottenere tutti gli elementi di questo ordine. Hibernate nasconde le query di database richieste per ottenere le entità OrderItem correlate dal database.

Quando hai iniziato con Hibernate, probabilmente hai imparato che dovresti usare FetchType.LAZY per la maggior parte delle relazioni e che è l'impostazione predefinita per le relazioni a molti. Questo dice a Hibernate di recuperare solo le entità correlate se usi l'attributo che mappa la relazione. Recuperare solo i dati necessari è una buona cosa in generale, ma richiede anche che Hibernate esegua una query aggiuntiva per inizializzare ogni relazione. Ciò può comportare un numero enorme di query, se lavori su un elenco di entità, come faccio nel seguente frammento di codice:

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()); }

Probabilmente non ti aspetteresti che queste poche righe di codice possano creare centinaia o addirittura migliaia di query di database. Ma lo fa se usi FetchType.LAZY per la relazione con l' entità OrderItem :

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 di questi sono stati causati da un numero enorme di istruzioni SQL. Questo è un motivo comune per problemi di prestazioni, se lavori con Hibernate. Hibernate nasconde l'accesso al database dietro la sua API e questo rende spesso difficile indovinare il numero effettivo di istruzioni SQL. Pertanto, dovresti sempre controllare le istruzioni SQL eseguite quando apporti una modifica al tuo livello di persistenza.