Перейти к основному содержимому

3 распространенных проблемы с производительностью Hibernate и как их найти в файле журнала

· 14 мин. чтения

1. Введение

Вы, вероятно, читали некоторые из жалоб на плохую производительность Hibernate или, возможно, сами боролись с некоторыми из них. Я использую Hibernate уже более 15 лет, и я столкнулся с более чем достаточным количеством этих проблем.

С годами я понял, что этих проблем можно избежать и что многие из них можно найти в файле журнала. В этом посте я хочу показать вам, как вы можете найти и исправить 3 из них.

2. Найдите и устраните проблемы с производительностью

2.1. Записывать операторы SQL в рабочей среде

Первую проблему с производительностью очень легко обнаружить, и ее часто игнорируют. Это регистрация операторов SQL в производственной среде.

Написание некоторых операторов журнала не кажется чем-то большим, и существует множество приложений, которые делают именно это. Но это крайне неэффективно, особенно через System.out.println , поскольку Hibernate делает это, если вы установите для параметра show_sql в вашей конфигурации Hibernate значение 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=?

В одном из моих проектов я улучшил производительность на 20% за несколько минут, установив для show_sql значение false . Это то достижение, о котором вы хотели бы рассказать на следующем стендапе 🙂

Совершенно очевидно, как вы можете решить эту проблему с производительностью. Просто откройте свою конфигурацию (например, файл persistence.xml) и установите для параметра show_sql значение false . В любом случае вам не нужна эта информация в производстве.

Но они могут понадобиться вам во время разработки. Если вы этого не сделаете, вы используете 2 разные конфигурации Hibernate (чего вам не следует делать), вы также отключили ведение журнала операторов SQL. Решением для этого является использование двух разных конфигураций журналов для разработки и производства, которые оптимизированы для конкретных требований среды выполнения.

Конфигурация разработки

Конфигурация разработки должна предоставлять как можно больше полезной информации, чтобы вы могли видеть, как Hibernate взаимодействует с базой данных. Поэтому вы должны, по крайней мере, регистрировать сгенерированные операторы SQL в вашей конфигурации разработки. Вы можете сделать это, активировав сообщение DEBUG для категории org.hibernate.SQL . Если вы также хотите видеть значения ваших параметров привязки, вы должны установить уровень журнала 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 показывают, сколько JDBC-соединений и операторов использовал Hibernate во время этого сеанса и сколько времени он потратил на это. Вы всегда должны смотреть на эти значения и сравнивать их с вашими ожиданиями.

Если операторов намного больше, чем вы ожидали, скорее всего, у вас самая распространенная проблема с производительностью — проблема выбора n+1. Вы можете найти его почти во всех приложениях, и это может создать огромные проблемы с производительностью в большой базе данных. Я объясню этот вопрос более подробно в следующем разделе.

Строки с 7 по 9 показывают, как Hibernate взаимодействует с кешем 2-го уровня. Это один из трех кешей Hibernate, и он хранит сущности независимо от сеанса. Если вы используете 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 Выберите проблему

Как я уже объяснил, проблема выбора n+1 является наиболее распространенной проблемой производительности. Многие разработчики винят в этой проблеме концепцию OR-Mapping, и они не совсем не правы. Но вы можете легко избежать этого, если понимаете, как 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 для большинства отношений и что он используется по умолчанию для отношений «ко многим». Это говорит 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());
}

Вероятно, вы не ожидаете, что эти несколько строк кода могут создать сотни или даже тысячи запросов к базе данных. Но это так, если вы используете FetchType.LAZY для связи с сущностью 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 выполняет один запрос для получения всех сущностей Order и дополнительный для каждой из n сущностей Order для инициализации отношения orderItem . Итак, теперь вы знаете, почему такая проблема называется проблемой выбора n+1 и почему она может создавать огромные проблемы с производительностью.

Что еще хуже, так это то, что вы часто не узнаете его в небольшой тестовой базе данных, если вы не проверили свою статистику Hibernate. Фрагмент кода требует всего несколько десятков запросов, если в тестовой базе не так много заказов. Но все будет совсем по-другому, если вы будете использовать свою производительную базу данных, в которой их несколько тысяч.

Я уже говорил ранее, что вы можете легко избежать этих проблем. И это правда. Вам просто нужно инициализировать отношение orderItem при выборе объектов Order из базы данных.

Но, пожалуйста, делайте это только в том случае, если вы используете отношение в своем бизнес-коде и не используете FetchType.EAGER , чтобы всегда получать связанные объекты. Это просто заменяет вашу проблему n + 1 другой проблемой производительности.

Инициализировать отношения с помощью @NamedEntityGraph

