Es posible encontrarse con una entrada en el slow query log que resulte desconcertante, especialmente cuando el tiempo de ejecución es alto pero el número de filas examinadas es cero. A continuación, se presenta un ejemplo de un log capturado con un long_query_time=1:

# Time: 2024-01-28T22:52:24.500491+08:00
# User@Host: dba_admin[root] @ [127.0.0.1] Id: 12
# Query_time: 8.120450 Lock_time: 8.115200 Rows_sent: 0 Rows_examined: 0
use production_db;
SET timestamp=1706453536;
DELETE FROM orders WHERE order_id < 5;

Configuración del entorno de pruebas

Variables de control del Slow Log

Para entender por qué se registran estas consultas, es fundamental revisar los parámetros que gobeirnan el comportamiento del motor:

• slow_query_log: Habilita o deshabilita el registro.
• long_query_time: Define el umbral en segundos (soporta microsegundos) para considerar una consulta como lenta.
• log_output: Determina si el log se escribe en un archivo (FILE) o en una tabla (TABLE).
• min_examined_row_limit: Establece un número mínimo de filas que deben ser escaneadas para que la consulta sea candidata al log.
• log_queries_not_using_indexes: Si está activo, registra consultas que no aprovechan índices, independientemente del tiempo.
• log_slow_admin_statements: Incluye operaciones como OPTIMIZE TABLE o ALTER TABLE.

Arquitectura del proceso de registro

El ciclo de vida de una sentencia SQL y su evaluación para el log lento sigue esta secuencia simplificada en el código fuente:

1. dispatch_command: Inicializa el estado de la conexión y marca el tiempo de inicio.
2. parse_sql: Realiza el aálisis léxico y sintáctico.
3. mysql_execute_command: Ejecución real de la operación (CRUD).
4. update_slow_query_status: Aquí ocurre la lógica crítica de comparación de tiempos.
5. log_slow_statement: Punto de entrada para la escritura física si se cumplen las condiciones.

Evolución de la lógica de evaluación (Versión 8.0.26 vs 8.0.32)

El criterio para decidir si una consulta es "lenta" ha cambiado significativamente en las versiones recientes de MySQL y GreatSQL.

Lógica en versión 8.0.26 (y anteriores)

En esta versión, el tiempo de espera por bloqueos (lock time) se restringe del tiempo total para la evaluación del umbral:

void THD::update_slow_query_status() {
  // Se obtiene el tiempo actual y se compara excluyendo el tiempo de bloqueo
  if (get_current_microtime() > time_after_lock_wait + variables.long_query_time)
    server_status |= SERVER_QUERY_WAS_SLOW;
}

Bajo este esquema, si una consulta tarda 10 segundos pero 9.5 segundos fueron espera de bloqueos (MDL o filas), y long_query_time es 1, la consulta no se registrará porque el tiempo neto de ejecución (0.5s) es menor al umbral.

Lógica en versión 8.0.32 (Desde 8.0.28)

El criterio se simplificó para incluir el tiempo total, incluyendo esperas:

void THD::update_slow_query_status() {
  // La comparación se hace directamente contra el tiempo de inicio de la sentencia
  if (get_current_microtime() > start_utime + variables.long_query_time)
    server_status |= SERVER_QUERY_WAS_SLOW;
}

En este escenario, cualquier consulta cuya duración total exceda el umbral aparecerá en el log, facilitando la detección de cuellos de botella por contención de bloqueos.

Condiciones para la persistencia del log

Incluso si una consulta es marcada como lenta, la función log_slow_applicable debe retornar verdadero para que se escriba en el disco. La lógica interna sigue esttas reglas:

bool log_slow_applicable(THD *thd) {
  // Evitar sub-sentencias o conexiones terminadas
  if (thd->is_sub_statement() || thd->is_killed()) return false;

  if (thd->enable_slow_log && opt_slow_log) {
    // Verificar si no se usaron índices y la opción está activa
    bool missing_index = (thd->server_status & (SERVER_QUERY_NO_INDEX_USED | SERVER_QUERY_NO_GOOD_INDEX_USED)) 
                         && opt_log_queries_not_using_indexes;
    
    // Evaluación principal de registro
    bool should_log = ((thd->server_status & SERVER_QUERY_WAS_SLOW) || missing_index) &&
                      (thd->get_examined_row_count() >= thd->variables.min_examined_row_limit);

    // Aplicar throttling si está configurado
    bool throttled = slow_log_throttle.check(thd, missing_index);

    if (should_log && !throttled) return true;
  }
  return false;
}

Factores que pueden prevenir la escritura:

• Si la consulta es una sub-sentencia dentro de un trigger o función almacenada.
• Si la conexión fue abortada (killed).
• Si el número de filas examinadas es menor al configurado en min_examined_row_limit.
• Si la sentencia es un comando administrativo y log_slow_admin_statements está en OFF.

Esta distinción técnica explica por qué, en versiones modernas, una sentencia DELETE o UPDATE que se queda bloqueada por otra transacción aparecerá en el log con un Query_time elevado y un Lock_time casi idéntico, reflejando que la mayor parte del tiempo fue latencia de espera y no procesamiento activo de filas.