Count spring data jpa + hibernate requests per 1 rest request

It all started with the desire to calculate how many requests to the database flies for each rest request when using spring data jpa + hibernate.

Google released an interesting video about xrebelbut also said that xrebel is paid.

Further search led to the article Counting Queries per Request with Hibernate and Spring
He took it as the basis for his counter. I did not find any other example, so I decided to leave this note

The first thing to create is the counter class:

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)
    }
}

Because using regular mvc and not async, ThreadLocal will suffice.

Next, you need an http request filter that will reset the counter at the beginning of the request and display data at the end:

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()
        }
    }
}

Important here:

  1. ConditionalOnProperty, I don’t need to count the number of requests in the prom, this information is needed only during development, so the ability to control the presence of this filter through the spring property has been added

  2. Just in case, the output to the console when creating a bean about the fact that it can negatively affect performance

The third element is the registration of a request interceptor for hibernate, which will increment the counter:

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
        }
    }
}
  • Here it is also registered only if sql.query.count.per.request.log.enable is specified and set to true at startup, you can probably change it to ConditionalOnProperty as well

  • And in the same way, the output of a warning to the log.

As a result, by running the application with the counter, you can see the data in the log

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 gives a very convenient interface for working with the database, but one mistake can cost 100 or 1000 requests. The main thing that jpa gives is development speed.

The ability to quickly make a prototype and then finish it a little when the integrations are already fixed and each side debugs and improves its part.

About imports

I intentionally left all imports in the code, some points may be obvious, but not all.

Similar Posts

Leave a Reply