null

Логирование количества запросов к БД во время HTTP-запроса в Spring и Hibernate

При использовании любого 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 переменную в работе фильтра.

Назад Вперед