En cada implementación, siempre hay algunas consultas que se ejecutan demasiado lentamente.
Siga leyendo para ver cómo descubrir consultas que tardan demasiado en ejecutarse y cómo descubrir por qué son lentas.
¿Solo usar pg_stat_statements?
pg_stat_statements es una extensión popular que se incluye en la distribución principal de PostgreSQL y está disponible de forma predeterminada en casi todos los proveedores de DBaaS. Es invaluable y es más o menos la única forma de obtener estadísticas sobre consultas sin instalar extensiones personalizadas.
Sin embargo, tiene un par de limitaciones cuando se trata de descubrir consultas lentas.
Estadísticas acumulativas
La extensión pg_stat_statements proporciona acumulativos estadísticas sobre cada consulta ejecutada por el servidor. Para cada consulta, muestra, entre otras métricas, la cantidad total de veces que se ejecutó y el tiempo total que se tomó en todas las ejecuciones.
Para "atrapar" consultas lentas cuando ocurren, debe obtener periódicamente el contenido completo de pg_stat_statements ver, almacenarlo en una base de datos de series temporales y comparar los recuentos de ejecución. Por ejemplo, si tiene el contenido de pg_stat_statements a las 10:00 a. m. y a las 10:10 a. m., puede seleccionar aquellas consultas que tengan un mayor número de ejecuciones a las 10:10 a. m. que a las 10:00 a. m. Para estas consultas, puede calcular el tiempo de ejecución promedio durante este intervalo, usando:
(total time at 10.10 AM - total time at 10.00 AM) ÷ (total count at 10.10 AM - total count at 10.00 AM)
Si este tiempo de ejecución promedio supera un umbral superior, puede activar una alerta para tomar medidas.
Esto funciona razonablemente bien en la práctica, pero necesitará una buena infraestructura de monitoreo o un servicio dedicado como pgDash.
Parámetros de consulta
pg_stat_statements no captura los valores de los parámetros de enlace pasados a las consultas.
Una de las cosas que el planificador de consultas de Postgres estima para seleccionar un plan de ejecución es la cantidad de filas que es probable que una condición filtre. Por ejemplo, si la mayoría de las filas de una tabla tienen el valor de una columna indexada país como "EE. UU.", el planificador podría decidir hacer un escaneo secuencial de toda la tabla para el dónde cláusula country = "US" y podría decidir utilizar un análisis de índice para country = "UK" desde el primer dónde se espera que la cláusula coincida con la mayoría de las filas de la tabla.
Conocer el valor real de los parámetros para los que la ejecución de la consulta fue lenta puede ayudar a diagnosticar problemas de consultas lentas más rápido.
Registro lento de consultas
La alternativa más simple es registrar consultas lentas. A diferencia de otros DBMS que lo facilitan, PostgreSQL nos presenta un montón de ajustes de configuración de aspecto similar:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Estos se describen en detalle en la documentación de Postgres. Este es un punto de partida razonable:
# next line says only log queries that take longer 5 seconds
log_min_duration_statement = 5s
log_parameter_max_length = 1024
log_parameter_max_length_on_error = 1024
Lo que da como resultado registros como estos:
2022-04-14 06:17:11.462 UTC [369399] LOG: duration: 5.060 ms statement: select i.*, t."Name" as track, ar."Name" as artist
from "InvoiceLine" as i
join "Track" as t on i."TrackId" = t."TrackId"
join "Album" as al on al."AlbumId" = t."AlbumId"
join "Artist" as ar on ar."ArtistId" = al."ArtistId";
Si hay demasiados registros, puede pedirle a Postgres que registre solo (digamos) el 50 % de las consultas que duran más de 5 segundos:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Por supuesto, debe leer los documentos sobre lo que significan e implican estos parámetros antes de agregarlos a su configuración de Postgres. Tenga en cuenta que la configuración es peculiar y poco intuitiva.
Planes de Ejecucion de Consultas Lentas
Por lo general, no es suficiente saber que se produjo una consulta lenta, también deberá averiguar por qué fue lento Para esto, normalmente primero verificará el plan de ejecución de la consulta.
auto_explain es otra extensión central de PostgreSQL (nuevamente, también disponible en la mayoría de DBaaS) que puede registrar los planes de ejecución de consultas que acaban de finalizar su ejecución. Está documentado aquí.
Para habilitar auto_explain, normalmente lo agregaría a shared_preload_libraries y reinicie Postgres. Aquí hay una configuración inicial de muestra:
# logs execution plans of queries that take 10s or more to run
auto_explain.log_min_duration = 10s
auto_explain.log_verbose = on
auto_explain.log_settings = on
auto_explain.log_format = json
auto_explain.log_nested_statements = on
# enabling these provide more information, but have a performance cost
#auto_explain.log_analyze = on
#auto_explain.log_buffers = on
#auto_explain.log_wal = on
#auto_explain.log_timing = on
#auto_explain.log_triggers = on
Esto hará que los planes se registren en formato JSON, que luego se pueden visualizar en herramientas como estas.
Aún ejecutando consultas
Todas las técnicas enumeradas anteriormente tienen una cosa en común:producen resultados procesables solo después una consulta ha terminado de ejecutarse. No se pueden usar para manejar consultas que son tan lentas esta vez, que aún no han terminado de ejecutarse.
Cada conexión a un servidor PostgreSQL es manejada por un backend , específicamente un backend de cliente . Cuando dicho backend está ejecutando una consulta, su estado es activo . También podría haber iniciado una transacción pero luego está inactivo, llamado inactivo en transacción estado.
La pg_stat_activity La vista del sistema documentada aquí proporciona una lista de todos los backends de Postgres en ejecución. Puede consultar esta vista para obtener consultas que aún se están ejecutando:
SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
Por cierto, sin usar extensiones de terceros, no hay forma de conocer el plan de ejecución de una consulta que está siendo ejecutada actualmente por un backend.
Bloqueos
Si el plan de ejecución de una consulta lenta no indica ningún problema obvio, es posible que el backend que ejecuta la consulta se haya retrasado debido a bloqueos en conflicto.
Los bloqueos se obtienen de forma explícita o implícita durante la ejecución de la consulta por diversos motivos. Hay un capítulo completo en la documentación de Postgres dedicado a esto.
Bloqueos de registro
Por lo general, se establece un límite superior de tiempo de espera mediante la opción lock_timeout , generalmente en el lado del cliente. Si una consulta ha estado esperando tanto tiempo para adquirir un bloqueo, Postgres cancelará la ejecución de esta consulta y registrará un error:
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 ERROR: canceling statement due to lock timeout
2021-01-30 09:35:52.415 UTC [67] psql postgres testdb 172.17.0.1 STATEMENT: cluster t;
Supongamos que desea establecer un tiempo de espera de bloqueo de 1 minuto, pero registrar consultas que esperan bloqueos durante más de, digamos, 30 segundos. Puedes hacer esto usando:
log_lock_waits = on
deadlock_timeout = 30s
Esto creará registros como este:
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 LOG: process 70 still waiting for ShareLock on transaction 493 after 30009.004 ms
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 68. Wait queue: 70.
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:49:22.331 UTC [70] psql postgres testdb 172.17.0.1 STATEMENT: select * from t for update;
El uso de deadlock_timeout no es un error tipográfico:es el valor que utiliza el mecanismo de registro de espera de bloqueo. Idealmente, debería haber algo como log_min_duration_lock_wait , pero desafortunadamente, ese no es el caso.
En caso de bloqueos reales, Postgres anulará las transacciones bloqueadas después de deadlock_timeout duración, y registrará las declaraciones infractoras. No es necesaria una configuración explícita.
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 LOG: process 68 detected deadlock while waiting for ShareLock on transaction 496 after 30007.633 ms
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process holding the lock: 70. Wait queue: .
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.724 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 ERROR: deadlock detected
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 DETAIL: Process 68 waits for ShareLock on transaction 496; blocked by process 70.
Process 70 waits for ShareLock on transaction 495; blocked by process 68.
Process 68: select * from t where a=4 for update;
Process 70: select * from t where a=0 for update;
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 HINT: See server log for query details.
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 CONTEXT: while locking tuple (0,3) in relation "t"
2021-01-30 09:55:37.725 UTC [68] psql postgres testdb 172.17.0.1 STATEMENT: select * from t where a=4 for update;
Descubriendo bloqueos actuales
La lista completa de bloqueos actualmente otorgados está disponible en la vista del sistema pg_locks. Sin embargo, normalmente es más fácil usar la función pg_blocking_pids , junto con pg_stat_activity , así:
SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
que puede mostrar una salida como esta:
state | pid | pg_blocking_pids | query
---------------------+--------+------------------+-------------------------------------------------
active | 378170 | {} | SELECT state, pid, pg_blocking_pids(pid), query+
| | | FROM pg_stat_activity +
| | | WHERE backend_type='client backend';
active | 369399 | {378068} | cluster "Track";
idle in transaction | 378068 | {} | select * from "Track" for update;
(3 rows)
lo que indica que hay un backend que está bloqueado (el que ejecuta la instrucción CLUSTER) y que está siendo bloqueado por el PID 378068 (que ha ejecutado SELECCIONAR..PARA ACTUALIZAR pero luego está inactivo dentro de la transacción).
