PostgreSQL 17 e os logs que revelam por que o startup process travou

Todo DBA que já ficou olhando um PostgreSQL↳PostgreSQL11 conteúdosPostgreSQL via SSL com GolangData · abr 20195 itens legais sobre data types do PostgreSQLData · mar 20195 serviços gratuitos na cloud para bancos de dados PostgresData · fev 2025Ver tudo em Data → "pendurado" na inicialização, sem uma linha nova no log por vários minutos, conhece a tentação errada: reiniciar. Christophe Pettus, no artigo All Your GUCs in a Row: log_startup_progress_interval and log_recovery_conflict_waits publicado no Planet PostgreSQL, dedica o texto justamente a esse ponto cego, o startup process, o backend↳Back-end49 conteúdosIntegração front-end com backend: 7 decisões que evitam caos entre APIs, BFF e GraphQLDev (Back & Front) · abr 2026Como criar uma FAKE API REST para testes — JSONPlaceholderDev (Back & Front) · set 2025Construindo um aplicativo de bate-papo de IA simples com Spring AI e AngularDev (Back & Front) · jul 2025Ver tudo em Dev (Back & Front) → que reproduz o WAL, e aos dois parâmetros que o obrigam a dizer o que está fazendo.

O recorte é preciso porque os dois GUCs respondem à mesma pergunta em contextos opostos. No primário, o startup process só existe durante o crash recovery, e enquanto ele existe ninguém conecta: o cliente recebe FATAL: the database system is not yet accepting connections. No standby, ele nunca termina, replica pela vida inteira do servidor, e a pergunta deixa de ser "quanto falta" e passa a ser "por que parou". Um parâmetro para cada situação, e ambos respondem no log do servidor, porque nas duas situações o log é o único lugar onde há o que olhar.

O primário que ficou em silêncio

O log_startup_progress_interval chegou no PostgreSQL 15. O padrão é 10s, a unidade é milissegundos se você omitir, 0 desabilita e o contexto é sighup. Uma vez por intervalo, enquanto uma operação longa de startup ainda roda, o processo escreve uma linha dizendo isso. Três operações se qualificam: sincronizar o data directory (um fsync() de cada arquivo do cluster, feito sempre que o último shutdown não foi limpo, o que inclui o primeiro start de um base backup recém-restaurado), resetar relações unlogged e o replay do WAL. Cada uma tem seu próprio timer.

As linhas de replay são as que interessam, porque carregam o LSN:

LOG: redo starts at 0/902EC1F0
LOG: redo in progress, elapsed time: 10.00 s, current LSN: 0/A905D938
LOG: redo in progress, elapsed time: 20.00 s, current LSN: 0/B8FB2DB8
LOG: redo done at 0/C0B96070 system usage: CPU: user: 11.43 s, system: 8.45 s, elapsed: 27.80 s

Duas dessas linhas já dão uma taxa de replay. O startup process não sabe onde o WAL termina até ler um registro inválido, então não imprime estimativa, mas o segmento de maior número em pg_wal é o limite superior, e taxa mais distância dá um ETA, que é exatamente o número que quem está de plantão quer ouvir. Antes da versão 15, esse cálculo saía observando o nome do segmento no título do processo em ps e cronometrando na mão, método que Pettus atribui ao how-to de Nikolay Samokhvalov e que segue sendo o único caminho no PostgreSQL 14.

Por que o parâmetro existe

O commit que adicionou o recurso explica o motivo: a pessoa sobe o servidor, vê três linhas, não vê nada por minutos e conclui que travou. O que ela faz em seguida, reiniciar, é o pior movimento disponível. O restart repete a sincronização do data directory por inteiro, retoma o replay de onde o último restartpoint concluído parou e ainda adiciona um HINT ao log dizendo que os dados provavelmente estão corrompidos e que será preciso o último backup.

Aqui está o alerta que vale internalizar: esse HINT não é diagnóstico. Ele aparece porque o control file registra que o startup anterior morreu no meio da recuperação, o que de fato aconteceu, porque você o matou. A fase de sync é a que mais merece atenção: num cluster grande em storage de rede com cache frio, ela pode rodar muitos minutos sem nada no log, e a linha de progresso nomeia o arquivo em que está. Se essa for a fase lenta, recovery_init_sync_method = syncfs é a correção, e é o próprio parâmetro que revela essa necessidade.

