Началось все с желания посчитать, сколько запросов в БД улетает на каждый rest запрос при использовании spring data jpa + hibernate.

Гугл выдал интересное видео про xrebel, но так же сообщил, что xrebel платный.

Дальнейший поиск привел к статье Counting Queries per Request with Hibernate and Spring
Её и взял за основу для своего счетчика. Какого-то ещё примера не нашел, поэтому решил оставить эту заметку

Первое, что нужно создать - класс счетчик:

package ru.counter.utils.querycounter

import org.hibernate.EmptyInterceptor
import org.springframework.stereotype.Component

@Component
class HibernateStatisticsInterceptor : EmptyInterceptor() {
    private val queryCount = ThreadLocal<Long>()

    fun startCounter() {
        queryCount.set(0L)
    }

    fun getQueryCount(): Long {
        return queryCount.get()
    }

    fun clearCounter() {
        queryCount.remove()
    }

    override fun onPrepareStatement(sql: String?): String? {
        val count = queryCount.get()
        if (count != null) {
            queryCount.set(count + 1)
        }
        return super.onPrepareStatement(sql)
    }
}

Т.к. используется обычный mvc а не асинхронный, ThreadLocal будет достаточно.

Далее понадобится фильтр http запросов, который будет обнулять счетчик в начале запроса и выводить данные по завершению:

package ru.counter.utils.querycounter

import org.slf4j.Logger
import org.slf4j.LoggerFactory
import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty
import org.springframework.core.Ordered
import org.springframework.core.annotation.Order
import org.springframework.stereotype.Component
import javax.servlet.FilterChain
import javax.servlet.http.HttpFilter
import javax.servlet.http.HttpServletRequest
import javax.servlet.http.HttpServletResponse

@Component
@ConditionalOnProperty(name = ["sql.query.count.per.request.log.enable"], havingValue = true.toString())
@Order(Ordered.HIGHEST_PRECEDENCE) // максимальный приоритет, чтобы фильтр был первым
																	// на случай, если другие фильтры тоже кидают запросы в БД
class RequestStatisticsSqlQueryCountFilter(
    private val statisticsInterceptor: HibernateStatisticsInterceptor
) : HttpFilter() {

    private val log: Logger = LoggerFactory.getLogger(javaClass)

    init {
        log.warn(
            "http фильтр для подсчета количества sql запросов на 1 http запрос включен," +
                    " негативно для производительности"
        )
    }

    private val time = ThreadLocal<Long>()

    override fun doFilter(request: HttpServletRequest?, response: HttpServletResponse?, chain: FilterChain?) {
        if (request?.requestURI?.startsWith("/api") != true) { // мне были важны только запросы к api
            chain?.doFilter(request, response)
        } else {
            time.set(System.currentTimeMillis())
            statisticsInterceptor.startCounter()
            chain?.doFilter(request, response)
            val duration = System.currentTimeMillis() - time.get()
            val queryCount: Long = statisticsInterceptor.getQueryCount()
            log.info("[Time: {} ms] [Queries: {}] {} {}", duration, queryCount, request.method, request.requestURI)
            statisticsInterceptor.clearCounter()
            time.remove()
        }
    }
}

Важное тут:

  1. ConditionalOnProperty, считать количество запросов в проме мне не надо, это информация нужна только во время разработки, поэтому добавлена возможность управлять наличием этого фильтра через spring property

  2. На всякий случай вывод в консоль при создании бина о, том что он может негативно влиять на производительность

Третий элемент это регистрация перехватчика запросов для hibernate, который и будет инкрементировать счетчик:

package ru.counter.configuration

import org.slf4j.LoggerFactory
import org.springframework.beans.factory.annotation.Autowired
import org.springframework.beans.factory.annotation.Value
import org.springframework.boot.autoconfigure.orm.jpa.HibernatePropertiesCustomizer
import org.springframework.context.annotation.Configuration
import ru.counter.utils.querycounter.HibernateStatisticsInterceptor

@Configuration
class HibernateInterceptorRegistration : HibernatePropertiesCustomizer {

    private val log = LoggerFactory.getLogger(javaClass)

    @Value("\${sql.query.count.per.request.log.enable:false}")
    private var statisticsInterceptorEnabled: Boolean = false

    @Autowired
    private lateinit var statisticsInterceptor: HibernateStatisticsInterceptor

    override fun customize(hibernateProperties: MutableMap<String, Any>) {
        if (statisticsInterceptorEnabled) {
            log.warn("Счетчик sql запросов на 1 http запрос включен, негативно для производительности")
            hibernateProperties["hibernate.session_factory.interceptor"] = statisticsInterceptor
        }
    }
}
  • Здесь так же он регистрируется, только если при запуске sql.query.count.per.request.log.enable указана и имеет значение true, наверно можно переделать так же под ConditionalOnProperty

  • И точно так же вывод предупреждения в лог.

