Configurando o PostgreSQL para observabilidade

O PostgreSQL vem com uma infinidade de opções de configuração, mas alterar as configurações padrão de algumas dessas opções melhora drasticamente a observabilidade do seu servidor PostgreSQL. Você desejará definir e configurar essas opções antes que problemas surjam na produção, pois elas podem fornecer informações essenciais para entender e resolver esses problemas.

Continue lendo para saber mais sobre as configurações e extensões que expõem métricas e informações sobre o funcionamento interno do seu servidor PostgreSQL.

Prefixo da linha de registro

O log_line_prefix A opção de configuração determina o que o PostgreSQL escreve no início de cada linha de log. O padrão depende da distribuição Linux específica ou da solução gerenciada que você está usando, mas na maioria das vezes não inclui alguns itens que podem ser muito úteis no rastreamento de clientes com mau comportamento. Experimente este log_line_prefix :

log_line_prefix = '%m [%p] %a %u %d %h '

Inclui o carimbo de data/hora (%m ), o PID do processo de backend (%p ), o nome do aplicativo (%a ) do cliente, o nome de usuário com o qual o cliente se conectou (%u ), o banco de dados ao qual o cliente se conectou (%d ) e o nome do host ou IP de onde vem a conexão (%h ). Isso resulta em linhas de log como esta:

2021-01-30 05:06:03.675 UTC [73] psql postgres bench 172.17.0.1 ERROR:  relation "pgbench_akkounts" does not exist at character 15
2021-01-30 05:06:03.675 UTC [73] psql postgres bench 172.17.0.1 STATEMENT:  select * from pgbench_akkounts;

que são muito mais úteis do que o padrão. Você pode ver que um cliente conectado de 172.17.0.1 como usuário postgres para banco de dados banco , e o aplicativo era psql . Definitivamente uma melhoria em relação à opção padrão, que mostra apenas isso:

2021-01-30 05:13:22.630 UTC [63] ERROR:  relation "pgbench_akkounts" does not exist at character 15
2021-01-30 05:13:22.630 UTC [63] STATEMENT:  select * from pgbench_akkounts;

Registrando consultas lentas

O PostgreSQL pode ser configurado para registrar consultas que levam mais do que um determinado período de tempo para serem executadas. Eles vão para o mesmo arquivo de log; não há arquivo de log de consulta lento separado como no MySQL.

Para registrar instruções que levam mais de 1 segundo para serem executadas, use olog_min_duration_statement opção assim:

log_min_duration_statement = 1s

Observe que log_min_duration_statement irá considerar todas as instruções (incluindo, por exemplo, instruções de administração de longa duração como REINDEX TABLE ) e não apenas consultas (SELECT ). Aqui estão algumas entradas de log produzidas por esta opção:

2021-01-30 08:42:57.473 UTC [62] psql postgres postgres 172.17.0.1 LOG:  duration: 1016.283 ms  statement: select pg_sleep(1);
2021-01-30 08:52:00.541 UTC [62] psql postgres postgres 172.17.0.1 LOG:  duration: 1118.277 ms  statement: select pg_sleep(1.1);

Se isso resultar em muitos logs de declarações semelhantes, você pode dizer ao Postgres para registrar apenas uma porcentagem disso, usando:

log_min_duration_statement = -1
log_min_duration_sample = 1s
log_statement_sample_rate = 0.25

Isso registra apenas 25% das instruções que se tornam elegíveis para registro (as que levaram mais de 1 segundo para serem executadas). A saída do log é a mesma de antes. Não há como saber quantas instruções elegíveis não foram registradas.

Para registrar todas as instruções, juntamente com o tempo necessário para executá-las, use olog_statement opção em vez disso:

log_statement = mod
log_duration = on

A opção ‘mod’ diz ao Postgres para registrar DDLs e instruções de modificação de dados. Isso resulta em logs como estes:

2021-01-30 08:35:08.985 UTC [64] pgbench postgres bench 172.17.0.1 LOG:  statement: insert into pgbench_tellers(tid,bid,tbalance) values (10,1,0)
2021-01-30 08:35:08.985 UTC [64] pgbench postgres bench 172.17.0.1 LOG:  duration: 0.241 ms

