Log de sentencias SQL, sentencias lentas y otra información en jOOQ

Escrito por el 24/05/2019.
java planeta-codigo programacion
Enlace permanente Comentarios

Algunas de las causas del bajo rendimiento de una aplicación que utiliza una base de datos son el número de sentencias que se realizan junto con las sentencias lentas por su coste de ejecución. Cada ejecución de una sentencia significa una comunicación por la red y ejecutar muchas de ellas significa un considerable y perceptible tiempo para el usuario. Por ello es conveniente saber que sentencias se ejecutan, si hay algún problema de 1+N o sentencias innecesarias que se repiten. Un log de las sentencias que se ejecutan es muy útil para detectar ineficiencias en la aplicación y corregirlas.

jOOQ

Java

La librería jOOQ devuelve al lenguaje SQL de consultas para bases de datos relacionales al primer plano en una aplicación Java. En vez de crear una capa de abstracción como realiza la popular librería Hibernate del modelo relacional al modelo orientado a objetos de Java permite construir con un DSL mediante su API fluída avanzadas sentencias SQL que soportan las versiones recientes de PostgreSQL y MySQL.

Alternativa a Hibernate u ORM y ejemplo de jOOQ

En Hibernate la configuración de statistics, el logger org.hibernate.SQL y con el parámetro show_sql permiten visualizar que sentencias SQL se están lanzando, útil para conocer si algún problema de 1+N al navegar relaciones que ocasionalmente se producen si no son tenidas en cuenta. Además de que sentencias se están lanzando es también interesante conocer que tiempo de ejecución está tomando cada sentencia para conseguir que el rendimiento de la aplicación no sea lento, para detectar sentencias lentas.

Usando Spring Boot y la dependencia de jOOQ hay que proporcionar una instancia que implemente la interfaz ExecuteListener o crear una instancia de DefaultExecuteListener. Esta clase contiene numerosos métodos que permiten conocer y realizar acciones, en este caso emitir trazas. Dos de los métodos son executeStart() y executeEnd() invocados por jOOQ antes y después de cada sentencia que lanza. Usando System.nanoTime() se mide el tiempo de ejecución.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52


package io.github.picodotdev.plugintapestry.spring;

...

@Configuration
@ComponentScan({ "io.github.picodotdev.plugintapestry" })
@EnableTransactionManagement
public class AppConfiguration {

    @Bean(destroyMethod = "close")
    public DataSource dataSource() {
        BasicDataSource ds = new BasicDataSource();
        ds.setDriverClassName(Driver.class.getCanonicalName());
        ds.setUrl("jdbc:h2:./misc/database/app");
        ds.setUsername("sa");
        ds.setPassword("sa");
        return ds;
    }

    ...

    @Bean
    public ConnectionProvider connectionProvider(DataSource dataSource) {
        return new DataSourceConnectionProvider(dataSource);
    }

    @Bean
    public ExecuteListenerProvider executeListenerProvider() {
        return new ExecuteListenerProvider() {
            @Override
            public ExecuteListener provide() {
                return new JooqExecuteListener();
            }
        };
    }

    @Bean
    public org.jooq.Configuration config(ConnectionProvider connectionProvider, ExecuteListenerProvider executeListenerProvider) {
        DefaultConfiguration config = new DefaultConfiguration();
        config.set(connectionProvider);
        config.set(SQLDialect.H2);
        config.set(executeListenerProvider);
        return config;
    }

    @Bean
    public DSLContext dsl(org.jooq.Configuration config) {
        return DSL.using(config);
    }

    ...
}

AppConfiguration.java

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32


package io.github.picodotdev.plugintapestry.misc;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.jooq.ExecuteContext;
import org.jooq.impl.DefaultExecuteListener;

import java.math.BigDecimal;
import java.math.MathContext;

public class JooqExecuteListener extends DefaultExecuteListener {

    private static final Logger logger = LogManager.getLogger(JooqExecuteListener.class);

    private long start;
    private long end;

    @Override
    public void executeStart(ExecuteContext ctx) {
        start = System.nanoTime();
    }

    @Override
    public void executeEnd(ExecuteContext ctx) {
        end = System.nanoTime();
        logger.info("{} ({}ms)", ctx.sql(), getTime(start, end));
    }

    private String getTime(long start, long end) {
        return new BigDecimal(end - start, new MathContext(4)).divide(new BigDecimal("1000000")).toString();
    }
}

JooqExecuteListener.java

En las siguientes trazas de ejecución de sentencias se observa una inserción de un registro (1), una posterior muestra del listado para lo que se realizan dos sentencias una que cuenta el número de elementos en la tabla con un select count(*) que junto con el número de elementos por página permite conocer cuantas páginas hay y un select con un limit ? para recuperar los datos de la primera página (2). Con el suficiente número de elementos en la tabla se hace una consulta con un limit ? y un offset ? para los elementos de una página posterior a la primera (3). Al eliminar un elemento de la tabla se ejecuta una sentencia delete con el identificativo de la fila a eliminar en la clausula where (4), finalmente si se utiliza el botón Eliminar todos se elimina todas las filas con otra sentencia delete pero sin especificar la clausula where (5). En cada sentencia se muestra el tiempo que ha tardado.

