Como identificar problemas de desempenho do PostgreSQL com consultas lentas

Ao trabalhar com bancos de dados OLTP (OnLine Transaction Processing), o desempenho da consulta é fundamental, pois afeta diretamente a experiência do usuário. Consultas lentas significam que o aplicativo parece lento e sem resposta e isso resulta em taxas de conversão ruins, usuários insatisfeitos e todos os conjuntos de problemas.

OLTP é um dos casos de uso comuns do PostgreSQL, portanto, você deseja que suas consultas sejam executadas o mais suavemente possível. Neste blog, gostaríamos de falar sobre como você pode identificar problemas com consultas lentas no PostgreSQL.

Compreendendo o registro lento

De um modo geral, a maneira mais comum de identificar problemas de desempenho com o PostgreSQL é coletar consultas lentas. Existem algumas maneiras de fazer isso. Primeiro, você pode habilitá-lo em um único banco de dados:

pgbench=# ALTER DATABASE pgbench SET log_min_duration_statement=0;

ALTER DATABASE

Após isso, todas as novas conexões com o banco de dados ‘pgbench’ serão registradas no log do PostgreSQL.

Também é possível habilitar isso globalmente adicionando:

log_min_duration_statement = 0

para a configuração do PostgreSQL e recarregue a configuração:

pgbench=# SELECT pg_reload_conf();

 pg_reload_conf

----------------

 t

(1 row)

Isso permite o registro de todas as consultas em todos os bancos de dados em seu PostgreSQL. Se você não vir nenhum log, convém habilitar logging_collector =on também. Os logs incluirão todo o tráfego que chega às tabelas do sistema PostgreSQL, tornando-o mais ruidoso. Para nossos propósitos, vamos nos ater ao registro em nível de banco de dados.

O que você verá no log são as entradas abaixo:

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);

Você pode ver informações sobre a consulta e sua duração. Não muito mais, mas é definitivamente um bom lugar para começar. A principal coisa a ter em mente é que nem toda consulta lenta é um problema. Às vezes, as consultas precisam acessar uma quantidade significativa de dados e espera-se que demorem mais para acessar e analisar todas as informações solicitadas pelo usuário. Outra questão é o que significa “lento”? Isso depende principalmente da aplicação. Se estamos falando de aplicativos interativos, provavelmente algo mais lento que um segundo é perceptível. Idealmente, tudo é executado dentro do limite de 100 - 200 milissegundos.

Desenvolvendo um plano de execução de consulta

Uma vez que determinamos que determinada consulta é realmente algo que queremos melhorar, devemos dar uma olhada no plano de execução da consulta. Em primeiro lugar, pode acontecer que não haja nada que possamos fazer sobre isso e teremos que aceitar que determinada consulta é apenas lenta. Em segundo lugar, os planos de execução de consultas podem mudar. Os otimizadores sempre tentam escolher o plano de execução mais ideal, mas tomam suas decisões com base apenas em uma amostra de dados, portanto, pode acontecer que o plano de execução da consulta mude com o tempo. No PostgreSQL você pode verificar o plano de execução de duas maneiras. Primeiro, o plano de execução 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 você pode ver, espera-se que acessemos os dados usando a pesquisa de chave primária. Se quisermos verificar como exatamente a consulta será executada, 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)

Agora, o PostgreSQL executou esta consulta e pode nos dizer não apenas as estimativas, mas os números exatos quando se trata do plano de execução, número de linhas acessadas e assim por diante. Lembre-se de que registrar todas as consultas pode se tornar uma sobrecarga séria em seu sistema. Você também deve ficar de olho nos logs e garantir que eles sejam girados corretamente.

Pg_stat_statements

Pg_stat_statements é a extensão que coleta estatísticas de execução para diferentes tipos de consulta.

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 você pode ver nos dados acima, temos uma lista de diferentes consultas e informações sobre seus tempos de execução - isso é apenas uma parte dos dados que você pode ver nos pg_stat_statements, mas é suficiente para entendermos que nossa pesquisa de chave primária às vezes leva quase 39 segundos para ser concluída - isso não parece bom e é definitivamente algo que queremos investigar.

Se você não tiver pg_stat_statements ativado, você pode fazer isso de maneira padrão. Seja via arquivo de configuração e

shared_preload_libraries = 'pg_stat_statements'

Ou você pode habilitá-lo via linha de comando do PostgreSQL:

pgbench=# CREATE EXTENSION pg_stat_statements;

CREATE EXTENSION

Usando ClusterControl para eliminar consultas lentas

Se você usar o ClusterControl para gerenciar seu banco de dados PostgreSQL, poderá usá-lo para coletar dados sobre consultas lentas.

Como você pode ver, ele coleta dados sobre execução de consultas - linhas enviadas e examinados, estatísticas de tempo de execução e assim por diante. Com ele, você pode identificar facilmente as consultas mais caras e ver como são os tempos médio e máximo de execução. Por padrão, o ClusterControl coleta consultas que demoraram mais de 0,5 segundo para serem concluídas, você pode alterar isso nas configurações:

Conclusão