Esteja avisado de que não possível testar o log de instrução habilitado dessa maneira, todas as instruções serão registradas e você acabará com toneladas de entradas de log.

Registrando bloqueios e impasses

As consultas podem esperar muito tempo para adquirir um bloqueio. 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 desta 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 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 irá 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;

Registrando Autovacuums

O processo de autovacuum entra em ação quando o Postgres determina que os dados em uma tabela mudaram o suficiente para garantir um vácuo e uma análise. Para ficar de olho nesse processo, habilite o registro de execuções de autovacuum:

log_autovacuum_min_duration = 250ms

Aqui está uma entrada de exemplo que foi causada por alterações excessivas em uma tabela:

2021-01-30 10:23:33.201 UTC [63]     LOG:  automatic vacuum of table "postgres.public.t": index scans: 0
        pages: 0 removed, 95 remain, 0 skipped due to pins, 0 skipped frozen
        tuples: 8991 removed, 10000 remain, 0 are dead but not yet removable, oldest xmin: 492
        buffer usage: 215 hits, 4 misses, 4 dirtied
        avg read rate: 1.885 MB/s, avg write rate: 1.885 MB/s
        system usage: CPU: user: 0.01 s, system: 0.00 s, elapsed: 0.01 s
        WAL usage: 244 records, 1 full page images, 67984 bytes
2021-01-30 10:23:33.222 UTC [63]     LOG:  automatic analyze of table "postgres.public.t" system usage: CPU: user: 0.01 s, system: 0.00 s, elapsed: 0.01 s

Observe que o vácuo automático normalmente acionará uma análise após o vácuo, e isso também será registrado.

Esses logs ajudarão você a descobrir a melhor forma de ajustar os parâmetros do autovacuum e ajudarão a investigar se e quando o autovacuum não está sendo tão eficaz quanto você pensava que seria.

Pontos de verificação de registro

Checkpointing é o processo de enviar as alterações registradas no WAL para os arquivos reais que suportam as tabelas. Idealmente, os pontos de verificação devem ocorrer em intervalos regulares e não muito frequentes, pois é um processo intensivo de CPU e disco. Por vários motivos, os pontos de verificação também são forçados a ocorrer antes do próximo horário agendado, e isso resulta em desempenho de consulta reduzido.

Para ficar de olho na frequência e eficiência do checkpoint, habilite o registro de checkpoints:

log_checkpoints = on

Isso diz ao PostgreSQL para registrar o seguinte sempre que ocorrer um ponto de verificação:

2021-01-30 10:05:57.085 UTC [56]     LOG:  checkpoint starting: immediate force wait
2021-01-30 10:05:57.159 UTC [56]     LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.000 s, sync=0.000 s, total=0.074 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB

A primeira linha contém os sinalizadores que o backend passou para o checkpointer. Você pode ver que a “força” causou um ponto de verificação mesmo que não houvesse alterações pendentes no ponto de verificação. Se “imediato” não tivesse sido especificado, o checkpointer teria feito checkpoint até checkpoint_completion_target .

Outras configurações do lado do servidor

Existem algumas outras configurações que você pode ativar na configuração do PostgreSQL que ajudarão no diagnóstico de problemas:

track_io_timing - configurando isso para ligado permite ver o tempo gasto na E/S do indisk para cada consulta (combinada com a extensão pg_stat_statements descrita abaixo). Veja os documentos sobre uma advertência para ativar isso, mas deve ser seguro em praticamente qualquer Linux moderno. É impossível ver o custo de E/S de disco de uma consulta sem ativar isso.
track_commit_timestamp - configurando isso para ligado pode ser útil na depuração de atrasos de replicação e outros problemas relacionados à replicação.

Consultar estatísticas por meio de pg_stat_statements

A extensão pg_stat_statements é um acessório essencial para qualquer implantação do PostgreSQL. Ele coleta e registra estatísticas para cada consulta executada e as apresenta como uma visão chamada “pg_stat_statements”. Esta é uma extensão, o que significa que você deve instalá-la explicitamente em cada banco de dados para o qual deseja dados, usando o comando:

CREATE EXTENSION pg_stat_statements;

Como a extensão depende de um .so , você precisará carregá-lo usandoshared_preload_libraries :

shared_preload_libraries = 'pg_stat_statements'

Infelizmente, isso requer uma reinicialização do servidor PostgreSQL; então certifique-se de fazer isso antes de ir ao vivo.

Se você atualizou de uma versão anterior do PostgreSQL, certifique-se de atualizar sua extensão pg_stat_statement também, usando:

ALTER EXTENSION pg_stat_statements UPDATE;

A extensão pg_stat_statements não registra nada, ela é usada por meio de consulta à visualização de mesmo nome. Para mais detalhes, consulte a documentação oficial.

Consulte Planos de Execução via auto_explain

auto_explain é outra extensão presente no núcleo do PostgreSQL. Ele pode registrar os planos de execução de consultas lentas. Ele só precisa ser adicionado ashared_preload_libraries , e não precisa ser instalado como uma extensão. Ele também tem algumas outras opções que normalmente precisam ser definidas para valores não padrão:

shared_preload_libraries = 'pg_stat_statements,auto_explain'

auto_explain.log_min_duration = 1s
auto_explain.log_analyze = on
auto_explain.log_buffers = on
auto_explain.log_triggers = on
auto_explain.log_timing = on
auto_explain.log_verbose = on
auto_explain.log_format = json

O acima registra o plano de execução para qualquer consulta que leve mais de 1 segundo para ser concluída. Aqui está um exemplo de saída:

2021-01-30 11:28:25.977 UTC [64] psql postgres postgres 172.17.0.1 LOG:  duration: 1.305 ms  plan:
        {
          "Query Text": "SELECT n.nspname as \"Schema\",\n  c.relname as \"Name\",\n  CASE c.relkind WHEN 'r' THEN 'table' WHEN 'v' THEN 'view' WHEN 'm' THEN 'materialized view' WHEN 'i' THEN 'index' WHEN 'S' TH
EN 'sequence' WHEN 's' THEN 'special' WHEN 'f' THEN 'foreign table' WHEN 'p' THEN 'table' WHEN 'I' THEN 'index' END as \"Type\",\n  pg_catalog.pg_get_userbyid(c.relowner) as \"Owner\"\nFROM pg_catalog.pg_class c
\n     LEFT JOIN pg_catalog.pg_namespace n ON n.oid = c.relnamespace\nWHERE c.relkind IN ('r','p','v','m','S','f','')\n      AND n.nspname <> 'pg_catalog'\n      AND n.nspname <> 'information_schema'\n      AND
n.nspname !~ '^pg_toast'\n  AND pg_catalog.pg_table_is_visible(c.oid)\nORDER BY 1,2;",
          "Plan": {
            "Node Type": "Sort",
            "Parallel Aware": false,
            "Startup Cost": 32.93,
            "Total Cost": 33.01,
            "Plan Rows": 32,
            "Plan Width": 224,
            "Actual Startup Time": 1.292,
            "Actual Total Time": 1.298,
            "Actual Rows": 0,
[... lots of text snipped ...]

Para saber mais sobre auto_explain, consulte os documentos oficiais.

As extensões pg_stat_statements e auto_explain são as únicas duas opções amplamente suportadas que o PostgreSQL tem para gerenciamento de desempenho de consulta e gerenciamento de plano de consulta. Vale a pena conhecer esses dois recursos e planejar com antecedência o uso deles na produção.

Nome do aplicativo

O nome do aplicativo é um parâmetro do lado do cliente e geralmente pode ser definido em DSNs ou strings de conexão no estilo libpq que seu aplicativo usa para informações de conexão. Muitas ferramentas e utilitários no sistema ecológico PostgreSQL entendem o nome do aplicativo, e isso ajuda a definir um valor significativo, por exemplo:

application_name = weekly-revenue-report

Isso seria definido para cada aplicativo cliente que se conecta ao seu servidor PostgreSQL.