Estas sentencias se ejecutan en unos pocos milisegundos, en una aplicación con tablas de algún millón de registros, varios joins, condiciones where complejas, ordenación y paginación las sentencias SQL pueden tardar varias segundos y decenas de segundos, conocer sus tiempos de ejecución es importante.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16


// (1)
2019-05-24 19:00:00,829 ... INFO  ...JooqExecuteListener insert into "PLUGINTAPESTRY"."PRODUCTO" ("ID", "NOMBRE", "DESCRIPCION", "CANTIDAD", "FECHA") values (cast(? as bigint), cast(? as varchar), cast(? as varchar), cast(? as bigint), cast(? as timestamp)) (1.887ms)

// (2)
2019-05-24 19:01:00,843 ... INFO  ...JooqExecuteListener select count(*) from "PLUGINTAPESTRY"."PRODUCTO" (0.1474ms)
2019-05-24 19:01:00,879 ... INFO  ...JooqExecuteListener select "PLUGINTAPESTRY"."PRODUCTO"."ID", "PLUGINTAPESTRY"."PRODUCTO"."NOMBRE", "PLUGINTAPESTRY"."PRODUCTO"."DESCRIPCION", "PLUGINTAPESTRY"."PRODUCTO"."CANTIDAD", "PLUGINTAPESTRY"."PRODUCTO"."FECHA" from "PLUGINTAPESTRY"."PRODUCTO" limit ? (0.2915ms)

// (3)
2019-05-24 19:02:00,289 ... INFO  ...JooqExecuteListener select count(*) from "PLUGINTAPESTRY"."PRODUCTO" (0.1092ms)
2019-05-24 19:02:00,291 ... INFO  ...JooqExecuteListener select "PLUGINTAPESTRY"."PRODUCTO"."ID", "PLUGINTAPESTRY"."PRODUCTO"."NOMBRE", "PLUGINTAPESTRY"."PRODUCTO"."DESCRIPCION", "PLUGINTAPESTRY"."PRODUCTO"."CANTIDAD", "PLUGINTAPESTRY"."PRODUCTO"."FECHA" from "PLUGINTAPESTRY"."PRODUCTO" limit ? offset ? (0.1623ms)

// (4)
2019-05-24 19:03:00,224 ... INFO  ...JooqExecuteListener delete from "PLUGINTAPESTRY"."PRODUCTO" where "PLUGINTAPESTRY"."PRODUCTO"."ID" = cast(? as bigint) (1.19ms)

// (5)
2019-05-24 19:04:00,037 ... INFO  ...JooqExecuteListener delete from "PLUGINTAPESTRY"."PRODUCTO" (0.391ms)

System.out

La clase ExecuteContext proporciona numerosa información sobre la ejecución de la sentencia como número de filas afectadas, si se ha producido una excepción, el tipo de sentencia (READ, WRITE, DDL, BATCH, ROUTINE u OTHER), sentencias batch u obtener los parámetros a través del objeto Query.

Simplemente mostrando las trazas de sentencias me ha permitido detectar que en el ejemplo se estaba realizando una pequeña ineficiencia. La sentencia select count(*) se lanzaba dos veces en la página de listado, una al querer saber si hay alguna fila y otra usada por el componente Grid de Tapestry. Para resolverlo se cachea el resultado en la clase anónima JooqGridDataSource con el siguiente código.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45


package io.github.picodotdev.plugintapestry.pages.admin;

...
public class ProductoAdmin {

    ...

	public boolean hasProductos() {
		return source.getAvailableRows() > 0;
	}

    ...

	private void setModo(Modo modo, Producto producto) {
		switch (modo) {
            ...
			case LISTA:
				this.producto = null;
				this.source = new JooqGridDataSource(context, Producto.class) {

					private int count = -1;
					private List list = null;

					@Override
					public int getAvailableRows() {
						if (count == -1) {
							count = (int) dao.countAll();
						}
						return count;
					}

					@Override
					public List find(Pagination pagination) {
						if (list == null) {
							list = dao.findAll(pagination);
						}
						return list;
					}
				};
				break;

		}
		this.modo = modo;
	}
}

ProductoAdmin.java

Las bases de datos MySQL y PostgreSQL también ofrecen la posibilidad de emitir en las sentencias en un log incluidas las sentencias lentas. Otra posibilidad es resaltar la sintaxis de las sentencias en la salida a la terminal para una mejor lectura dando color a las palabras claves.

El código fuente completo del ejemplo puedes descargarlo del repositorio de ejemplos de Blog Bitix alojado en GitHub y probarlo en tu equipo ejecutando siguiente comando:
./gradlew run

Log de sentencias SQL, sentencias lentas y otra información en jOOQ

Este artículo forma parte de la serie jooq: