Cloud Intelligence™

Cómo capturar sentencias SQL con AWS RDS MySQL

By Ronald BradfordNov 9, 202321 min read

Esta página también está disponible en English, Deutsch, Français, Italiano, 日本語 y Português.

Captura de sentencias SQL en RDS MySQL

En este artículo voy a mostrarte todas las capacidades nativas de MySQL para capturar sentencias SQL cuando usas AWS Relational Database Service (RDS). Identificar las sentencias SQL es un principio clave de diseño y operación que te ayuda a entender cómo se usa tu aplicación, su carga, el impacto en el rendimiento y los cuellos de botella de configuración de la base de datos.

El objetivo de este artículo es mostrar cómo "capturar" la información de las sentencias SQL. No voy a abordar la información complementaria que también puedes obtener junto con una sentencia SQL, como el Query Execution Plan (QEP), la estructura de la tabla, la cardinalidad de los índices, la configuración del optimizador y las estadísticas. Eso lo cubriré en una próxima publicación.

Recopilación de sentencias SQL

MySQL ofrece varias formas de recopilar sentencias SQL en ejecución o ya ejecutadas. Ningún método es por sí solo el mejor, y normalmente hace falta combinar varios para reunir información suficiente que permita una observabilidad detallada del sistema y un análisis más profundo de las sentencias SQL. Puedes usar estos distintos métodos, y cada uno admite a su vez varias maneras de obtener los mismos detalles.

Processlist
Performance Schema
Sys Schema
Slow query log
General query log
Binary log

Salvo que se indique lo contrario, en los siguientes ejemplos de salida se utiliza el cliente de línea de comandos mysql.

NOTA: Los ejemplos de SQL que aquí se muestran son compatibles con MySQL 5.7 y MySQL 8.0. Debido al fin de vida (EOL) de la edición community de MySQL 5.7 y al próximo EOL de AWS RDS MySQL 5.7, todas las salidas de ejemplo y las referencias a la documentación corresponden a la versión actual de MySQL 8.0. Algunas salidas que verás en este artículo pueden variar respecto a las que se obtienen con MySQL 5.7.

1\. SQL con el processlist de MySQL

El processlist de MySQL muestra las sentencias SQL que se están ejecutando en ese momento, es decir, las que están corriendo justo cuando ejecutas la sentencia processlist. Para consultas de larga duración es un método sencillo para encontrar sentencias SQL. En cambio, para sentencias SQL de alta frecuencia y baja latencia puede ser muy difícil observarlas a través del processlist de MySQL. Además de la sentencia SQL en ejecución, puedes obtener detalles del usuario y host de origen, el schema de base de datos en uso, el tiempo de ejecución (en segundos) y el estado interno actual de la consulta.

Puedes obtener la salida del processlist de MySQL por distintas vías:

performance schema
sys schema
information schema
sentencia SHOW
comando mysqladmin

No hay una ventaja específica de una opción sobre otra cuando la salida ofrece las mismas columnas de información. Algunas de estas opciones no estaban disponibles en versiones anteriores de MySQL y se incorporaron siguiendo estándares aceptados de la industria que sí son sentencias SQL ISO válidas, mientras que SHOW no lo es. El comando mysqladmin ofrece distintas opciones de administración y permite combinar varias salidas, como se ve en el ejemplo.

Processlist mediante Performance Schema

Cuando está habilitado, las tablas threads y processlist de performance_schema entregan esta información.

mysql> SELECT * FROM performance_schema.processlist;
+-----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| ID  | USER            | HOST               | DB      | COMMAND | TIME | STATE                  | INFO                                                                                                                                                                      |
+-----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|   5 | event_scheduler | localhost          | NULL    | Daemon  |  456 | Waiting on empty queue | NULL                                                                                                                                                                      |
|   9 | rdsadmin        | localhost          | NULL    | Sleep   |    0 |                        | NULL                                                                                                                                                                      |
|  11 | rdsadmin        | localhost          | NULL    | Sleep   |    0 |                        | NULL                                                                                                                                                                      |
|  19 | rdsadmin        | localhost          | NULL    | Sleep   |    3 |                        | NULL                                                                                                                                                                      |
|  23 | rdsadmin        | localhost          | NULL    | Sleep   |   65 |                        | NULL                                                                                                                                                                      |
| 263 | rdsadmin        | localhost          | NULL    | Sleep   |    0 |                        | NULL                                                                                                                                                                      |
| 404 | dba             | 172.31.16.14:43464 | airport | Query   |    0 | executing              | SELECT SQL_NO_CACHE a.country_code, c.name, COUNT(*) AS cnt FROM airport a INNER JOIN country c USING (country_code) GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10 |
| 406 | dba             | 172.31.16.14:43484 | airport | Query   |    0 | executing              | SELECT * FROM performance_schema.processlist                                                                                                                              |
+-----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

