При использовании любого Data Access фреймворка, например, Hibernate, полезно следить за количеством генерируемых запросов.
Т.к. любая абстракция несет свою цену, а Hibernate не исключение, при отсутствии должного внимания может возникнуть ситуация, когда для доступа к данным используется слишком много запросов.
Эту проблему можно решить на раннем этапе, если периодически следить за тем, сколько запросов исполняется при рендринге какой-нибудь страницы или при формировании ответа от REST endpoint'а.
В Hibernate существует механизм логирования всех SQL запросов, включаемый свойством show_sql=true
или переключением определенного логера в режим DEBUG
, но этот способ неудобен для постоянного использования из-за того что лог очень быстро превращается в кашу из SQL кода.
Далее на примере Spring Framework 4 и Hibernate 5 рассматривается способ, при котором на каждый HTTP запрос в компактном виде в лог будет выводиться количество исполненных SQL запросов во время формирования ответа от сервера.
Пример лога:
2017-01-16 17:09:07.150 INFO DbQueryCountFilter : POST http://localhost:8080/auth, Queries: 3
2017-01-16 17:09:07.845 INFO DbQueryCountFilter : POST http://localhost:8080/object/, Queries: 1
2017-01-16 17:10:15.203 INFO DbQueryCountFilter : GET http://localhost:8080/user/, Queries: 1
Мы будем использовать Servlet Filter, который будет передавать управление следующим в цепочке фильтрам, а после возвращения из цепочки (когда запрос уже обработан) будет получать количество выполненных SQL запросов и писать об этом лог.
Код фильтра (для краткости некоторые import'ы опущены):
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.util.Assert;
import org.springframework.web.filter.OncePerRequestFilter;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
public class DbQueryCountFilter extends OncePerRequestFilter {
private static final Logger log = LoggerFactory.getLogger(DbQueryCountFilter.class);
private final DbQueryCounter queryCounter;
@Autowired
public DbQueryCountFilter(DbQueryCounter queryCounter) {
Assert.notNull(queryCounter);
this.queryCounter = queryCounter;
}
@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
throws ServletException, IOException {
try {
filterChain.doFilter(request, response);
} finally {
if (!isAsyncStarted(request)) {
log.info("{} {}, Queries: {}", request.getMethod(), request.getRequestURL(),
queryCounter.getQueryCount());
}
queryCounter.reset();
}
}
}
К сожалению, в стандарте JPA нету никаких способов вести статистику исполненных запросов или подписаться на их генерацию, поэтому я использую интерфейс DbQueryCounter
, чтобы как-то абстрагироваться от реализации JPA:
public interface DbQueryCounter {
int getQueryCount();В связи с изменениями в политике Oracle по отношению к java 8, выходом LTS-выпуска java 11 и разваливающимся приложением при попытке "в тупую" запустить его на новой джаве, я решил написать данную заметку по миграции.
void reset();
}
Для Hibernate реализация этого интерфейса использует механизм Interceptor
, который позволяет перехватывать функции самого Hibernate'а, а конкретно метод org.hibernate.Interceptor#onPrepareStatement(String)
, который вызывается каждый раз, когда генерируется SQL запрос. Так как зарегистрированный Interceptor общий для всего приложения, а каждый запрос обрабатывается в своем потоке, мы будем использовать внутри перехватчика ThreadLocal
счетчик запросов. После завершения обработки HTTP запроса необходимо очистить счетчик, чтобы для нового запроса отсчет начинался с нуля. Код перехватчика:
import org.hibernate.EmptyInterceptor;
public class HibernateQueryCountInterceptor extends EmptyInterceptor implements DbQueryCounter {
private static final ThreadLocal<Integer> queryCount = ThreadLocal.withInitial(() -> 0);
@Override
public int getQueryCount() {
return queryCount.get();
}
@Override
public void reset() {
queryCount.remove();
}
@Override
public String onPrepareStatement(String sql) {
queryCount.set(queryCount.get() + 1);
return super.onPrepareStatement(sql);
}
}
Осталось зарегистрировать фильтр и связать наши компоненты. Чтобы гибче конфигурировать приложение, в классе конфигурации используется аннотация @ConditionalOnProperty
из Spring Boot, включающая регистрацию компонентов только при наличии свойства db-query-count = true
. Это позволяет, например, отключить подсчет запросов в продакшене и включить только для тестового окружения. Для этого нужно добавить свойство spring.jpa.db-query-count = true
в файл application-<имя spring профиля>.properties
. Если вы не используете Spring Boot, то такого же поведения можно добиться с помощью аннотации @Conditional
из spring-context
, но с большим количеством кода. Так же не забудьте изменить строку "package.to.scan"
в методе entityManagerFactory
на пакет, содержащий ваши Entity.
Класс конфигурации:
import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty;
import org.springframework.boot.autoconfigure.orm.jpa.JpaProperties;
import org.springframework.boot.orm.jpa.EntityManagerFactoryBuilder;
import org.springframework.boot.web.servlet.FilterRegistrationBean;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean;
@Configuration
@ConditionalOnProperty(prefix = "spring.jpa", name = "db-query-count", havingValue = "true")
public class DbQueryCounterConfig {
@Bean
public DbQueryCounter hibernateQueryCountInterceptor() {
return new HibernateQueryCountInterceptor();
}
@Bean
public LocalContainerEntityManagerFactoryBean entityManagerFactory(EntityManagerFactoryBuilder factory,
DataSource dataSource,
JpaProperties properties) {
Map<String, Object> jpaProperties = new HashMap<>();
jpaProperties.putAll(properties.getHibernateProperties(dataSource));
jpaProperties.put("hibernate.ejb.interceptor", hibernateQueryCountInterceptor());
return factory.dataSource(dataSource).packages("package.to.scan").properties(jpaProperties).build();
}
@Bean
public FilterRegistrationBean dbQueryStatsFilter(DbQueryCounter queryCounter) {
FilterRegistrationBean registration = new FilterRegistrationBean();
registration.setName("dbQueryCountFilter");
registration.addUrlPatterns("/*");
registration.setOrder(Ordered.HIGHEST_PRECEDENCE);
registration.setDispatcherTypes(DispatcherType.REQUEST);
registration.setFilter(new DbQueryCountFilter(queryCounter));
return registration;
}
}
При регистрации фильтра используется DispatcherType = REQUEST
, чтобы исключить использование фильтра при асинхронных запросах, когда один запрос может исполняться в нескольких потоках, т.к мы используем ThreadLocal
переменную в работе фильтра.