Um detalhe operacional que Pettus faz questão de verificar: o timer é armado no início de cada fase com o valor vigente naquele momento. Se o parâmetro estava em 0 quando o replay começou, recarregar um novo valor no meio da recuperação não faz nada. Nas palavras dele:

This is a parameter you set before the crash, and the default is already the right value. The only setting that requires a decision is 0, and the decision is no.

Christophe Pettus

O standby que parou

No standby as linhas de replay são suprimidas (o processo reportaria progresso para sempre), mas as fases de sync e reset de unlogged ainda reportam. Logo, um standby que fica em silêncio depois de redo starts at está replicando, não sincronizando. E aqui há instrumentos melhores que o log: pg_last_wal_replay_lsn() no standby e replay_lag em pg_stat_replication no primário. A única lacuna é um standby reiniciando com grande backlog local de WAL: entre redo starts at e consistent recovery state reached você não tem SQL nem linhas de progresso, e volta ao ps.

O segundo parâmetro é o log_recovery_conflict_waits, que chegou no PostgreSQL 14. É booleano, off por padrão, contexto sighup, e só faz algo num hot standby. Ele reporta o mecanismo de conflito de recuperação: replay e uma query em execução querem a mesma coisa (uma versão de linha que o replay precisa remover, um lock de relação que o replay precisa tomar, um buffer pinado por um scan), e o startup process espera até max_standby_streaming_delay (30 segundos por padrão) para a query sair do caminho antes de cancelá-la.

Com o parâmetro ligado, uma espera que ultrapassa deadlock_timeout (o mesmo timer de um segundo do log_lock_waits) gera uma linha ao cruzar o limite e outra ao terminar:

LOG: recovery still waiting after 1077.432 ms: recovery conflict on snapshot
DETAIL: Conflicting process: 8617.
CONTEXT: WAL redo at 0/7901F4C0 for Heap2/PRUNE_VACUUM_SCAN: ... blkref #0: rel 1663/5/16384, blk 0
LOG: recovery finished waiting after 12877.511 ms: recovery conflict on snapshot

Não há nada entre as duas linhas, por mais longa que seja a espera. Portanto um still waiting sem um finished waiting depois significa que o standby está travado agora. O motivo pode ser snapshot, lock, buffer pin ou tablespace. O DETAIL nomeia a sessão que atrapalha (conflitos de buffer pin não têm DETAIL, porque o PostgreSQL não rastreia quem segura um pin), e o CONTEXT traz o registro WAL no formato do pg_waldump. O rel 1663/5/16384 é tablespace, database e relfilenode: SELECT pg_filenode_relation(1663, 16384) naquele database nomeia a tabela.

O caso em que ele é indispensável

O valor real do parâmetro está no que o exemplo não fez: foi um stall de treze segundos que não cancelou nada. A sessão terminou sozinha, então pg_stat_database_conflicts (que conta cancelamentos) ficou em zero, a query não recebeu erro, e a única outra evidência era o replay_lag subindo no primário. O log, esse, diz que o standby ficou travado às 03:12, por treze segundos, num registro de vacuum de uma tabela específica, e qual sessão foi responsável. É exatamente o que se precisa às 09:00, quando alguém pergunta por que os relatórios estavam desatualizados.

A intensidade da necessidade depende de max_standby_streaming_delay:

O valor -1 é o de toda réplica analítica configurada para parar de cancelar o relatório noturno, e é a configuração para a qual esse parâmetro existe. A string de motivo ainda resolve se hot_standby_feedback teria ajudado, já que o feedback previne conflitos de snapshot e nenhum outro tipo.

A recomendação de Pettus é econômica: custa nada até o startup process já ter esperado um segundo, ponto em que duas linhas a mais não são problema. Ligue em todo standby e mantenha deadlock_timeout em um segundo. Para o dev brasileiro que opera réplicas de leitura, a lição prática é que esses dois GUCs não são opcionais em produção séria: são a diferença entre debugar com evidência e adivinhar. E, como quase sempre em PostgreSQL, a decisão certa se toma antes do incidente, não durante.

Fonte: Planet PostgreSQL