Para más información, consulta el Manual de Referencia de MySQL 8.0.

Processlist mediante Sys Schema

Las vistas processlist y session del sys schema dan acceso a las sentencias SQL y a información complementaria. Estas vistas se construyen sobre el performance schema, que debe estar habilitado para capturar SQL a través del sys schema. Además, aportan atributos extra de metadatos junto con la sentencia SQL. Este es el ejemplo usando la vista sys.x$processlist.

mysql> SELECT * FROM sys.x$processlist WHERE command = 'Query'\G
*************************** 1. row ***************************
                thd_id: 675
               conn_id: 650
                  user: [email protected]
                    db: airport
               command: Query
                 state: executing
                  time: 0
     current_statement: SELECT a.country_code, c.name, COUNT(*) AS cnt FROM airport a INNER JOIN country c USING (country_code) GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10
     statement_latency: 116727428000
              progress: NULL
          lock_latency: 506000000
         rows_examined: 0
             rows_sent: 0
         rows_affected: 0
            tmp_tables: 1
       tmp_disk_tables: 0
             full_scan: YES
        last_statement: NULL
last_statement_latency: NULL
        current_memory: 165019
             last_wait: NULL
     last_wait_latency: NULL
                source: NULL
           trx_latency: 116250140000
             trx_state: ACTIVE
        trx_autocommit: YES
                   pid: 15730
          program_name: mysql

El terminador de sentencia anterior produce un formato de tabla vertical, es decir, columna: valor por fila, en lugar del tradicional formato horizontal de columnas y filas. Aquí se usa el terminador de sentencia SQL '\G' en vez del clásico punto y coma ';'. Esta sintaxis es propia del cliente mysql y no funciona en clientes GUI de terceros.

NOTA: Si recibes el siguiente mensaje de error, puedes ejecutar sin problema la sentencia SET SQL_BIG_SELECTS=1; antes de la sentencia SQL anterior.

ERROR 1104 (42000) at line 1: The SELECT would examine more than
MAX_JOIN_SIZE rows; check your WHERE and use SET SQL_BIG_SELECTS=1
or SET MAX_JOIN_SIZE=# if the SELECT is okay

Para más información, consulta el Manual de Referencia de MySQL 8.0.

Processlist mediante Information Schema

Aunque el Information Schema es un estándar de facto en muchos productos RDBMS, la tabla processlist no es estándar. En MySQL puedes consultar la información con la siguiente sentencia.

mysql > SELECT * FROM information_schema.processlist;
+----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| ID | USER            | HOST               | DB      | COMMAND | TIME | STATE                  | INFO                                                                                                                                                                      |
+----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 88 | dba             | 172.31.16.14:59474 | airport | Query   |    0 | executing              | SELECT SQL_NO_CACHE a.country_code, c.name, COUNT(*) AS cnt FROM airport a INNER JOIN country c USING (country_code) GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10 |
|  9 | rdsadmin        | localhost          | NULL    | Sleep   |    0 |                        | NULL                                                                                                                                                                      |
| 26 | rdsadmin        | localhost          | NULL    | Sleep   |    1 |                        | NULL                                                                                                                                                                      |
| 11 | rdsadmin        | localhost          | NULL    | Sleep   |    0 |                        | NULL                                                                                                                                                                      |
| 19 | rdsadmin        | localhost          | NULL    | Sleep   |    9 |                        | NULL                                                                                                                                                                      |
|  5 | event_scheduler | localhost          | NULL    | Daemon  |  352 | Waiting on empty queue | NULL                                                                                                                                                                      |
| 94 | dba             | 172.31.16.14:59522 | airport | Query   |    0 | executing              | SELECT * FROM information_schema.processlist                                                                                                                              |
| 23 | rdsadmin        | localhost          | NULL    | Sleep   |  261 |                        | NULL                                                                                                                                                                      |
+----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

Para más información, consulta el Manual de Referencia de MySQL 8.0

Processlist mediante la sentencia SHOW

Antes de la llegada del Information Schema en la versión 5.1 y del Performance Schema en la 5.5, la principal forma de capturar el processlist en MySQL era con el comando SHOW.

mysql> SHOW FULL PROCESSLIST;

Esta salida es idéntica a la del SELECT * FROM performance_schema.processlist; que se mostró antes. La palabra clave FULL es necesaria para obtener las sentencias sin truncar.

Para más información, consulta el Manual de Referencia de MySQL 8.0.

Processlist mediante el cliente _mysqladmin_

Otra herramienta cliente de MySQL, mysqladmin, que se usa para realizar diversas operaciones administrativas, también puede generar una salida del processlist en ejecución en formato tabular.

