3 Masalah Prestasi Hibernate yang Umum dan Cara Menemukannya dalam Fail Log Anda

1. Pengenalan

Anda mungkin pernah membaca beberapa aduan mengenai prestasi Hibernate yang buruk atau mungkin anda sendiri yang menghadapi masalah tersebut. Saya telah menggunakan Hibernate selama lebih dari 15 tahun sekarang dan saya menghadapi lebih daripada cukup masalah ini.

Selama bertahun-tahun, saya mengetahui bahawa masalah ini dapat dielakkan dan anda dapat menjumpai banyak masalah di dalam fail log anda. Dalam catatan ini, saya ingin menunjukkan kepada anda bagaimana anda dapat mencari dan memperbaiki 3 daripadanya.

2. Cari dan Selesaikan Masalah Prestasi

2.1. Log Penyataan SQL dalam Pengeluaran

Isu prestasi pertama sangat mudah dilihat dan sering diabaikan. Ini adalah log penyataan SQL dalam persekitaran pengeluaran.

Menulis beberapa pernyataan log tidak kedengaran seperti masalah besar, dan ada banyak aplikasi di luar sana yang melakukan perkara itu. Tetapi ia sangat tidak berkesan, terutamanya melalui System.out.println kerana Hibernate melakukannya jika anda menetapkan parameter show_sql dalam konfigurasi Hibernate anda menjadi benar :

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=?

Dalam salah satu projek saya, saya meningkatkan prestasi sebanyak 20% dalam beberapa minit dengan menetapkan show_sql ke false . Itulah kejayaan yang ingin anda laporkan dalam perjumpaan seterusnya ?

Cukup jelas bagaimana anda dapat menyelesaikan masalah prestasi ini. Cukup buka konfigurasi anda (mis. Fail persistence.xml anda) dan tetapkan parameter show_sql ke false . Anda tidak memerlukan maklumat ini dalam pengeluaran.

Tetapi anda mungkin memerlukannya semasa pembangunan. Sekiranya tidak, anda menggunakan 2 konfigurasi Hibernate yang berbeza (yang tidak sepatutnya) anda juga mematikan penyataan penyataan SQL di sana. Penyelesaian untuk itu adalah dengan menggunakan 2 konfigurasi log yang berbeza untuk pengembangan dan produksi yang dioptimalkan untuk keperluan khusus lingkungan runtime.

Konfigurasi Pembangunan

Konfigurasi pembangunan harus memberikan seberapa banyak maklumat berguna sehingga anda dapat melihat bagaimana Hibernate berinteraksi dengan pangkalan data. Oleh itu anda sekurang-kurangnya harus log penyataan SQL yang dihasilkan dalam konfigurasi pembangunan anda. Anda boleh melakukannya dengan mengaktifkan mesej DEBUG untuk kategori org.hibernate.SQL . Sekiranya anda juga ingin melihat nilai parameter pengikat anda, anda harus menetapkan tahap log org.hibernate.type.descriptor.sql ke 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

Coretan kod berikut menunjukkan beberapa contoh mesej log yang Hibernate tulis dengan konfigurasi log ini. Seperti yang anda lihat, anda mendapat maklumat terperinci mengenai pertanyaan SQL yang dilaksanakan dan semua nilai parameter yang ditetapkan dan diambil:

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 memberi anda banyak maklumat dalaman mengenai Sesi sekiranya anda mengaktifkan statistik Hibernate. Anda boleh melakukan ini dengan menetapkan hibernate.generate_statistics sifat sistem menjadi benar.

Tetapi tolong, hanya aktifkan statistik pembangunan atau persekitaran ujian anda. Mengumpulkan semua maklumat ini melambatkan aplikasi anda dan anda mungkin akan menimbulkan masalah prestasi anda sendiri jika anda mengaktifkannya dalam pengeluaran.

Anda dapat melihat beberapa contoh statistik dalam coretan kod berikut:

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

Saya selalu menggunakan statistik ini dalam kerja harian saya untuk mencari masalah prestasi sebelum ia berlaku dalam pengeluaran dan saya dapat menulis beberapa catatan sahaja. Oleh itu, mari kita fokus pada perkara yang paling penting.

Garis 2 hingga 5 menunjukkan kepada anda berapa banyak sambungan dan pernyataan JDBC yang digunakan Hibernate semasa sesi ini dan berapa banyak masa yang dihabiskan untuknya. Anda harus selalu melihat nilai-nilai ini dan membandingkannya dengan jangkaan anda.