В итоге запустив приложение со счетчиком можно увидеть данные в логе

INFO RequestStatisticsSqlQueryCountFilter : [Time: 154 ms] [Queries: 18] GET /api/private/v1/auth/check
INFO RequestStatisticsSqlQueryCountFilter : [Time: 149 ms] [Queries: 4] GET /api/private/v1/organisation/employee
INFO RequestStatisticsSqlQueryCountFilter : [Time: 0 ms] [Queries: 0] GET /api/private/v1/auth/check
INFO RequestStatisticsSqlQueryCountFilter : [Time: 62 ms] [Queries: 16] GET /api/private/v1/organisation
INFO RequestStatisticsSqlQueryCountFilter : [Time: 30 ms] [Queries: 1] GET /api/public/v1/image/1001
INFO RequestStatisticsSqlQueryCountFilter : [Time: 30 ms] [Queries: 1] GET /api/public/v1/image/1000

Spring data jpa дает очень удобные интерфейс для работы с БД, но одна ошибка, может стоит 100 или 1000 запросов. Главное, что jpa дает, это скорость разработки.

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

Про импорты

В коде специально оставил все импорты, некоторые моменты могут быть очевидны, но не все.

Комментарии (9)


  1. vooft
    12.05.2022 01:08
    +1

    Главное, что jpa дает, это скорость.

    Что?! Скорость первичной разработки только если, а потом долго и мучительно пытаться выразить нужный тебе sql через всякие NamedGraph. Ваш счетчик настолько ничтожен по оверхеду по сравнению с JPA, что даже смешно писать об этом.

    Код у вас выглядит будто вы сконвертировали через Intellij из Java в Kotlin. Зачем у вас все параметры nullable в doFilter?


    1. sergeevik Автор
      12.05.2022 02:14
      +1

      Что?! Скорость первичной разработки только если

      Да, это я и хотел написать, спасибо, поправил

      мучительно пытаться выразить нужный тебе sql через всякие NamedGraph

      Есть много разных вариантов как можно получить данные из БД, на мой взгляд выбирать нужно тот, который нужен сейчас и тот который можно сейчас использовать с учетом временных ограничений.

      Ваш счетчик настолько ничтожен по оверхеду по сравнению с JPA, что даже смешно писать об этом

      Да, но зачем тащить в пром, то что там не будет никогда использоваться? Так можно сотню небольших сервисов набрать, каждый из которых ничтожен, но вместе дадут просадку.

      будто вы сконвертировали через Intellij из Java в Kotlin

      прям так и сделал с нужными мне правками


      1. hello_my_name_is_dany
        12.05.2022 04:46

        А почему было не оставить код на Java?


      1. vooft
        12.05.2022 10:01

        Да, но зачем тащить в пром, то что там не будет никогда использоваться? Так можно сотню небольших сервисов набрать, каждый из которых ничтожен, но вместе дадут просадку.

        В проде тоже нужны метрики :)

        Еще замечу, что time в RequestStatisticsSqlQueryCountFilter совершенно не нужен в ThreadLocal, это может быть просто локальная переменная.


        1. sergeevik Автор
          12.05.2022 10:16

          Ну это не совсем метрика)

          Тут задача в том, чтобы понять нагрузку в плане количества запросов на 1 вызов и оптимизировать запрос. В прозе он будет таким же и там полезнее метрики самой бд

          совершенно не нужен в ThreadLocal, это может быть просто локальная пепеременнаяд

          Да, согласен)


    1. aleksandy
      12.05.2022 07:16

      Согласен, что JPA даёт нехилый оверхед особенно на простых структурах. Но, чтобы не заниматься

      долго и мучительно пытаться выразить нужный тебе sql через всякие NamedGraph

      Кто мешает написать через HQL или, если он не позволяет выразить полёт мысли, native sql?


      1. vooft
        12.05.2022 09:55

        Даже native sql не гарантирует, что хибернейт не решит сгонять в базу еще пару-тройку раз, особенно если есть пара уровней вложенности. При маленькой нагрузке это не важно, но при большой это это становится критично.

        Особенно это проблематично когда в проект могут добавлять новые сущности, я в свое время сильно обжегся, что на простом вызове save и findById он делал 10 запросов.

        К слову, с этим бороться мне в свое время помогла вот эта библиотечка, которая позволяет сделать тест на количество запросов https://github.com/quick-perf/quickperf


  1. aleksandy
    12.05.2022 07:13

    Для простого подсчёта запросов проще использовать специально созданный инспектор.


    1. sergeevik Автор
      12.05.2022 10:14

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