Cuando se trabaja con bases de datos OLTP (procesamiento de transacciones en línea), el rendimiento de las consultas es primordial, ya que afecta directamente la experiencia del usuario. Las consultas lentas significan que la aplicación se siente lenta y que no responde y esto resulta en malas tasas de conversión, usuarios descontentos y todo tipo de problemas.
OLTP es uno de los casos de uso común para PostgreSQL, por lo que desea que sus consultas se ejecuten de la mejor manera posible. En este blog nos gustaría hablar sobre cómo puede identificar problemas con consultas lentas en PostgreSQL.
Comprender el registro lento
En términos generales, la forma más típica de identificar problemas de rendimiento con PostgreSQL es recopilar consultas lentas. Hay un par de formas en las que puedes hacerlo. Primero, puede habilitarlo en una sola base de datos:
pgbench=# ALTER DATABASE pgbench SET log_min_duration_statement=0;
ALTER DATABASEDespués de esto, todas las conexiones nuevas a la base de datos 'pgbench' se registrarán en el registro de PostgreSQL.
También es posible habilitar esto globalmente agregando:
log_min_duration_statement = 0a la configuración de PostgreSQL y luego vuelva a cargar la configuración:
pgbench=# SELECT pg_reload_conf();
pg_reload_conf
----------------
t
(1 row)Esto permite el registro de todas las consultas en todas las bases de datos de su PostgreSQL. Si no ve ningún registro, es posible que desee habilitar logging_collector =on también. Los registros incluirán todo el tráfico que llegue a las tablas del sistema PostgreSQL, lo que lo hará más ruidoso. Para nuestros propósitos, limitémonos al registro a nivel de la base de datos.
Lo que verá en el registro son las siguientes entradas:
2020-02-21 09:45:39.022 UTC [13542] LOG: duration: 0.145 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 29817899;
2020-02-21 09:45:39.022 UTC [13544] LOG: duration: 0.107 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 11782597;
2020-02-21 09:45:39.022 UTC [13529] LOG: duration: 0.065 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 16318529;
2020-02-21 09:45:39.022 UTC [13529] LOG: duration: 0.082 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + 3063 WHERE tid = 3244;
2020-02-21 09:45:39.022 UTC [13526] LOG: duration: 16.450 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + 1359 WHERE bid = 195;
2020-02-21 09:45:39.023 UTC [13523] LOG: duration: 15.824 ms statement: UPDATE pgbench_accounts SET abalance = abalance + -3726 WHERE aid = 5290358;
2020-02-21 09:45:39.023 UTC [13542] LOG: duration: 0.107 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -2716 WHERE tid = 1794;
2020-02-21 09:45:39.024 UTC [13544] LOG: duration: 0.112 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -3814 WHERE tid = 278;
2020-02-21 09:45:39.024 UTC [13526] LOG: duration: 0.060 ms statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (4876, 195, 39955137, 1359, CURRENT_TIMESTAMP);
2020-02-21 09:45:39.024 UTC [13529] LOG: duration: 0.081 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + 3063 WHERE bid = 369;
2020-02-21 09:45:39.024 UTC [13523] LOG: duration: 0.063 ms statement: SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
2020-02-21 09:45:39.024 UTC [13542] LOG: duration: 0.100 ms statement: UPDATE pgbench_branches SET bbalance = bbalance + -2716 WHERE bid = 210;
2020-02-21 09:45:39.026 UTC [13523] LOG: duration: 0.092 ms statement: UPDATE pgbench_tellers SET tbalance = tbalance + -3726 WHERE tid = 67;
2020-02-21 09:45:39.026 UTC [13529] LOG: duration: 0.090 ms statement: INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (3244, 369, 16318529, 3063, CURRENT_TIMESTAMP);Puede ver información sobre la consulta y su duración. No mucho más, pero definitivamente es un buen lugar para comenzar. Lo principal a tener en cuenta es que no todas las consultas lentas son un problema. En ocasiones, las consultas tienen que acceder a una cantidad importante de datos y se espera que tarden más en acceder y analizar toda la información solicitada por el usuario. Otra pregunta es ¿qué significa "lento"? Esto depende principalmente de la aplicación. Si hablamos de aplicaciones interactivas, lo más probable es que se note algo más lento que un segundo. Idealmente, todo se ejecuta dentro del límite de 100 a 200 milisegundos.
Desarrollo de un plan de ejecución de consultas
Una vez que determinamos que la consulta dada es realmente algo que queremos mejorar, debemos echar un vistazo al plan de ejecución de la consulta. En primer lugar, puede suceder que no haya nada que podamos hacer al respecto y tengamos que aceptar que la consulta dada es lenta. En segundo lugar, los planes de ejecución de consultas pueden cambiar. Los optimizadores siempre intentan elegir el plan de ejecución más óptimo, pero toman sus decisiones basándose solo en una muestra de datos, por lo que puede suceder que el plan de ejecución de la consulta cambie con el tiempo. En PostgreSQL puedes comprobar el plan de ejecución de dos formas. Primero, el plan de ejecución estimado, usando EXPLAIN:
pgbench=# EXPLAIN SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
QUERY PLAN
----------------------------------------------------------------------------------------------
Index Scan using pgbench_accounts_pkey on pgbench_accounts (cost=0.56..8.58 rows=1 width=4)
Index Cond: (aid = 5290358)Como puede ver, se espera que accedamos a los datos mediante la búsqueda de clave principal. Si queremos volver a verificar cómo se ejecutará exactamente la consulta, podemos usar EXPLAIN ANALYZE:
pgbench=# EXPLAIN ANALYZE SELECT abalance FROM pgbench_accounts WHERE aid = 5290358;
QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------
Index Scan using pgbench_accounts_pkey on pgbench_accounts (cost=0.56..8.58 rows=1 width=4) (actual time=0.046..0.065 rows=1 loops=1)
Index Cond: (aid = 5290358)
Planning time: 0.053 ms
Execution time: 0.084 ms
(4 rows)Ahora, PostgreSQL ha ejecutado esta consulta y puede decirnos no solo las estimaciones, sino también los números exactos en lo que respecta al plan de ejecución, el número de filas a las que se accede, etc. Tenga en cuenta que el registro de todas las consultas puede convertirse en una sobrecarga importante para su sistema. También debe vigilar los registros y asegurarse de que estén rotados correctamente.
Pg_stat_statements
Pg_stat_statements es la extensión que recopila estadísticas de ejecución para diferentes tipos de consultas.
pgbench=# select query, calls, total_time, min_time, max_time, mean_time, stddev_time, rows from public.pg_stat_statements order by calls desc LIMIT 10;
query | calls | total_time | min_time | max_time | mean_time | stddev_time | rows
------------------------------------------------------------------------------------------------------+-------+------------------+----------+------------+---------------------+---------------------+-------
UPDATE pgbench_branches SET bbalance = bbalance + $1 WHERE bid = $2 | 30437 | 6636.83641200002 | 0.006533 | 83.832148 | 0.218051595492329 | 1.84977058799388 | 30437
BEGIN | 30437 | 231.095600000001 | 0.000205 | 20.260355 | 0.00759258796859083 | 0.26671126085716 | 0
END | 30437 | 229.483213999999 | 0.000211 | 16.980678 | 0.0075396134310215 | 0.223837608828596 | 0
UPDATE pgbench_accounts SET abalance = abalance + $1 WHERE aid = $2 | 30437 | 290021.784321001 | 0.019568 | 805.171845 | 9.52859297305914 | 13.6632712046825 | 30437
UPDATE pgbench_tellers SET tbalance = tbalance + $1 WHERE tid = $2 | 30437 | 6667.27243200002 | 0.00732 | 212.479269 | 0.219051563294674 | 2.13585110968012 | 30437
SELECT abalance FROM pgbench_accounts WHERE aid = $1 | 30437 | 3702.19730600006 | 0.00627 | 38.860846 | 0.121634763807208 | 1.07735927551245 | 30437
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES ($1, $2, $3, $4, CURRENT_TIMESTAMP) | 30437 | 2349.22475800002 | 0.003218 | 61.372127 | 0.0771831901304325 | 0.971590327400244 | 30437
SELECT $1 | 6847 | 60.785467 | 0.002321 | 7.882384 | 0.00887767883744706 | 0.105198744982906 | 6847
insert into pgbench_tellers(tid,bid,tbalance) values ($1,$2,$3) | 5000 | 18.592042 | 0.001572 | 0.741427 | 0.0037184084 | 0.0137660355678027 | 5000
insert into pgbench_tellers(tid,bid,tbalance) values ($1,$2,$3) | 3000 | 7.323788 | 0.001598 | 0.40152 | 0.00244126266666667 | 0.00834442591085048 | 3000
(10 rows)Como puede ver en los datos anteriores, tenemos una lista de diferentes consultas e información sobre sus tiempos de ejecución; esto es solo una parte de los datos que puede ver en pg_stat_statements pero es suficiente para para que entendamos que nuestra búsqueda de clave principal a veces tarda casi 39 segundos en completarse; esto no se ve bien y definitivamente es algo que queremos investigar.
Si no tiene habilitado pg_stat_statements, puede hacerlo de forma estándar. Ya sea a través del archivo de configuración y
shared_preload_libraries = 'pg_stat_statements'O puede habilitarlo a través de la línea de comandos de PostgreSQL:
pgbench=# CREATE EXTENSION pg_stat_statements;
CREATE EXTENSIONUso de ClusterControl para eliminar consultas lentas
Si usa ClusterControl para administrar su base de datos PostgreSQL, puede usarlo para recopilar datos sobre consultas lentas.
Como puede ver, recopila datos sobre la ejecución de consultas:filas enviadas y examinado, estadísticas de tiempo de ejecución, etc. Con él, puede identificar fácilmente las consultas más costosas y ver cómo son los tiempos de ejecución promedio y máximo. De forma predeterminada, ClusterControl recopila consultas que tardaron más de 0,5 segundos en completarse, puede cambiar esto en la configuración:
Conclusión
Este breve blog de ninguna manera cubre todos los aspectos y herramientas útiles para identificar y resolver problemas de rendimiento de consultas en PostgreSQL. Esperamos que sea un buen comienzo y que lo ayude a comprender qué puede hacer para identificar la causa raíz de las consultas lentas.