Sekiranya terdapat lebih banyak pernyataan daripada yang anda jangkakan, kemungkinan besar anda mempunyai masalah prestasi yang paling biasa, masalah pilih n + 1. Anda dapat menemuinya di hampir semua aplikasi, dan mungkin menimbulkan masalah prestasi besar pada pangkalan data yang lebih besar. Saya menerangkan masalah ini dengan lebih terperinci di bahagian seterusnya.

Garis 7 hingga 9 menunjukkan bagaimana Hibernate berinteraksi dengan cache tahap ke-2. Ini adalah salah satu daripada 3 cache Hibernate, dan menyimpan entiti secara sesi secara bebas. Sekiranya anda menggunakan tahap 2 dalam aplikasi anda, anda harus selalu memantau statistik ini untuk melihat apakah Hibernate mendapat entiti dari sana.

Konfigurasi Pengeluaran

Konfigurasi pengeluaran harus dioptimumkan untuk prestasi dan mengelakkan mesej yang tidak diperlukan segera. Secara amnya, ini bermakna anda hanya perlu log mesej ralat. Sekiranya anda menggunakan Log4j, anda boleh mencapainya dengan konfigurasi berikut:

Sekiranya anda menggunakan Log4j, anda boleh mencapainya dengan konfigurasi berikut:

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 Pilih Isu

Seperti yang telah saya jelaskan, masalah pilih n + 1 adalah masalah prestasi yang paling biasa. Banyak pembangun menyalahkan konsep OR-Mapping untuk masalah ini, dan mereka tidak salah sepenuhnya. Tetapi anda boleh menghindarinya dengan mudah jika anda memahami bagaimana Hibernate memperlakukan hubungan yang malas. Oleh itu, pemaju juga harus dipersalahkan kerana tanggungjawabnya untuk mengelakkan masalah seperti ini. Oleh itu, izinkan saya menerangkan terlebih dahulu mengapa masalah ini wujud dan kemudian tunjukkan cara mudah untuk mencegahnya. Sekiranya anda sudah biasa dengan masalah pilihan n + 1, anda boleh terus mencari penyelesaiannya.

Hibernate menyediakan pemetaan yang sangat sesuai untuk hubungan antara entiti. Anda hanya memerlukan atribut dengan jenis entiti yang berkaitan dan beberapa anotasi untuk menentukannya:

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

Apabila anda sekarang memuat entiti Pesanan dari pangkalan data, anda hanya perlu memanggil kaedah getItems () untuk mendapatkan semua item pesanan ini. Hibernate menyembunyikan pertanyaan pangkalan data yang diperlukan untuk mendapatkan entiti OrderItem yang berkaitan dari pangkalan data.

Semasa anda memulakan dengan Hibernate, anda mungkin mengetahui bahawa anda harus menggunakan FetchType.LAZY untuk kebanyakan hubungan dan bahawa ia adalah lalai untuk hubungan yang banyak. Ini memberitahu Hibernate hanya mengambil entiti yang berkaitan jika anda menggunakan atribut yang memetakan hubungan. Mengambil hanya data yang anda perlukan adalah sesuatu yang baik secara umum, tetapi ia juga memerlukan Hibernate untuk menjalankan pertanyaan tambahan untuk memulakan setiap hubungan. Ini boleh menghasilkan sejumlah besar pertanyaan, jika anda menggunakan senarai entiti, seperti yang saya lakukan dalam coretan kod berikut:

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

Anda mungkin tidak menyangka bahawa beberapa baris kod ini dapat membuat beratus-ratus atau bahkan ribuan pertanyaan pangkalan data. Tetapi ia berlaku jika anda menggunakan FetchType.LAZY untuk hubungan dengan entiti 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 daripadanya disebabkan oleh sebilangan besar pernyataan SQL. Ini adalah sebab biasa untuk masalah prestasi, jika anda bekerja dengan Hibernate. Hibernate menyembunyikan akses pangkalan data di belakang API-nya dan itu menjadikannya sukar untuk meneka jumlah penyataan SQL yang sebenarnya. Oleh itu, anda harus selalu memeriksa pernyataan SQL yang dilaksanakan semasa anda membuat perubahan pada tahap kegigihan anda.