Jun 5, 2020

4 min read

Habilitar logging detallado en Aurora-MySQL

Estaba trabajando con un cluster productivo de Aurora-Mysql y comenzamos a identificar algunas demoras en ejecución de consultas. Así surgió la necesidad de habilitar todo el logging detallado en Aurora para identificar las demoras en las consultas.

Detalles del Cluster Aurora-MySQL

2 instancias db.r4.2xlarge.
Deployment: Multi AZ.
Engine: Mysql 5.7.12 (Performance Insights no tiene soporte).
Tamaño: 220GB.
Consultas de lectura: 3,43/sg
Consultas de escritura: 72,7/sg
Conexiones: 1100 /sg

Paso a paso para habilitar logging en Aurora-MySQL:

Prerequisitos

Se debe modificar cada una de las instancias de la base de datos y habilitar todo el logging como se ve en la siguiente imagen:

Paso # 1 — Parameter Group:

Lo primero que se debe tener en cuenta es que se debe tener un parameter group personalizado, si se creó la base de datos con el que trae por defecto se debe reemplazar de la siguiente forma:

1- Crear un nuevo parameter group de tipo DB cluster parameter group.

2- Se debe asociar a la instancia (no requiere reinicio todavía).

3- Para que tome los cambios se debe reiniciar el cluster, primero el nodo reader y después el nodo writer.

Paso # 2 — Configurar el Parameter Group:

Se deben editar del cluster parameter group los siguientes campos:

1- server_audit_event: Define los eventos que se van a enviar al log.

Valores permitidos:

CONNECT: Registra conexiones exitosas, fallidas y desconexiones.
QUERY: Registra todas las consultas en texto sin formato, incluidas las consultas que fallan debido a errores de sintaxis o permisos.
QUERY_DCL: Solo devuelve consultas del lenguaje de control de datos (DCL) (GRANT, REVOKE, etc.).
QUERY_DDL: Solo devuelve consultas del lenguaje de definición de datos (DDL) (CREATE, ALTER, etc.).
QUERY_DML: Solo devuelve consultas del lenguaje de manipulación de datos (DML) (INSERT, UPDATE, etc., y también SELECT).
TABLE: Registra las tablas que se vieron afectadas por la ejecución de la consulta.

2- server_audit_logging: Permite habilitar el logging avanzado.

Valores permitidos: 0/1

3- server_audit_logs_upload: Habilita la carga de logs a cloudwatch.

Valores permitidos: 0/1

4- slow_query_log: Consultas que están tomando más tiempo.

Valores permitidos: 0/1

5- long_query_time: Para evitar que las consultas de ejecución rápida se registren en el slow_query_log, se debe especificar un valor para el menor tiempo de ejecución de consultas que se registrará en segundos. El valor por defecto es 10 segundos.

Valores permitidos: 0–31536000

Consultar Logging detallado en Aurora-MySQL

En cloudwatch se van a crear unos log group de la siguiente forma:

/aws/rds/cluster/CLUSTER_NAME/slowquery: Guarda la información de las slow queries.
/aws/rds/cluster/CLUSTER_NAME/audit: Contiene todos los eventos restantes.
/aws/rds/cluster/CLUSTER_NAME/error: Errores de la base de datos.

Resultados de Slow Queries

Revisando en los grupos de logs de cloudwatch se pueden ver las queries en mucho detalle, incluyendo el tiempo que toma y la cantidad de filas que afecta:

# Time: 2020–05–25T19:54:15.240980Z
# User@Host: admin[admin] @ [10.10.2.109] Id: 23436326
# Query_time: 13.553803 Lock_time: 0.000094 Rows_sent: 30 Rows_examined: 5611008
SET timestamp=1590436455;
select xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx 
 FROM xxxxxxxxxxxxxxxxxxxxxxxxxxxxxx 
 INNER JOIN xxxxxxxxxxxxxxxx ON xxxxxxxx=xxxxxxxx and yyyyyyy=yyyyyy  
 WHERE xxxxxxx  BETWEEN ‘FECHA_1’ and ‘FECHA_2’ AND xxxxxxxxx=12345678 
 GROUP BY xxxxxx, yyyyy, wwwwww, zzzzzz;

En este caso vemos lo siguiente:

Tiempo de ejecución: 13,5 sg
Filas resultantes: 30
Filas examinadas: 5611008

# Time: 2020-05-25T20:02:30.321178Z
# User@Host: admin[admin] @  [10.10.2.109]  Id: 23443701
# Query_time: 17.499512  Lock_time: 0.000117 Rows_sent: 3730  Rows_examined: 54081143
SET timestamp=1590436950;
select DATE_FORMAT(fecha,'%Y-%m-%d %k:00:00') as xxxxxxxxx ,count(xxx) as xxxxx,yyyyy,wwwwww,zzzzzzz,sssssss,ffffffff,ggggggg,hhhhhhh,uuuuuuuuu from xxxxxxxxxx 
  LEFT JOIN xxxxxx ON rrrrrrr=jjjjjjj    
  LEFT JOIN xxxxxxxxxx ON xxxxxxxx=yyyyyyy and wwwww=zzzzzz   
  where fecha between '2020-05-25 14:00:00' and '2020-05-25 14:59:59'
  GROUP BY DATE_FORMAT(r.fecha,'%Y-%m-%d %k:00:00'),xxxxxxx,yyyyyy 
  ORDER BY DATE_FORMAT(r.fecha,'%Y-%m-%d %k:00:00'),yyyyyyy;

En este caso vemos lo siguiente:

Tiempo de ejecución: 17,4 sg
Filas resultantes: 3730
Filas examinadas: 54081143

Resultados de Audit Queries

Acá se puede ver la consulta completa incluyendo los valores que específicos en el WHERE:

'SELECT xxxxx, xxxx AS xxx, xxxx AS xxxx, xxxx AS xxx, xxx AS xxxx, xxxx AS xxxx, xxxxx AS xxxxx, xxxxx AS xxxxx FROM xxxxx WHERE xxxxxx = \'9000923851\' AND xxxxxxxxx = 35',0

Resultados de Error

Acá se ven los errores con más detalle de las conexiones a la BD:

2020-05-25T16:39:28.113003Z 23255151 [Note] Aborted connection 23255151 to db: 'xxxxx' user: 'admin' host: '34.72.xx.xxx' (Got an error reading communication packets)

Recomendaciones Finales

1- En bases de datos productivas es recomendado siempre habilitar el logging detallado para conocer sobre errores, las consultas y todo lo de auditoria.

2- Tenga cuidado con el billing de cloudwatch, este se puede incrementar por la cantidad de eventos que genera la BD.