Em cada implantação, sempre há algumas consultas que são executadas muito lentamente.
Continue lendo para ver como descobrir consultas que demoram muito para serem executadas e como descobrir por que elas são lentas.
Apenas usar pg_stat_statements?
pg_stat_statements é uma extensão popular incluída na distribuição central do PostgreSQL e disponível por padrão em quase todos os provedores de DBaaS. É inestimável e é mais ou menos a única maneira de obter estatísticas sobre consultas sem instalar extensões personalizadas.
No entanto, tem algumas limitações quando se trata de descobrir consultas lentas.
Estatísticas cumulativas
A extensão pg_stat_statements fornece cumulativos estatísticas sobre cada consulta já executada pelo servidor. Para cada consulta, mostra, entre outras métricas, o número total de vezes que foi executada e o tempo total gasto em todas as execuções.
Para “capturar” consultas lentas quando elas acontecem, você precisa buscar periodicamente todo o conteúdo do
pg_stat_statements visualizar, armazená-lo em um banco de dados de série temporal e comparar as contagens de execução. Por exemplo, se tiver o conteúdo de pg_stat_statements às 10h00 e 10h10, você pode selecionar as consultas que têm uma contagem de execução mais alta às 10h10 do que às 10h00. Para essas consultas, você pode calcular o tempo médio de execução durante esse 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)
Se esse tempo médio de execução exceder um limite superior, você poderá acionar um alerta para agir.
Isso funciona razoavelmente bem na prática, mas você precisará de uma boa infraestrutura de monitoramento ou de um serviço dedicado como o pgDash.
Parâmetros de consulta
pg_stat_statements não captura os valores dos parâmetros de ligação passados para as consultas.
Uma das coisas que o planejador de consulta do Postgres estima para selecionar um plano de execução é o número de linhas que uma condição provavelmente filtrará. Por exemplo, se a maioria das linhas de uma tabela tiver o valor de uma coluna indexada país como "US", o planejador pode decidir fazer uma varredura sequencial da tabela inteira para onde cláusula
country = "US" , e pode decidir usar uma varredura de índice para country = "UK" desde o primeiro onde espera-se que a cláusula corresponda à maioria das linhas na tabela. Saber o valor real dos parâmetros para os quais a execução da consulta foi lenta pode ajudar a diagnosticar problemas de consulta lenta mais rapidamente.
Registro de consulta lento
A alternativa mais simples é registrar consultas lentas. Ao contrário de um certo outro SGBD que facilita isso, o PostgreSQL nos apresenta várias configurações de aparência semelhante:
log_statementlog_min_duration_statementlog_min_duration_samplelog_statement_sample_ratelog_parameter_max_lengthlog_parameter_max_length_on_errorlog_duration
Eles são descritos em detalhes na documentação do Postgres. Aqui está um ponto de partida razoável:
# 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
O que resulta em logs como estes:
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";
Se houver muitos logs, você pode pedir ao Postgres para registrar apenas (digamos) 50% das consultas que duram mais de 5 segundos:
log_min_duration_sample = 5s
log_statement_sample_rate = 0.5 # 0..1 => 0%..100%
Você deve, é claro, ler os documentos sobre o que esses parâmetros significam e implicam antes de adicioná-los à sua configuração do Postgres. Esteja avisado de que as configurações são peculiares e não intuitivas.
Planos de execução de consultas lentas
Geralmente, não é suficiente saber que ocorreu uma consulta lenta, você também precisará descobrir por que foi lento. Para isso, você normalmente verificará primeiro o plano de execução da consulta.
auto_explain é outra extensão central do PostgreSQL (novamente, disponível na maioria dos DBaaS também) que pode registrar os planos de execução de consultas que acabaram de ser executadas. Está documentado aqui. Para ativar o auto_explain, você normalmente o adiciona a
shared_preload_libraries e reinicie o Postgres. Aqui está um exemplo de configuração inicial:# 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
Isso fará com que os planos sejam registrados no formato JSON, que podem ser visualizados em ferramentas como essas.
Consultas ainda em execução
Todas as técnicas listadas acima têm uma coisa em comum:elas produzem saída acionável somente depois uma consulta terminou a execução. Eles não podem ser usados para lidar com consultas tão lentas desta vez que ainda não terminaram a execução.
Cada conexão com um servidor PostgreSQL é tratada por um backend , especificamente um back-end de cliente . Quando esse back-end está executando uma consulta, seu estado é ativo . Ele também pode ter iniciado uma transação, mas está ocioso, chamado ocioso na transação Estado.
A
pg_stat_activity A visão do sistema documentada aqui fornece uma lista de todos os backends do Postgres em execução. Você pode consultar essa visualização para obter consultas que ainda estão em execução:SELECT client_addr, query_start, query
FROM pg_stat_activity
WHERE state IN ('active', 'idle in transaction')
AND backend_type = 'client backend';
A propósito, sem usar extensões de terceiros, não há como saber o plano de execução de uma consulta que está sendo executada por um back-end.
Bloqueios
Se o plano de execução de uma consulta lenta não indicar nenhum problema óbvio, o back-end que executa a consulta pode ter sido atrasado por bloqueios disputados.
Os bloqueios são obtidos de forma explícita ou implícita durante a execução da consulta por vários motivos. Há um capítulo inteiro na documentação do Postgres dedicado a isso.
Bloqueios de registro
Normalmente, um limite superior de quanto tempo de espera é definido usando a opção lock_timeout , geralmente no lado do cliente. Se uma consulta estiver esperando tanto tempo para adquirir um bloqueio, o Postgres cancelará a execução dessa consulta e registrará um erro:
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;
Digamos que você deseja definir um tempo limite de bloqueio de 1 minuto, mas registra consultas que aguardam bloqueios por mais de, digamos, 30 segundos. Você pode fazer isso usando:
log_lock_waits = on
deadlock_timeout = 30s
Isso criará logs 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;
O uso de deadlock_timeout não é um erro de digitação:é o valor que o mecanismo de log de espera de bloqueio usa. Idealmente, deveria haver algo como log_min_duration_lock_wait , mas infelizmente não é bem assim.
No caso de deadlocks reais, o Postgres abortará as transações em deadlock após deadlock_timeout duração e registrará as declarações ofensivas. Nenhuma configuração explícita é necessária.
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;
Descobrindo bloqueios atuais
A lista completa de bloqueios atualmente concedidos está disponível na visualização do sistema pg_locks. No entanto, normalmente é mais fácil usar a função
pg_blocking_pids , junto com pg_stat_activity , assim:SELECT state, pid, pg_blocking_pids(pid), query
FROM pg_stat_activity
WHERE backend_type='client backend';
que pode mostrar uma saída 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)
que indica que há um backend que está bloqueado (o que está executando a instrução CLUSTER) e que está sendo bloqueado pelo PID 378068 (que executou um SELECT..FOR UPDATE, mas está inativo dentro da transação).