$ mysqladmin --verbose processlist status
+-----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Id  | User            | Host               | db      | Command | Time | State                  | Info                                                                                                                                                          |
+-----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 5   | event_scheduler | localhost          |         | Daemon  | 1419 | Waiting on empty queue |                                                                                                                                                               |
| 9   | rdsadmin        | localhost          |         | Sleep   | 1    |                        |                                                                                                                                                               |
| 11  | rdsadmin        | localhost          |         | Sleep   | 1    |                        |                                                                                                                                                               |
| 19  | rdsadmin        | localhost          |         | Sleep   | 6    |                        |                                                                                                                                                               |
| 23  | rdsadmin        | localhost          |         | Sleep   | 128  |                        |                                                                                                                                                               |
| 771 | rdsadmin        | localhost          |         | Sleep   | 3    |                        |                                                                                                                                                               |
| 830 | dba             | 172.31.16.14:54000 | airport | Query   | 0    | executing              | SELECT  a.country_code, c.name, COUNT(*) AS cnt FROM airport a INNER JOIN country c USING (country_code) GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10 |
| 832 | dba             | 172.31.16.14:54026 |         | Query   | 0    | init                   | show full processlist                                                                                                                                         |
+-----+-----------------+--------------------+---------+---------+------+------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------+
Uptime: 1421  Threads: 8  Questions: 14058  Slow queries: 1290  Opens: 261  Flush tables: 3  Open tables: 181  Queries per second avg: 9.893

Si no especificas --verbose, recibirás sentencias SQL truncadas, incluso para esta sentencia tan corta. Por ejemplo:

