Slow query en Hibernate

En este artículo sobre las slow query en hibernate vamos a ver como activar los logs de slow query cuando trabajamos con Hibernate y JPA.

La funcionalidad para activar los logs de las slow queries se encuentra disponible desde la versión de Hibernate 5.4.5, y el objetivo es notificar cuando alguna query excede de un tiempo prefijado.

Si quieres puedes consultar ejemplos con Spring e Hibernate en este enlace.

Activar el log de slow query en Hibernate

Para activar el flag de log de slow query en hibernate hay que añadir la siguiente propiedad en tu fichero de propiedades de tu aplicación:

hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS

Por ejemplo si usas Spring Boot lo tendrás que añadir de la siguiente manera en tu fichero de propiedades, application.yml o application.properties:

spring.jpa.properties.hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS=25

El valor anterior tiene que ser mayor de 0 y será el valor que cuando se supere hará saltar la notificación y mostrará el log.

En el caso en el que te encuentres trabajando con xml y tengas la configuración en tu xml tendrás que añadir:

<property
    name="hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS"
    value="10"
/>

Y además tendremos que establecer la siguiente propiedad para los logs de hibernate con un nivel de al menos INFO:

<logger name="org.hibernate.SQL_SLOW" level="info"/>

En el caso anterior obtendremos un log para todas aquellas queries que superen el umbral de 10 ms.

Funcionamiento del log en slow query de Hibernate

Vamos a ver el funcionamiento de la clase responsable de notificar una slow query,

@Override
public ResultSet extract(
        Statement statement, String sql) {
         
    sqlStatementLogger.logStatement(sql);
     
    long executeStartNanos = 0;
    if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
        executeStartNanos = System.nanoTime();
    }
     
    try {
        final ResultSet rs;
        try {
            jdbcExecuteStatementStart();
            rs = statement.executeQuery(sql);
        }
        finally {
            jdbcExecuteStatementEnd();
            sqlStatementLogger.logSlowQuery(
                sql,
                executeStartNanos
            );
        }
        postExtract(rs, statement);
        return rs;
    }
    catch (SQLException e) {
        throw sqlExceptionHelper.convert(
            e,
            "could not extract ResultSet"
        );
    }
}

En el código podemos ver como se obtiene el tiempo y luego una vez finalizada la ejecución de la query es envíado a un método que se encargará de evaluar ese tiempo y escribir el log con la slow query.

Hibernate únicamente va a aplicar el umbral que hemos establecido al tiempo de ejecución de la consulta, es decir, si añadimos pasos previos o procesamientos posteriores este tiempo no influye.

Ejemplo

A continuación vamos a ejecutar una query lenta (hemos hecho trampa arrancando la aplicación en modo debug y poniendo un punto de ruptura en la ejecución de la query del método ResultSet), para poder ver en nuestros logs la notificación de que es una slow query.

    select
        car0_.id as id1_1_,
        car0_.brand_id as brand_id4_1_,
        car0_.color as color2_1_,
        car0_.model as model3_1_ 
    from
        car car0_

Al ejecutar esa query hemos obtenido un tiempo superior al que hemos establecido en nuestro fichero de propiedades obteniendo una slow query que es informada por consola como un log más:

Como podemos ver una vez se ha ejecutado la consulta SQL, al tener activado el slow query de hibernate, podemos ver en los logs la notificación. En este caso vemos que nos ha dado 9525 ms, que ha sido el tiempo total de la ejecución de la query, podríamos decir que es el tiempo que ha estado en el método ResultSet.

Conclusión

Como hemos podido ver la activación de slow query en Hibernate es realmente sencillo. Una vez activado con un umbral mayor que 0, Hibernate medirá el tiempo en ejecutar cada query. Cuando la query es superior al umbral establecido entonces una notificación es mostrada en nuestros logs.

Esta funcionalidad que nos ofrece Hibernate es de gran utilidad para detectar problemas o cuellos de botella en alguna de nuestras querys. Y de esta manera poder optimizar el rendimiento de nuestras aplicaciones.