Introducción al Monitoreo de Consultas SQL
Durante el desarrollo y depuración de aplicaciones que enteractúan con bases de datos, es común necesitar visualizar las sentencias SQL exactas que se ejecutan. Por defecto, muchos frameworks de persistencia como MyBatis ocultan estos detalles, dificultando la identificación de problemas de rendimiento o errores lógicos. Este artículo explora diversas estrategias para registrar de forma detallada las consultas SQL, incluyendo sus parámetros, en proyectos basados en Spring Boot.
- Implementación Mediante un Interceptor de MyBatis
MyBatis, uno de los frameworks de mapeo de objetos relacionales más populares en Java, ofrece un potente mecanismo de plugins o interceptores. Estos permiten interceptar llamadas a métodos clave dentro del ciclo de vida de ejecución de una sentencia, como la preparación o la ejecución. Podemos aprovechar este punto de extensión para capturar y formatear las sentencias SQL junto con sus parámetros y el tiempo de ejecución.
Código del Interceptor
A continuación, se presenta un interceptor personalizado que registra la consulta SQL preparada y sus argumentos, reemplazando los marcadores de posición ? con sus valores reales para una legibilidad mejorada.
package com.example.app.config;
import org.apache.ibatis.executor.statement.StatementHandler;
import org.apache.ibatis.mapping.BoundSql;
import org.apache.ibatis.mapping.ParameterMapping;
import org.apache.ibatis.plugin.*;
import org.apache.ibatis.reflection.MetaObject;
import org.apache.ibatis.session.Configuration;
import org.apache.ibatis.session.ResultHandler;
import org.apache.ibatis.type.TypeHandlerRegistry;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import java.sql.Statement;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.List;
import java.util.Properties;
@Intercepts({
@Signature(type = StatementHandler.class, method = "query", args = {Statement.class, ResultHandler.class}),
@Signature(type = StatementHandler.class, method = "update", args = {Statement.class}),
@Signature(type = StatementHandler.class, method = "batch", args = {Statement.class})
})
@Component
public class QueryLogInterceptor implements Interceptor {
private static final Logger queryLogger = LoggerFactory.getLogger(QueryLogInterceptor.class);
@Override
public Object intercept(Invocation invocation) throws Throwable {
long startTimeMillis = System.currentTimeMillis();
StatementHandler handler = (StatementHandler) invocation.getTarget();
Configuration configuration = handler.getBoundSql().getConfiguration();
try {
return invocation.proceed();
} finally {
long endTimeMillis = System.currentTimeMillis();
long queryDuration = endTimeMillis - startTimeMillis;
BoundSql boundSql = handler.getBoundSql();
String originalSql = boundSql.getSql();
Object parametersObject = boundSql.getParameterObject();
List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
String formattedSql = formatSqlStatement(originalSql, parametersObject, parameterMappings, configuration);
String cleanedSql = cleanUpSqlString(formattedSql);
queryLogger.info("SQL Executado: [{}] Tiempo: [{} ms]", cleanedSql, queryDuration);
}
}
/**
* Formatea la sentencia SQL reemplazando los marcadores '?' con los valores reales de los parámetros.
* Esto hace que la SQL sea directamente ejecutable y fácil de leer.
* @param configuration Configuración de MyBatis para resolver manejadores de tipos y meta objetos.
*/
private String formatSqlStatement(String sql, Object parameterObject, List<ParameterMapping> parameterMappings, Configuration configuration) {
if (sql == null || sql.isEmpty()) {
return "";
}
sql = cleanUpSqlString(sql);
if (parameterObject == null || parameterMappings == null || parameterMappings.isEmpty()) {
return sql;
}
TypeHandlerRegistry typeHandlerRegistry = configuration.getTypeHandlerRegistry();
StringBuilder formattedSqlBuilder = new StringBuilder(sql);
// Iterar los parámetros en orden inverso para evitar problemas de índice al reemplazar
for (int i = parameterMappings.size() - 1; i >= 0; i--) {
ParameterMapping paramMapping = parameterMappings.get(i);
if (paramMapping.getMode() != org.apache.ibatis.mapping.ParameterMode.OUT) {
Object value;
String propertyName = paramMapping.getProperty();
if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {
value = parameterObject; // El objeto parámetro es el valor directamente
} else {
MetaObject metaObject = configuration.newMetaObject(parameterObject);
value = metaObject.getValue(propertyName);
}
String paramValue = getParamValueAsString(value);
int questionMarkIndex = formattedSqlBuilder.lastIndexOf("?");
if (questionMarkIndex != -1) {
formattedSqlBuilder.replace(questionMarkIndex, questionMarkIndex + 1, paramValue);
}
}
}
return formattedSqlBuilder.toString();
}
/**
* Convierte el valor del parámetro a una representación de cadena adecuada para SQL.
*/
private String getParamValueAsString(Object value) {
if (value == null) {
return "NULL";
} else if (value instanceof String) {
return "'" + value.toString().replace("'", "''") + "'"; // Escapar comillas simples
} else if (value instanceof Date) {
return "'" + new SimpleDateFormat("yyyy-MM-dd HH:mm:ss").format((Date) value) + "'";
} else {
return value.toString();
}
}
/**
* Limpia la cadena SQL eliminando espacios en blanco excesivos y saltos de línea.
*/
private String cleanUpSqlString(String sqlInput) {
if (sqlInput == null || sqlInput.isEmpty()) {
return "";
}
return sqlInput.replaceAll("[\\s\n\r]+", " ").trim();
}
@Override
public Object plugin(Object target) {
return Plugin.wrap(target, this);
}
@Override
public void setProperties(Properties properties) {
// No hay propiedades específicas para configurar en este interceptor
}
}
Salida de Ejemplo
2023-10-26 10:30:00.123 INFO QueryLogInterceptor - SQL Executado: [SELECT u.id, u.nombre, r.nombre_rol FROM usuarios u JOIN usuario_roles ur ON u.id = ur.usuario_id JOIN roles r ON ur.rol_id = r.id WHERE u.id = 1 AND r.nombre_rol = 'Administrador'] Tiempo: [15 ms]
- Configuración Sencilla con MyBatis-Plus
Para proyectos que utilizan MyBatis-Plus, una extensión popular de MyBatis, la habilitación del logging SQL es sorprendentemente simple y no requiere código adicional. Con una única línea de configuración, puedes obtener un registro detallado de las operaciones de la base de datos.
Configuración en application.properties
# Configuración general de MyBatis
mybatis.configuration.auto-mapping-behavior=full
mybatis.configuration.map-underscore-to-camel-case=true
mybatis-plus.mapper-locations=classpath*:/mybatis/mappers/*.xml
# Habilitar el log de SQL de MyBatis-Plus en la consola
mybatis-plus.configuration.log-impl=org.apache.ibatis.logging.stdout.StdOutImpl
Salida de Ejemplo
Creating a new SqlSession
SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@xyzabc] was not registered for synchronization because synchronization is not active
JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@123def] will not be managed by Spring
==> Preparing: SELECT user_id, user_name, role_id, role_name FROM user_role_link t1 LEFT JOIN app_role t2 ON t1.role_id = t2.role_id LEFT JOIN app_user t3 ON t1.user_id = t3.user_id WHERE t1.user_id = ?
==> Parameters: 5(Long)
<== Columns: user_id, user_name, role_id, role_name
<== Row: 5, UsuarioPrueba, 1, Admin
<== Row: 5, UsuarioPrueba, 2, Lector
<== Total: 2
Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@xyzabc]
- Integración con p6spy para un Monitoreo Avanzado
p6spy es una API de código abierto diseñada para interceptar y registrar las operaciones de la base de datos. Se integra como un driver JDBC proxy, lo que le permite capturar todas las interacciones sin modificar el código de la aplicación. Ofrece un control granular sobre el formato de salida y es ideal para un monitoreo más robusto, mostrando el SQL con los parámetros ya sustituidos.
Dependencia Maven
<dependency>
<groupId>p6spy</groupId>
<artifactId>p6spy</artifactId>
<version>3.9.1</version> <!-- Usar la última versión estable -->
</dependency>
Configuración de la Fuente de Datos en application.properties
Para usar p6spy, es necesario modificar la URL de la base de datos y el nombre del driver en tu archivo application.properties.
spring.datasource.url=jdbc:p6spy:mysql://localhost:3306/mi_base_datos?characterEncoding=utf8&useSSL=false&serverTimezone=America/Mexico_City
spring.datasource.username=root
spring.datasource.password=suContrasena
spring.datasource.driver-class-name=com.p6spy.engine.spy.P6SpyDriver
Creación del Archivo spy.properties
Este archivo se coloca en la carpeta src/main/resources y permite personaliazr el comportamiento de p6spy, incluyendo el formato de los mensajes de log. Podemos utilizar un formateador personalizado para adaptar la salida a nuestras necesidades.
# Habilitar módulos de log (por ejemplo, SQL y tiempos de ejecución prolongados)
module.log=com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory
# Usar una clase de formato personalizada para los mensajes de log
logMessageFormat=com.example.app.config.CustomSqlLogFormatter
# Configurar la salida del log a la consola estándar
appender=com.p6spy.engine.spy.appender.StdoutLogger
# appender=com.p6spy.engine.spy.appender.Slf4JLogger # Para integrar con SLF4J
# Excluir ciertas categorías de log si son demasiado ruidosas
excludecategories=info,debug,result,resultset
# Desregistrar los drivers JDBC originales una vez que P6Spy ha tomado el control
deregisterdrivers=true
# Especificar el driver JDBC real que P6Spy debe envolver
driverlist=com.mysql.cj.jdbc.Driver
# Habilitar la detección de consultas de larga duración y el umbral en milisegundos
outagedetection=true
outagedetectioninterval=250 # Registra consultas que tarden más de 250 ms
Para un formato de log más específico, podemos implementar una clase Java que extienad com.p6spy.engine.spy.appender.MessageFormat:
package com.example.app.config;
import com.p6spy.engine.spy.appender.MessageFormat;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.Locale;
public class CustomSqlLogFormatter implements MessageFormat {
private final DateTimeFormatter dateTimeFormatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS", Locale.getDefault());
@Override
public String formatMessage(int connectionId, String now, long elapsed, String category, String prepared, String sql, String url) {
String currentTimestamp = LocalDateTime.now().format(dateTimeFormatter);
// Limpiar la cadena SQL de espacios y saltos de línea excesivos
String cleanedSql = sql != null ? sql.replaceAll("\\s+", " ").trim() : "N/A";
// Formato de log personalizado: [TIMESTAMP] | Con: [ID] | Dur: [MS] ms | Cat: [CATEGORY] | SQL: [STATEMENT]
return String.format(
"[%s] | Conexión: %d | Duración: %d ms | Categoría: %s | SQL: %s",
currentTimestamp,
connectionId,
elapsed,
category,
cleanedSql
);
}
}
Salida de Ejemplo de p6spy
[2023-10-26 10:30:00.123] | Conexión: 1 | Duración: 8 ms | Categoría: statement | SQL: SELECT t3.user_id, t3.user_name, t2.role_id, t2.role_name FROM user_role_link t1 LEFT JOIN app_role t2 ON t1.role_id = t2.role_id LEFT JOIN app_user t3 ON t1.user_id = t3.user_id WHERE t1.user_id = 1 AND t2.role_id = 1;
Resolución de Problemas Comunes con p6spy
Problema: Error "dbType not support : null" con Druid
Este error suele ocurrir al combinar p6spy con el datasource Druid. Druid intenta analizar la URL de la base de datos y puede no reconocer la estructura de jdbc:p6spy:mysql://....
Solución: Puedes desactivar ciertos filtros de Druid o configurar explícitamente el tipo de base de datos para los filtros de Druid:
# Desactivar el filtro de Druid que causa el conflicto
# spring.datasource.druid.filters=stat,wall
# O configurar explícitamente el tipo de base de datos para los filtros de Druid
spring.datasource.druid.filter.wall.enabled=true
spring.datasource.druid.filter.wall.db-type=mysql
spring.datasource.druid.filter.stat.db-type=mysql
spring.datasource.druid.filter.stat.enabled=true
Problema: El archivo spy.properties no surte efecto
Si la configuración en spy.properties parece ser ignorada, la causa más común es que el archivo no se esté incluyendo correctamente en el classpath o el empaquetado del proyecto. p6spy carga este archivo automáticamente al inicializarse, ya que opera a nivel del driver JDBC.
Solución: Asegúrate de que spy.properties esté ubicado directamente en src/main/resources y sea empaquetado en el JAR/WAR final. Verifica la estructura del JAR si es necesario.
Consideraciones Finales
De las opciones presentadas, p6spy tiende a ofrecer el registro SQL más completo y fácil de leer, ya que puede generar sentencias SQL directamente ejecutables con sus parámetros. Sin embargo, es crucial recordar que el logging excesivo, especialmente en un entorno de producción, puede introducir una sobrecarga de rendimiento significativa. Se recomienda deshabilitar o limitar el nivel de logging de SQL en entornos productivos para evitar el consumo innecesario de recursos y el impacto en la latencia.