| 786 | dba             | 172.31.16.14:59446 | airport | Query   | 0    | executing              | SELECT  a.country_code, c.name, COUNT(*) AS cnt FROM airport a INNER JOIN country c USING (country_c |

Para más información, consulta el Manual de Referencia de MySQL 8.0

2\. SQL con el Performance Schema

Cuando el Performance Schema está habilitado y los consumidores correspondientes están activados, varias tablas permiten obtener información detallada sobre las sentencias SQL ejecutadas y en ejecución.

Opciones de configuración

En MySQL nativo, el performance schema se habilita así:

mysql> SET GLOBAL performance_schema=1;

Con el servicio gestionado AWS RDS debes usar parameter groups para modificar parámetros. Por ejemplo:

$ modify-parameter ${PG_NAME} performance_schema 1 pending-reboot

NOTA: Para una instancia RDS, esto se refiere al parameter group de la instancia. Cuando una instancia forma parte de un cluster AWS RDS Aurora, existe un parameter group de cluster que es el predeterminado, salvo que sus valores se sobrescriban desde el parameter group de la instancia.

Cuando el performance schema se habilita por primera vez, hay que reiniciar la instancia MySQL y, por lo tanto, la instancia AWS RDS.

$ aws rds reboot-db-instance --db-instance-identifier ${INSTANCE_ID}

Los consumidores e instrumentos del performance schema para capturar sentencias SQL vienen habilitados por defecto, aunque pueden modificarse en una instancia MySQL en ejecución. Puedes verificar la configuración actual con:

mysql> SELECT * FROM performance_schema.setup_instruments WHERE NAME LIKE 'statement/%';
mysql> SELECT * FROM performance_schema.setup_consumers WHERE NAME LIKE '%statements%';

Validación de la configuración

Con la siguiente sentencia se puede confirmar si el performance schema está habilitado.

mysql> SELECT @@performance_schema;
+----------------------+
| @@performance_schema |
+----------------------+
|                    1 |
+----------------------+

Tabla processlist del Performance Schema

Como ya se mostró, la tabla processlist entrega información básica sobre las sentencias en ejecución.

Tabla threads del Performance Schema

La tabla threads muestra atributos adicionales de las sentencias SQL en ejecución.

mysql> SELECT * FROM performance_schema.threads WHERE PROCESSLIST_STATE="executing"\G
*************************** 1. row ***************************
          THREAD_ID: 960
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 935
   PROCESSLIST_USER: dba
   PROCESSLIST_HOST: 172.31.16.14
     PROCESSLIST_DB: airport
PROCESSLIST_COMMAND: Query
   PROCESSLIST_TIME: 0
  PROCESSLIST_STATE: executing
   PROCESSLIST_INFO: SELECT  a.country_code, c.name, COUNT(*) AS cnt FROM airport a INNER JOIN country c USING (country_code) GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10
   PARENT_THREAD_ID: NULL
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: SSL/TLS
       THREAD_OS_ID: 353
     RESOURCE_GROUP: NULL

Tablas events_statements_* del Performance Schema

El verdadero punto fuerte del performance schema es su capacidad de capturar sentencias SQL ejecutadas recientemente, una herramienta esencial para sentencias SQL que se ejecutan muy rápido.

mysql> SELECT * FROM performance_schema.events_statements_current WHERE SQL_TEXT like '%airport%'\G
*************************** 1. row ***************************
              THREAD_ID: 981
               EVENT_ID: 4
           END_EVENT_ID: NULL
             EVENT_NAME: statement/sql/select
                 SOURCE: init_net_server_extension.cc:110
            TIMER_START: 2471111163284000
              TIMER_END: 2471111453481000
             TIMER_WAIT: 290197000
              LOCK_TIME: 175000000
               SQL_TEXT: SELECT * FROM performance_schema.events_statements_current WHERE SQL_TEXT like '%airport%'
                 DIGEST: 2fdfe28204e80c382a14597873be575ea8c7ede6e4757e77700a333bbe50b025
            DIGEST_TEXT: SELECT * FROM `performance_schema` . `events_statements_current` WHERE `SQL_TEXT` LIKE ?
         CURRENT_SCHEMA: NULL
            OBJECT_TYPE: NULL
          OBJECT_SCHEMA: NULL
            OBJECT_NAME: NULL
  OBJECT_INSTANCE_BEGIN: NULL
            MYSQL_ERRNO: 0
      RETURNED_SQLSTATE: NULL
           MESSAGE_TEXT: NULL
                 ERRORS: 0
               WARNINGS: 0
          ROWS_AFFECTED: 0
              ROWS_SENT: 0
          ROWS_EXAMINED: 0
CREATED_TMP_DISK_TABLES: 0
     CREATED_TMP_TABLES: 0
       SELECT_FULL_JOIN: 0
 SELECT_FULL_RANGE_JOIN: 0
           SELECT_RANGE: 0
     SELECT_RANGE_CHECK: 0
            SELECT_SCAN: 1
      SORT_MERGE_PASSES: 0
             SORT_RANGE: 0
              SORT_ROWS: 0
              SORT_SCAN: 0
          NO_INDEX_USED: 1
     NO_GOOD_INDEX_USED: 0
       NESTING_EVENT_ID: NULL
     NESTING_EVENT_TYPE: NULL
    NESTING_EVENT_LEVEL: 0
           STATEMENT_ID: 22413
1 row in set (0.01 sec)

Otras tablas de performance que incluyen sentencias SQL ejecutadas son events_statements_current, events_statements_history y events_statements_long. Para más información, consulta el Manual de Referencia de MySQL 8.0.

3\. SQL con el Sys Schema

El sys schema de MySQL es un conjunto de objetos y vistas que interpretan los datos disponibles en el Performance Schema y los presentan de forma más amigable para el usuario final. También muestra sentencias SQL ejecutadas y estadísticas agregadas de las ejecuciones. La primera vista a tener en cuenta es statement_analysis, o x$statement_analysis.

mysql> select * from sys.x$statement_analysis where query like '%airport%'\G
*************************** 1. row ***************************
            query: SELECT `a` . `country_code` , `c` . `name` , COUNT ( * ) AS `cnt` FROM `airport` `a` INNER JOIN `country` `c` USING ( `country_code` ) GROUP BY `country_code` , NAME ORDER BY ? DESC LIMIT ?
               db: airport
        full_scan: *
       exec_count: 8
        err_count: 0
       warn_count: 0
    total_latency: 1330746923000
      max_latency: 304276507000
      avg_latency: 166343365000
     lock_latency: 1937000000
        rows_sent: 80
    rows_sent_avg: 10
    rows_examined: 1223680
rows_examined_avg: 152960
    rows_affected: 0
rows_affected_avg: 0
       tmp_tables: 8
  tmp_disk_tables: 0
      rows_sorted: 80
sort_merge_passes: 0
           digest: 616aa31e4f99b22a194c91ae9f1cfbfb95d6957621b55393b4a01603d8e1fd47
       first_seen: 2023-10-12 14:55:56.021003
        last_seen: 2023-10-12 15:23:14.225503

Muchas otras tablas del sys schema incluyen sentencias SQL ejecutadas y agregaciones de subconjuntos de sentencias SQL. Algunos ejemplos son statements_with_full_table_scans y statements_with_temp_tables. Para más información, consulta el Manual de Referencia de MySQL 8.0.

4\. SQL con el slow query log

Cuando está habilitado, el slow query log hace exactamente lo que su nombre indica: registra todas las consultas lentas que superan un tiempo de ejecución predefinido. En versiones anteriores la unidad eran segundos. En MySQL 5.7 y posteriores se mide en microsegundos. El valor 0 también es válido y significa registrar todas las sentencias SQL ejecutadas. Eso sí, ten en cuenta que esto supone una sobrecarga de rendimiento y un costo adicional en una base de datos con alta concurrencia.

Opciones de configuración

En MySQL nativo puedes habilitar el slow query log con:

mysql> SET GLOBAL slow_query_log=1;
mysql> SET GLOBAL long_query_time=0.001;
mysql> SET GLOBAL log_output=FILE;   /* This is the default */

Con el servicio gestionado AWS RDS debes usar parameter groups para modificar parámetros. Estos cambios son inmediatos. Por ejemplo:

$ modify-parameter ${PG_NAME} slow_query_log 1
$ modify-parameter ${PG_NAME} long_query_time 0.001
$ modify-parameter ${PG_NAME} log_output FILE

Hay varios parámetros de configuración adicionales que no abordaremos, entre ellos slow_query_log_file, log_queries_not_using_indexes y log_slow_admin_statements.

NOTA: Conviene evaluar con cuidado el impacto de habilitar estas opciones adicionales del slow query log. Cada una puede generar grandes volúmenes de sentencias SQL que aumentan el tamaño del archivo de log. Pueden quedar registradas consultas que hacen un escaneo completo de tabla a propósito por tener pocas filas, o sentencias administrativas frecuentes esenciales para la instrumentación y la observabilidad con herramientas de monitoreo.

Validación de la configuración

Para confirmar que el slow query log está habilitado y configurado:

mysql> SELECT @@slow_query_log, @@long_query_time, @@log_output;
+------------------+-------------------+--------------+
| @@slow_query_log | @@long_query_time | @@log_output |
+------------------+-------------------+--------------+
|                1 |          0.001000 | FILE         |
+------------------+-------------------+--------------+

Para más información, consulta el Manual de Referencia de MySQL 8.0.

Descargar el slow query log desde AWS RDS

Cuando está habilitado, el slow query log escribe en un archivo de log dentro de tu instancia RDS. Puedes obtenerlo con el AWS CLI.

$ INSTANCE_ID=
$ aws rds download-db-log-file-portion  \
   --db-instance-identifier ${INSTANCE_ID} \
   --starting-token 0 \
   --output text \
   --log-file-name slowquery/mysql-slowquery.log > slowquery.log

Los archivos del slow log de RDS rotan cada hora. Con los siguientes comandos puedes ver todos los archivos de log disponibles para descargar.

$ aws rds describe-db-log-files --db-instance-identifier ${INSTANCE_ID}

{
    "DescribeDBLogFiles": [\
...\
        {\
            "LogFileName": "slowquery/mysql-slowquery.log",\
            "LastWritten": 1697125638054,\
            "Size": 761426\
        },\
        {\
            "LogFileName": "slowquery/mysql-slowquery.log.2023-10-12.14",\
            "LastWritten": 1697121600696,\
            "Size": 60517\
        },\
        {\
            "LogFileName": "slowquery/mysql-slowquery.log.2023-10-12.15",\
            "LastWritten": 1697122801087,\
            "Size": 343085\
        }\
    ]
}

Información disponible en el slow query log

Cada sentencia SQL en el slow query log incluye los siguientes datos:

Tiempo de ejecución
Usuario y Host
Thread Id
Query time
Lock time
Rows sent
Rows examined
Sentencia SQL completa

Ejemplo de salida del slow query log

# Time: 2023-10-05T15:56:58.831165Z
# User@Host: dba[dba] @  [172.31.16.14]  Id:   295
# Query_time: 0.259097  Lock_time: 0.000178 Rows_sent: 10  Rows_examined: 76733
SET timestamp=1696521418;
SELECT a.country_code, c.name, COUNT(*) AS cnt
FROM airport a
  INNER JOIN country c USING (country_code)
GROUP BY country_code, name
ORDER BY 3 DESC
LIMIT 10;

NOTA: El slow query log está bien estructurado: todas las líneas que no son comentarios son sentencias SQL reales y están correctamente terminadas, lo que facilita mucho recopilarlas, registrarlas y ejecutarlas. La única limitación es que cuando las tablas no están calificadas con su schema, hace falta conocer el schema de tu base de datos.

Slow query log mediante tabla SQL

Aunque por lo general no se recomienda, es posible recopilar consultas lentas mediante una sentencia SQL cuando el slow query log está habilitado y se utiliza la configuración log_output=TABLE.

Recopilación SQL de información del slow query log

La siguiente sentencia SQL permite recuperar las consultas registradas en la tabla mysql.slow_log.

# Table does not have a PK, so this is a crud hack
SELECT sl.*,
       CONVERT(q.sql_text USING utf8mb4)AS query
FROM mysql.slow_log sl
INNER JOIN mysql.slow_log q  USING (start_time)
WHERE CONVERT(q.sql_text USING utf8mb4) like '%airport%'\G

Ejemplo de salida del slow query log mediante tabla

    start_time: 2023-10-05 15:59:30.878226
     user_host: dba[dba] @  [172.31.16.14]
    query_time: 00:00:00.295653
     lock_time: 00:00:00.000164
     rows_sent: 10
 rows_examined: 76733
            db: airport
last_insert_id: 0
     insert_id: 0
     server_id: 1843089174
      sql_text: 0x53454C45435420612E636F756E7472795F636F64652C20632E6E616D652C20434F554E54282A2920415320636E742046524F4D20616972706F72742061202020494E4E4552204A4F494E20636F756E7472792063205553494E472028636F756E7472795F636F6465292047524F555020425920636F756E7472795F636F64652C206E616D65204F5244455220425920332044455343204C494D4954203130
     thread_id: 295
         query: SELECT a.country_code, c.name, COUNT(*) AS cnt FROM airport a   INNER JOIN country c USING (country_code) GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10

5\. SQL con el general query log

Si lo configuras, MySQL puede registrar todas las sentencias SQL en el general query log.

NOTA: Hay que pensar bien en qué entorno habilitar el general query log y por cuánto tiempo. El siguiente ejemplo corresponde a un sistema 100 % inactivo y a las 12 sentencias SQL adicionales ejecutadas en el mismo segundo que nuestra sentencia SQL de ejemplo.

ADVERTENCIA: Al igual que con el slow query log, es posible registrar esta salida en una tabla de MySQL. No es recomendable, ya que puede impactar de manera significativa el rendimiento de un sistema en ejecución.

Opciones de configuración

En MySQL nativo puedes habilitar el general query log con:

mysql> SET GLOBAL general_log=1;
mysql> SET GLOBAL log_output=FILE;   /* This is the default */

Con el servicio gestionado AWS RDS debes usar parameter groups para modificar parámetros. Estos cambios son inmediatos. Por ejemplo:

$ modify-parameter ${PG_NAME} general_log 1
$ modify-parameter ${PG_NAME} log_output FILE

Hay un parámetro de configuración adicional que no abordaremos aquí: la variable general_log_file.

Validación de la configuración

Para confirmar que el general query log está habilitado y configurado:

mysql> SELECT @@general_log, @@log_output, @@general_log_file;
+---------------+--------------+------------------------------------------+
| @@general_log | @@log_output | @@general_log_file                       |
+---------------+--------------+------------------------------------------+
|             1 | FILE         | /rdsdbdata/log/general/mysql-general.log |
+---------------+--------------+------------------------------------------+

Para más información, consulta el Manual de Referencia de MySQL 8.0.

Descargar el general query log desde AWS RDS

Cuando está habilitado, el general query log escribe en un archivo de log dentro de tu instancia RDS. Puedes obtenerlo con el AWS CLI.

$ INSTANCE_ID=
$ aws rds download-db-log-file-portion  \
   --db-instance-identifier ${INSTANCE_ID} \
   --starting-token 0 \
   --output text \
   --log-file-name general/mysql-general.log > general.log

Como se mencionó en la sección anterior, puedes usar el argumento describe-db-log-files para listar los archivos del general query log que ya rotaron.

Ejemplo de salida del general query log

2023-10-05T17:31:06.006853Z         9 Query     set local oscar_local_only_replica_host_status=1;
2023-10-05T17:31:06.006963Z         9 Query     SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2023-10-05T17:31:06.007500Z         9 Query     set local oscar_local_only_replica_host_status=0
2023-10-05T17:31:06.836552Z       540 Query     SELECT
       a.country_code, c.name, COUNT(*) AS cnt
FROM   airport a
INNER JOIN country c USING (country_code)
GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10
2023-10-05T17:31:06.932194Z         9 Query     set local oscar_local_only_replica_host_status=1;
2023-10-05T17:31:06.932368Z         9 Query     SELECT durable_lsn, current_read_point, server_id, last_update_timestamp FROM information_schema.replica_host_status;
2023-10-05T17:31:06.933104Z         9 Query     set local oscar_local_only_replica_host_status=0
2023-10-05T17:31:06.935817Z        11 Query     SET @@sql_log_bin=off
2023-10-05T17:31:06.936615Z        11 Query     select @@session.transaction_read_only
2023-10-05T17:31:06.937118Z        11 Query     INSERT INTO mysql.rds_heartbeat2(id, value) values (1,1696527066936) ON DUPLICATE KEY UPDATE value = 1696527066936
2023-10-05T17:31:06.947853Z        11 Query     select @@session.transaction_read_only
2023-10-05T17:31:06.948293Z        11 Query     COMMIT
2023-10-05T17:31:06.948725Z        11 Query     SET @@sql_log_bin=on

NOTA: El general query log está semiestructurado. Las sentencias SQL pueden ocupar varias líneas, conservando el formato con el que llegaron a MySQL desde tu programa cliente. No basta con eliminar los primeros 41 caracteres de cada línea para recopilar las sentencias SQL.

Para más información, consulta el Manual de Referencia de MySQL 8.0.

6\. SQL con el binary log

Muchas veces se pasa por alto, pero el binary log de MySQL, cuando está habilitado, es una mina de información sobre las sentencias SQL que escriben en tu base de datos. El binary log puede ser clave para identificar los límites de las transacciones y la secuencia de sentencias SQL dentro de una transacción, lo que ayuda al revisar bloqueos. También aporta el detalle completo de las columnas en sentencias INSERT, UPDATE y DELETE.

Toda configuración de instancia RDS que use réplicas de lectura tiene el binary log habilitado por defecto.

Validación de la configuración

Para confirmar que el binary log está habilitado y configurado:

mysql> SELECT @@log_bin, @@binlog_format, @@log_statements_unsafe_for_binlog, @@log_bin_trust_function_creators;
+-----------+-----------------+------------------------------------+-----------------------------------+
| @@log_bin | @@binlog_format | @@log_statements_unsafe_for_binlog | @@log_bin_trust_function_creators |
+-----------+-----------------+------------------------------------+-----------------------------------+
|         0 | ROW             |                                  1 |                                 0 |
+-----------+-----------------+------------------------------------+-----------------------------------+

Puedes identificar los binary logs disponibles en tu instancia MySQL con:

mysql> SHOW BINARY LOGS;

Puedes descargar los binary logs con el comando mysqlbinlog. Por ejemplo:

$ TMP_DIR=${TMP_DIR:-/tmp}
$ AUTHENTICATION="-h<host> -u<user> -p<password"
$ BINLOG_FILE="binlog.00042"
mysqlbinlog --read-from-remote-server --raw --result-file=${TMP_DIR}/ ${AUTHENTICATION} ${BINLOG_FILE} 2>/dev/null # Kill warning message and not mess with $?

Puedes ver el contenido del binary log con el comando mysqlbinlog. Según tu configuración, algunos argumentos resultan más adecuados, pero esta combinación suele funcionar bien para todos los formatos:

$ mysqlbinlog -vvv --base64-output=DECODE-ROWS ${TMP_DIR}/${BINLOG_FILE}

Analizar el binary log es un proceso más detallado que no abordaremos aquí. Este análisis también depende del valor de la variable de configuración del formato de fila del binary log. Puedes obtener un resumen por tabla de un archivo determinado, o de un período con uno o más archivos, usando argumentos adicionales. Este fragmento entrega un resumen por tabla cuando se usa binlog_format=ROW.

mysqlbinlog ${BINLOG_ADDITIONAL_ARGS} ${TMP_DIR}/${BINLOG_FILE}  | \
  sed -e "s/^### //;" | \
  sed -e "/^#/d;s/\/\*.*\*\/[;]//;/^$/d" | \
  cut -c1-100 | \
  tr '[A-Z]' '[a-z]' | \
  egrep "^(insert|update|delete|replace|commit|alter|drop|create)" |  \
  sed -e "s/\t/ /g;s/\`//g;s/(.*$//;s/ set .*$//;s/ as .*$//;s/ join .*$//;s/ values .*$//;" | sed -e "s/ where .*$//;s/ignore //g;s/ inner//g;s/ left//g;s/ right//g;s/ from//g;s/ into//g" |  \
  sed -e "s/or replace//;s/sql security definer//;s/algorithm=.* //;s/definer=.* //g" |  \
  sed -e "s/ \w.*\.\*//" | \
  awk '{ print $1,$2 }' | \
  sort | uniq -c | sort -nr

Puedes obtener una copia del script completo, que incluye la descarga y el procesamiento de un archivo de binary log, en este gist de Github.

Para más información, consulta el Manual de Referencia de MySQL 8.0.

Resumen de las opciones de recopilación de SQL

Estos son los principales beneficios y limitaciones de cada opción. La mejor manera de saber cuál se adapta a tus necesidades es probar cada una siguiendo los pasos descritos en este artículo.

Beneficios del Processlist

Habilitado por defecto

Limitaciones del Processlist

Solo captura las sentencias SQL que se están ejecutando en ese instante
Requiere privilegios elevados para ver todas las consultas de todos los usuarios

Beneficios del Performance Schema

Captura sentencias ejecutadas previamente, además de las que se están ejecutando
Entrega resultados agregados, ideales para consultas de alta frecuencia

Limitaciones del Performance Schema

Debe estar habilitado. Requiere un reinicio para la primera activación
Necesita ajustes en sistemas de alto rendimiento para limitar la sobrecarga de recursos

Beneficios del Sys Schema

Extiende el performance schema con vistas y objetos muy útiles, bien nombrados y orientados a propósitos específicos

Limitaciones del Sys Schema

Requiere que el performance schema esté habilitado

Beneficios del slow query log

Captura todas las consultas lentas que superen un tiempo de ejecución predefinido

Limitaciones del slow query log

Prácticamente no tiene limitaciones. Siempre debería estar habilitado con un umbral adecuado en todas las instancias de MySQL.

Beneficios del general query log

Entrega una lista secuencial completa de todas las sentencias SQL. Es ideal para el análisis de transacciones y la evaluación de antipatrones de acceso a datos.

Limitaciones del general query log

Sobrecarga significativa en sistemas de producción con alto uso. Se recomienda usarlo con una suite de pruebas, idealmente con un solo hilo.

Beneficios del binary log

Por lo general está siempre habilitado para asegurar capacidades de HA y PITR

Limitaciones del binary log

Solo captura escrituras cuando está habilitado
Formato más complejo de procesar para capturar sentencias SQL completas

Apéndice

Datos de ejemplo utilizados

Para este artículo usamos el siguiente dataset de aeropuertos disponible en https://github.com/ronaldbradford/data/tree/main/mysql-data/airport

SQL de ejemplo utilizado

Para cada método de recopilación se usó la siguiente sentencia SQL de ejemplo.

SELECT a.country_code, c.name, COUNT(*) AS cnt
FROM airport a
INNER JOIN country c USING (country_code)
GROUP BY country_code, name ORDER BY 3 DESC LIMIT 10;

Esta sentencia SQL devolverá un conjunto de resultados como:

+--------------+----------------+-------+
| country_code | name           | cnt   |
+--------------+----------------+-------+
| US           | United States  | 30581 |
| BR           | Brazil         |  6849 |
| JP           | Japan          |  3430 |
| CA           | Canada         |  3075 |
| AU           | Australia      |  2576 |
| MX           | Mexico         |  2288 |
| RU           | Russia         |  1556 |
| KR           | South Korea    |  1400 |
| GB           | United Kingdom |  1398 |
| DE           | Germany        |  1042 |
+--------------+----------------+-------+
10 rows in set (0.47 sec)

NOTA: La cantidad real de aeropuertos y el orden de los países pueden variar según el momento en que hayas obtenido el dataset.

Recopilación de SQL

Como se trata de un sistema de prueba con uso mínimo, algunas sentencias recuperaron todas las filas posibles, mientras que otras se restringieron con una cláusula WHERE apropiada para capturar específicamente esta sentencia SQL de ejemplo. Al capturar SQL en tu propio sistema, quizá necesites aplicar filtros adecuados para acotar la salida de las sentencias.

Función auxiliar Bash modify-parameter

La siguiente función se usa en este artículo para simplificar la sintaxis al modificar variables de parameter group de AWS RDS.

modify-parameter() {
  [[ $# -lt 3 ]] || [[ $# -gt 4 ]]  && echo "ERROR: <parameter-group> <parameter> <value> [pending-reboot]" && return 1

  local PARAMETER_GROUP="$1"
  local PARAMETER_NAME="$2"
  local PARAMETER_VALUE="$3"
  local APPLY_METHOD="immediate"

  [[ $# -eq 4 ]] && APPLY_METHOD="$4"
  aws rds modify-db-parameter-group --db-parameter-group-name ${PARAMETER_GROUP} --parameters "ParameterName=${PARAMETER_NAME},ParameterValue='${PARAMETER_VALUE}',ApplyMethod=${APPLY_METHOD}"
  aws rds describe-db-parameters --db-parameter-group-name ${PARAMETER_GROUP}  --query 'Parameters[] | [?ParameterName == `'${PARAMETER_NAME}'`]'
}

Para más información, consulta la referencia de comandos de AWS CLI para la sintaxis de modify-db-parameter-group y describe-db-parameters.

Tip para identificar SQL

MySQL te permite incrustar un comentario dentro de una sentencia SQL, aunque no todas las herramientas capturan ni registran esa información. Es buena práctica que el equipo de Engineering cree algún tipo de etiqueta única para cada sentencia SQL. El contenido del comentario no es lo importante: lo es su unicidad. Poder ver una consulta con un comentario y ubicarla en el código fuente reduce el tiempo de identificación y el mean-time-to-resolve (MTTR) ante cualquier incidente.

SELECT /* Countries with the most airports */
       a.country_code, c.name, COUNT(*) AS cnt
FROM   airport a
INNER JOIN country c USING (country_code)
GROUP BY country_code, name
ORDER BY 3 DESC LIMIT 10;

Para más información, consulta el Manual de Referencia de MySQL 8.0.

Existen varios métodos nativos, mediante herramientas cliente de MySQL, para recopilar sentencias SQL desde MySQL ejecutándose en AWS RDS. Hay otras herramientas y técnicas que también permiten recopilarlas y que no se abordan en este artículo.

Recopilar una sentencia SQL es el primer paso esencial para reunir información suficiente sobre los patrones de acceso a datos de tu aplicación. Esta información puede ser crítica para el diseño arquitectónico, las pruebas y el rendimiento.

En un próximo artículo hablaré sobre la recopilación de los metadatos de soporte que acompañan a cualquier sentencia SQL para hacer análisis de rendimiento. Esto incluye el Query Execution Plan (QEP), los metadatos de tablas e índices, las estadísticas de distribución de columnas y opciones de configuración específicas que pueden incidir en la ejecución de una sentencia SQL.