3一般的なHibernateパフォーマンスの問題とログファイルでそれらを見つける方法
1. 序章
Hibernateのパフォーマンスの悪さに関する苦情のいくつかを読んだことがあるか、自分で苦労している可能性があります。 私は15年以上Hibernateを使用しており、これらの問題を十分に経験しています。
何年にもわたって、これらの問題は回避でき、ログファイルで多くの問題を見つけることができることを学びました。 この投稿では、そのうちの3つを見つけて修正する方法を紹介します。
2. パフォーマンスの問題を見つけて修正する
2.1. 本番環境でSQLステートメントをログに記録する
最初のパフォーマンスの問題は非常に簡単に見つけられ、無視されることがよくあります。 これは、実稼働環境でのSQLステートメントのロギングです。
いくつかのログステートメントを書くことは大したことのように聞こえません、そしてそれを正確に行う多くのアプリケーションがそこにあります。 ただし、Hibernate構成でshow_sqlパラメーターをtrueに設定した場合、Hibernateが行うように、特にSystem.out.printlnを介した場合は非常に非効率的です。
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=?
私のプロジェクトの1つでは、show_sqlをfalseに設定することで、数分以内にパフォーマンスを20%向上させました。 それはあなたが次のスタンドアップミーティングで報告したい種類の成果です🙂
このパフォーマンスの問題を修正する方法は明らかです。 構成を開くだけです(例: あなたのpersistence.xmlファイル)そしてshow_sqlパラメータをfalseに設定します。 とにかく、本番環境ではこの情報は必要ありません。
ただし、開発中に必要になる場合があります。 そうでない場合は、2つの異なるHibernate構成を使用します(使用しないでください)。そこでもSQLステートメントのロギングを非アクティブ化します。 そのための解決策は、ランタイム環境の特定の要件に最適化された2つの異なるログ構成を開発と本番環境に使用することです。
開発構成
開発構成は、Hibernateがデータベースとどのように相互作用するかを確認できるように、できるだけ多くの有用な情報を提供する必要があります。 したがって、少なくとも、生成されたSQLステートメントを開発構成に記録する必要があります。 これを行うには、org.hibernate.SQLカテゴリのDEBUGメッセージをアクティブにします。 バインドパラメータの値も確認する場合は、org.hibernate.type.descriptor.sqlのログレベルを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
次のコードスニペットは、Hibernateがこのログ構成で書き込むログメッセージの例を示しています。 ご覧のとおり、実行されたSQLクエリと、設定および取得されたすべてのパラメータ値に関する詳細情報を取得できます。
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は、Hibernate統計をアクティブ化すると、セッションに関するより多くの内部情報を提供します。 これを行うには、システムプロパティhibernate.generate_statisticsをtrueに設定します。
ただし、開発環境またはテスト環境の統計のみをアクティブ化してください。 これらすべての情報を収集すると、アプリケーションの速度が低下し、本番環境でこれをアクティブ化すると、パフォーマンスの問題が発生する可能性があります。
次のコードスニペットでいくつかの統計例を見ることができます。
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)
}
私は日常業務でこれらの統計を定期的に使用して、本番環境で発生する前にパフォーマンスの問題を見つけ、それについていくつかの投稿を書くことができました。 それでは、最も重要なものに焦点を当てましょう。
2行目から5行目は、Hibernateがこのセッション中に使用したJDBC接続とステートメントの数とそれに費やした時間を示しています。 これらの値を常に確認し、期待と比較する必要があります。
予想よりも多くのステートメントがある場合は、最も一般的なパフォーマンスの問題であるn+1選択の問題が発生している可能性があります。 ほぼすべてのアプリケーションで見つけることができ、より大きなデータベースで大きなパフォーマンスの問題が発生する可能性があります。 この問題については、次のセクションで詳しく説明します。
7行目から9行目は、Hibernateが第2レベルのキャッシュとどのように相互作用したかを示しています。 これはHibernateの3つのキャッシュの1つであり、セッションに依存しない方法でエンティティを格納します。 アプリケーションで第2レベルを使用する場合は、これらの統計を常に監視して、Hibernateがそこからエンティティを取得するかどうかを確認する必要があります。
生産構成
本番構成はパフォーマンスを最適化する必要があり、緊急に必要とされないメッセージは避けてください。 一般に、これはエラーメッセージのみをログに記録する必要があることを意味します。 Log4jを使用する場合は、次の構成でこれを実現できます。
Log4jを使用する場合は、次の構成でこれを実現できます。
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 Select Issue
すでに説明したように、n+1選択の問題は最も一般的なパフォーマンスの問題です。 多くの開発者がこの問題のORマッピングの概念を非難していますが、完全に間違っているわけではありません。 しかし、Hibernateが遅延フェッチされた関係をどのように処理するかを理解していれば、簡単に回避できます。 したがって、この種の問題を回避するのは開発者の責任であるため、開発者も責任を負います。 それでは、最初にこの問題が存在する理由を説明し、次にそれを防ぐ簡単な方法を示します。 n + 1選択の問題に既に精通している場合は、ソリューションに直接ジャンプできます。
Hibernateは、エンティティ間の関係に非常に便利なマッピングを提供します。 関連するエンティティのタイプとそれを定義するためのいくつかの注釈を持つ属性が必要です。
@Entity
@Table(name = "purchaseOrder")
public class Order implements Serializable {
@OneToMany(mappedBy = "order", fetch = FetchType.LAZY)
private Set<OrderItem> items = new HashSet<OrderItem>();
...
}
データベースからOrderエンティティをロードするときは、 getItems()メソッドを呼び出すだけで、この注文のすべてのアイテムを取得できます。 Hibernateは、データベースから関連するOrderItemエンティティを取得するために必要なデータベースクエリを非表示にします。
Hibernateを使い始めたとき、ほとんどの関係に FetchType.LAZY を使用する必要があり、これがto-many関係のデフォルトであることをおそらく学びました。 これは、関係をマップする属性を使用する場合にのみ、関連するエンティティをフェッチするようにHibernateに指示します。 一般に、必要なデータのみをフェッチすることは良いことですが、各関係を初期化するためにHibernateが追加のクエリを実行する必要もあります。 次のコードスニペットのように、エンティティのリストで作業する場合、これにより膨大な数のクエリが発生する可能性があります。
List<Order> 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());
}
この数行のコードで数百または数千ものデータベースクエリが作成されるとは思わないでしょう。 ただし、OrderItemエンティティとの関係にFetchType.LAZYを使用すると、次のようになります。
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は1つのクエリを実行してすべてのOrderエンティティを取得し、n個のOrderエンティティごとに追加のクエリを実行してorderItem関係を初期化します。 これで、この種の問題がn + 1 select問題と呼ばれる理由と、それが大きなパフォーマンスの問題を引き起こす可能性がある理由がわかりました。
さらに悪いことに、Hibernateの統計をチェックしていないと、小さなテストデータベースで認識されないことがよくあります。 テストデータベースに多くの注文が含まれていない場合、コードスニペットは数十のクエリのみを必要とします。 しかし、それらを数千個含む生産的なデータベースを使用する場合、それは完全に異なります。
これらの問題は簡単に回避できると先に述べました。 そしてそれは本当です。 データベースからOrderエンティティを選択するときは、orderItem関係を初期化する必要があります。
ただし、ビジネスコードでリレーションシップを使用し、FetchType.EAGERを使用して関連エンティティを常にフェッチしない場合にのみ実行してください。 これは、n+1の問題を別のパフォーマンスの問題に置き換えるだけです。
@NamedEntityGraphとの関係を初期化します
関係を初期化するためのいくつかの異なるオプションがあります。 私は、JPA2.1で導入された私のお気に入りの機能の1つである@NamedEntityGraphを使用することを好みます。 これは、Hibernateがデータベースからフェッチするエンティティのグラフを指定するクエリに依存しない方法を提供します。 次のコードスニペットでは、Hibernateがエンティティのitems属性を熱心にフェッチできるようにする単純なグラフの例を見ることができます。
@Entity
@Table(name = "purchase_order")
@NamedEntityGraph(
name = "graph.Order.items",
attributeNodes = @NamedAttributeNode("items"))
public class Order implements Serializable {
...
}
@NamedEntityGraphアノテーションを使用してエンティティグラフを定義するために行う必要のあることはそれほど多くありません。 グラフに一意の名前を指定するだけで、Hibernateが熱心にフェッチする属性ごとに1つの@NamedAttributeNodeアノテーションを指定する必要があります。 この例では、OrderといくつかのOrderItemエンティティ間の関係をマップするのはitems属性のみです。
これで、エンティティグラフを使用して、フェッチ動作または特定のクエリを制御できます。 したがって、@NamedEntityGraph定義に基づいてEntityGraphをインスタンス化し、 EntityManager.find()メソッドまたはクエリへのヒントとして提供する必要があります。 。 これは、データベースからID1のOrderエンティティを選択する次のコードスニペットで行います。
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はこの情報を使用して、データベースからOrderエンティティの属性とエンティティグラフの属性を取得する1つのSQLステートメントを作成します。
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=<gen:0>,
path=blog.thoughts.on.java.jpa21.entity.graph.model.Order)
- CollectionAttributeFetchImpl(
collection=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items,
querySpaceUid=<gen:1>,
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=<gen:2>,
path=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items.<elements>)
- EntityAttributeFetchImpl(entity=blog.thoughts.on.java.jpa21.entity.graph.model.Product,
querySpaceUid=<gen:3>,
path=blog.thoughts.on.java.jpa21.entity.graph.model.Order.items.<elements>.product)
- QuerySpaces
- EntityQuerySpaceImpl(uid=<gen:0>, 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)) : <gen:0> -> <gen:1>
- CollectionQuerySpaceImpl(uid=<gen:1>,
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)) : <gen:1> -> <gen:2>
- EntityQuerySpaceImpl(uid=<gen:2>,
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)) : <gen:2> -> <gen:3>
- EntityQuerySpaceImpl(uid=<gen:3>,
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=?
ブログ投稿には1つの関係だけで十分ですが、実際のプロジェクトでは、より複雑なグラフを作成することをお勧めします。 それではやってみましょう。 もちろん、 @NamedAttributeNode アノテーションの配列を提供して、同じエンティティの複数の属性をフェッチできます。また、 @NamedSubGraph を使用して、追加レベルのエンティティのフェッチ動作を定義できます。 。 次のコードスニペットでこれを使用して、関連するすべての OrderItem エンティティだけでなく、各 OrderItem:のProductエンティティもフェッチします。
@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 {
...
}
ご覧のとおり、 @NamedSubGraph の定義は、@NamedEntityGraphの定義と非常によく似ています。 次に、 @NamedAttributeNode アノテーションでこのサブグラフを参照して、この特定の属性のフェッチ動作を定義できます。
これらのアノテーションの組み合わせにより、ユースケースで使用するすべての関係を初期化し、n+1の選択の問題を回避するために使用できる複雑なエンティティグラフを定義できます。 実行時にエンティティグラフを動的に指定する場合は、JavaAPIを介してこれを行うこともできます。
2.3. エンティティを1つずつ更新する
オブジェクト指向の方法で考えると、エンティティを1つずつ更新するのは非常に自然なことです。 更新するエンティティを取得し、他のオブジェクトで行うのと同じように、いくつかのセッターメソッドを呼び出して属性を変更するだけです。
このアプローチは、少数のエンティティのみを変更する場合に正常に機能します。 ただし、エンティティのリストを操作する場合は非常に非効率になり、ログファイルで簡単に見つけることができる3番目のパフォーマンスの問題です。 次のログファイルで確認できるように、完全に同じように見える一連のSQLUPDATEステートメントを探す必要があります。
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=?
データベースレコードのリレーショナル表現は、オブジェクト指向のユースケースよりもこれらのユースケースにはるかに適しています。 SQLを使用すると、変更するすべてのレコードを更新する1つのSQLステートメントを記述できます。
JPQL、 native SQL 、または CriteriaUpdate API を使用している場合は、Hibernateでも同じことができます。 3つすべてが非常に似ているので、この例ではJPQLを使用しましょう。
JPQL UPDATEステートメントは、SQLでわかっているのと同じ方法で定義できます。 更新するエンティティ、その属性の値を変更する方法、および影響を受けるエンティティを制限する方法をWHEREステートメントで定義するだけです。 次のコードスニペットでその例を見ることができます。ここでは、すべての製品の価格を10%引き上げています。
em.createQuery("UPDATE Product p SET p.price = p.price*0.1").executeUpdate();
HibernateはJPQLステートメントに基づいてSQLUPDATEステートメントを作成し、それをデータベースに送信して更新操作を実行します。
膨大な数のエンティティを更新する必要がある場合、このアプローチの方がはるかに高速であることは明らかです。 ただし、欠点もあります。 Hibernateは、更新操作の影響を受けるエンティティを認識せず、第1レベルのキャッシュを更新しません。 したがって、同じHibernateセッション内でJPQLステートメントを使用してエンティティを読み取ったり更新したりしないようにする必要があります。そうしないと、エンティティをデタッチしてキャッシュから削除する必要があります。
3. 概要
この投稿の中で、私はあなたに見せました
それらのうちの2つは、膨大な数のSQLステートメントが原因でした。 これは、Hibernateを使用している場合、パフォーマンスの問題の一般的な理由です。 HibernateはデータベースアクセスをAPIの背後に隠しているため、SQLステートメントの実際の数を推測するのが難しいことがよくあります。 したがって、永続性層に変更を加えるときは、実行されたSQLステートメントを常に確認する必要があります。