Существует несколько различных вариантов инициализации отношений . Я предпочитаю использовать @NamedEntityGraph , который является одной из моих любимых функций, представленных в JPA 2.1 . Он предоставляет независимый от запроса способ указать граф сущностей, которые Hibernate будет извлекать из базы данных. В следующем фрагменте кода вы можете увидеть пример простого графа, который позволяет Hibernate жадно извлекать атрибут элементов объекта:

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

...
}

Для определения графа сущностей с помощью аннотации @NamedEntityGraph не так уж много нужно сделать . Вам просто нужно указать уникальное имя для графа и одну аннотацию @NamedAttributeNode для каждого атрибута, который Hibernate будет охотно извлекать. В этом примере только атрибут items отображает связь между Order и несколькими сущностями OrderItem .

Теперь вы можете использовать граф сущностей для управления поведением выборки или конкретным запросом. Поэтому вам необходимо создать экземпляр EntityGraph на основе определения @NamedEntityGraph и предоставить его в качестве подсказки для метода EntityManager.find() или вашего запроса. Я делаю это в следующем фрагменте кода, где я выбираю объект Order с идентификатором 1 из базы данных:

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 использует эту информацию для создания одного оператора SQL, который получает атрибуты объекта Order и атрибуты графа объекта из базы данных:

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

Инициализации только одного отношения достаточно для публикации в блоге, но в реальном проекте вы, скорее всего, захотите построить более сложные графики. Итак, давайте сделаем это.

Конечно, вы можете предоставить массив аннотаций @NamedAttributeNode для получения нескольких атрибутов одной и той же сущности, а также вы можете использовать @NamedSubGraph для определения поведения выборки для дополнительного уровня сущностей. Я использую это в следующем фрагменте кода, чтобы получить не только все связанные сущности OrderItem , но и сущность Product для каждого 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 {

...
}

Как видите, определение @NamedSubGraph очень похоже на определение @NamedEntityGraph . Затем вы можете сослаться на этот подграф в аннотации @NamedAttributeNode , чтобы определить поведение выборки для этого конкретного атрибута.

Комбинация этих аннотаций позволяет вам определять сложные графы сущностей, которые вы можете использовать для инициализации всех отношений, которые вы используете в своем варианте использования, и избежать проблем выбора n + 1. Если вы хотите динамически указать свой граф сущностей во время выполнения , вы можете сделать это также с помощью Java API.

2.3. Обновление объектов по одному

Обновление сущностей по одной кажется очень естественным, если вы мыслите объектно-ориентированным образом. Вы просто получаете объекты, которые хотите обновить, и вызываете несколько методов установки, чтобы изменить их атрибуты, как вы делаете это с любым другим объектом.

Этот подход отлично работает, если вы изменяете только несколько сущностей. Но это становится очень неэффективным, когда вы работаете со списком сущностей, и это третья проблема с производительностью, которую вы можете легко обнаружить в файле журнала. Вам просто нужно найти кучу операторов SQL UPDATE, которые выглядят совершенно одинаково, как вы можете видеть в следующем файле журнала:

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 вы можете просто написать одну инструкцию SQL, которая обновит все записи, которые вы хотите изменить.

Вы можете сделать то же самое с Hibernate, если используете JPQL, нативный SQL или CriteriaUpdate API . Все 3 очень похожи, поэтому в этом примере будем использовать JPQL.

Вы можете определить оператор JPQL UPDATE так же, как вы знаете его из SQL. Вы просто определяете, какой объект вы хотите обновить, как изменить значения его атрибутов и ограничить затрагиваемые объекты в операторе WHERE.

Вы можете увидеть пример этого в следующем фрагменте кода, где я увеличиваю цену всех продуктов на 10%:

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

Hibernate создает оператор SQL UPDATE на основе оператора JPQL и отправляет его в базу данных, которая выполняет операцию обновления.

Совершенно очевидно, что этот подход намного быстрее, если вам нужно обновить огромное количество сущностей. Но у него есть и недостаток. Hibernate не знает, на какие объекты влияет операция обновления, и не обновляет свой кеш 1-го уровня. Поэтому вы должны быть уверены, что не читаете и не обновляете объект с оператором JPQL в рамках одного и того же сеанса Hibernate, иначе вам придется отсоединить его, чтобы удалить из кэша.

3. Резюме

В этом посте я показал вам 3 проблемы с производительностью Hibernate, которые вы можете найти в своих лог-файлах.

2 из них были вызваны огромным количеством операторов SQL. Это частая причина проблем с производительностью, если вы работаете с Hibernate. Hibernate скрывает доступ к базе данных за своим API, что часто затрудняет угадывание фактического количества операторов SQL. Поэтому вы всегда должны проверять выполняемые операторы SQL, когда вносите изменения в свой уровень сохраняемости.