Trabalhando com logs no PostgreSQL

Parece incrível mas existe um número grande de pessoas que não configura corretamente os logs no PostgreSQL. Muitos nem sabem onde ele fica e nunca foram olhar o que tem lá. É verdade que muitas aplicações que levam o PostgreSQL embarcado funcionam por anos sem nenhum problema. Mas um dia o problema vai surgir, e adivinha qual o primeiro lugar em que vamos olhar? Os logs claro. No entanto é bem frustrante chegar no cliente e ver que os logs não estão configurados, às vezes, sequer habilitados. Isto significa que a capacidade de verificar um problema ocorrido no passado é quase  nula.

A documentação possui um capítulo só com as configurações do log, vamos parar para olhar alguns pontos que você deveria conhecer, ok?

Onde logar

Aqui você vai configurar onde o arquivo de log vai ser gerado, o nome do arquivo, permissões no arquivo, tamanho do arquivo, etc. Preocupações com o local, nome e espaço em disco entram aqui.

• log_destination: Aqui você pode escolher entre stderr, csvlog, syslog e se estiver utilizando o Windows, eventlog. O uso do syslog ou do eventlog faz com que os logs sejam direcionados para o destino padrão dos logs no seu sistema operacional. Se você é um administrador de redes e está preocupado na gestão de dezenas de servidores, é possível que esteja mais confortável como isso. Por outro lado, DBAs em geral preferem o stderr ou csvlog. O padrão é utilizar o stderr, que produz um log mais fácil para a leitura humana, mas se você pretende importar os logs para uma ferramenta externa de analise, o csvlog pode ser uma boa opção também.
• logging_collector: Ligue e seja feliz. Deixe desligado e não me culpe se não souber te dizer o que houve de errado.
• log_directory: o diretório (dentro do diretório raiz da sua) onde os logs serão gravados. A não ser que tenha um bom motivo para isso, deixe o padrão, ‘pg_log’.
• log_filename: O nome do log gerado é muito importante para você. Pode acontecer de você gerar muitos logs por muito tempo e você tem que decidir se vai querer reaproveitar os logs antigos ou não. Se quiser rotacionar e manter apenas um log para cada dia da semana (manter apenas 7 dias de log) ou um para cada dia do mês (manter até 31 arquivos de log), você deve escolher um nome que seja sobrescrito periodicamente. Se você não tem alguém cuidando dos seus logs, pode ser melhor utilizar um esquema de rotação destes, não é o que eu prefiro, mas pode ser melhor do que ver seus logs lotando o espaço em disco sem que ninguém entenda o que está acontecendo. Parcimônia é uma boa pedida. Se você monitora o espaço em disco do seu servidor, não há motivos para mudar do padrão, que acredito que seja uma boa configuração.
• log_file_mode: Não mexa a não ser que você tenha um bom motivo para isso.
• log_rotation_age: O valor padrão faz com que pelo menos um novo log seja criado por dia. Gerar logs muito grandes torna muito difícil avaliar um problema. Meu conselho: deixe o valor padrão.
• log_rotation_size: Configura o tamanho máximo de um arquivo de log antes dele quebrar num novo arquivo. Como eu disse, logs muito grandes são difíceis de analisar. O padrão, 10MB talvez seja muito pequeno, uns 50MB ou 100MB são tranquilos para qualquer bom editor de texto abrir.
• log_truncate_on_rotation: Se você escolher um nome de arquivo em log_file_name de forma a ele reaproveitar os nomes anteriores, você precisa habilitar este parâmetros para ele apagar o log antigo.

Quando logar

Você pode dizer ao PostgreSQL em quais situações um log deve ser gerado. Essas demandas podem mudar o tempo todo e é importante saber quando e como mudar isso conforme a necessidade e o ambiente.

• client_min_messages, log_min_messages, log_min_error_statement: Estes 3 parâmetros possuem os mesmos valores que vão são DEBUG5, DEBUG4, DEBUG3, DEBUG2, DEBUG1, LOG, NOTICE, WARNING, ERROR, FATAL e PANIC. DEBUG5 é a opção que gera mais log e PANIC é a que gera menos log. DEBUG5 a DEBUG1 é utilizado em geral pelos próprios desenvolvedores do PostgreSQL. A opção PANIC por outro lado, é só vai registrar quando uma catástrofe absoluta acontecer. Um meio termo é o mais recomendado. Algo entre INFO e ERROR. O parâmetro client_min_messages se refere às mensagens enviadas para o usuário enquanto está interagindo com o banco de dados. Então a sua aplicação recebe mensagens que ela pode tratar. Um bom exemplo disso é quando você utiliza o psql. O log_min_messages é o que parâmetro que mede o que vai ser gravado de fato no nosso log. Por fim log_min_error_statement configura especificamente quando um comando SQL com erro vai ser gravado no log.  Vamos discutir um pouco mais sobre estes parâmetros mais tarde, eles são realmente importantes para nós.
• log_min_duration_statement: Faz com que qualquer comando SQL que leve mais do que o valor em  milissegundos configurado aqui entre no log. Muito útil para pegar comandos que estão levando muito tempo. É comum esperar que a maioria das consultas levem apenas alguns milissegundos ou no máximo alguns segundos. Capturar todas as consultas que demorem por exemplo mais de um minuto, pode ajudar a pegar gargalos importantes de performance. Se você configurar este parâmetro com 0 (zero) você vai logar todos os comandos SQL enviados para o postgres, que pode gerar uma quantidade muito grande de log. Em todo caso, experimente para ver o que acontece. Muitas pessoas se surpreendem com o que encontram…

O que logar

Dependendo da situação você pode querer logar coisas diferentes, a maioria destes parâmetros não serão alterados com o tempo, ao contrário dos parâmetros da sessão anterior.

• application_name: Não faz muito sentido ajustar este parâmetro aqui, mas é muito importante que sua aplicação saiba ajustar este parâmetro quando se conecta no postgres. Ajuda muito saber qual aplicação está conectada. Pode-se também alterar este valor para passar mais detalhes conforme a operação que vai executar ex: “Contabilidade | Cadastro de cliente”
• debug_print_parse, debug_print_rewritten, debug_print_plan e debug_pretty_print: Nunca vi um bom motivo para mexer nisso em condições normais de temperatura e pressão.
• log_checkpoints: Ativa o log dos checkpoints. Você pode não entender bem o que isso quer dizer, mas é uma informação que em geral não é gravada com muita frequência e pode ser bem útil para avaliação de performance. Deixe isso ligado.
• log_connections e log_disconnections: Faz com que cada conexão e desconexão de um usuário seja logada. Se você tem muitas conexões entrando e saindo com frequência, isso pode ser irritante, pois serão milhares de mensagens de log. Use com parcimônia.
• log_duration: tem um efeito parecido com o log_min_duration_statement configurado com 0 (zero). A diferença é que aqui ele não mostra a consulta executada, apenas a duração. Em geral prefiro utilizar o log_min_duration_statement, mas você pode usar ele para ter a estatística da duração das consultas que levaram menos tempo que o estipulado em log_min_duration_statement
• log_error_verbosity: em geral não há um bom motivo para mexer nisso nas condições normais de temperatura e pressão.
• log_hostname: Se você confia nas suas configurações de DNS na rede, pode habilitar este parâmetro para mostrar o nome das máquinas que se conectam no banco ao invés do seus IPs. Caso contrário, isso pode acrescentar um custo de performance considerável.
• log_line_prefix: Este parâmetro é muito importante e diz quais informações adicionais vem junto com os comandos SQL que aparecerem logados. Algumas ferramentas de análise de log (vamos discutir isso mais para frente) se beneficiam de determinadas configurações. Algumas coisas dependem do seu ambiente. Informação demais pode não ajudar. Por exemplo: se você utiliza um único banco de dados no seu ambiente, ou todos usuários utilizam um único usuário do banco, logar esta informação pode não ser tão útil. Mas não seja mesquinho também… Um exemplo de configuração pode ser algo como ‘%t [%p]: [%l] db=%d,user=%u ‘, ou seja, (%t) data e hora do evento, (%p) número do processo no SO, (%l) número da sequência de execução, (%d) nome da base, (%u) nome do usuário.
• log_lock_waits: Loga eventos de espera com locks. Você deve deixar isso ligado.
• log_statement: Loga tipos diferentes de SQL executados com sucesso, como DDL, MOD (DDL + DML), ALL (tudo) ou none (nada). Deixar em DDL costuma ser bastante razoável.
• log_temp_files: Útil para ajustar o tamanho do parâmetro work_mem e caçar comandos SQL mal comportados. Usar com parcimônia
• log_timezone: Em geral não costuma ser necessário mexer aqui.

Exemplos de configurações

Alterar as configurações de log é muito simples. Você deve ter uma configuração base bem robusta para o seu ambiente e pode altera-las para situações específicas onde precise de mais informações. Isto pode ser feito em uma base específica, para um usuário específico, uma função ou mesmo uma sessão. Algumas configurações no entanto se aplicam à todo o cluster e precisam que o PostgreSQL seja reiniciado para que a alteração faça efeito. Se quiser descobrir como lidar com os parâmetros do PostgreSQL, leia este artigo que publiquei sobre o assunto.

Vejamos algum alguns exemplos que utilizo no dia-a-dia. Outras possibilidades para situações específicas podem ocorrer, se quiser fazer uma sugestão, esteja à vontade para postar nos comentários.

Servidor de produção PostgreSQL dedicado

# - Where to Log -
log_destination                 = 'stderr'
logging_collector               = on
log_directory                   = 'pg_log'
log_filename                    = 'postgresql-%Y-%m-%d_%H%M%S.log'
log_truncate_on_rotation        = on
log_rotation_age                = 1d
log_rotation_size               = 64MB

# - When to Log -
client_min_messages             = log
log_min_messages                = notice
log_min_error_statement         = warning
log_min_duration_statement      = 120000

# - What to Log -
log_checkpoints                 = on
#log_connections                = off
#log_disconnections             = off
log_duration                    = off
log_error_verbosity             = default
log_hostname                    = on
log_line_prefix                 = '%t [%p]: [%l] user=%u,db=%d,app=%a,host=%h'
log_lock_waits                  = on
log_statement                   = 'ddl'
log_temp_files                  = 0
log_hostname                    = off

Aqui temos um log que será gerado em $PGDATA/pg_log e rotacionado todos os dias, ou quando o log atingir 64MB, ou quando o servidor for reiniciado. Optamos por um logar todos os comandos SQL que demorarem mais de 2 minutos para executarem, DDLs, uso do TEMP, locks, checkpoints. Logar todos os comandos pode ser inviável em termos de volume de logs gerados. Se você utiliza muitas tabelas temporárias, usar o log_statemente em ‘ddl’ pode ser um exagero também. Da mesma forma, logar conexões e desconexões pode gerar um excesso de logs.

Servidor de produção embarcado

# - Where to Log -
log_destination                 = 'stderr'
logging_collector               = on
log_directory                   = 'pg_log'
log_filename                    = 'postgresql-%d.log'
log_truncate_on_rotation        = on
log_rotation_age                = 1d
log_rotation_size               = 0

# - When to Log -
client_min_messages             = warning
log_min_messages                = warning
log_min_error_statement         = warning
log_min_duration_statement      = 120000

# - What to Log -
log_checkpoints                 = on
#log_connections                = off
#log_disconnections             = off
log_duration                    = off
log_error_verbosity             = default
log_hostname                    = on
log_line_prefix                 = '%t [%p]: [%l] user=%u,db=%d,app=%a,host=%h'
log_lock_waits                  = on
log_statement                   = 'none'
log_temp_files                  = 16MB
log_hostname                    = off

Aqui queremos um log mais enxuto, pois raramente alguém irá olhar para eles. Também vamos manter um log por dia do mês e depois reescrever eles. Também  diminuímos o número de mensagens e deixamos só as mais importantes.

Servidor de testes / homologação / desenvolvimento

# - Where to Log -
log_destination                 = 'stderr'
logging_collector               = on
log_directory                   = 'pg_log'
log_filename                    = 'postgresql-%Y-%m-%d_%H%M%S.log'
log_truncate_on_rotation        = on
log_rotation_age                = 1d
log_rotation_size               = 256MB

# - When to Log -
client_min_messages             = log
log_min_messages                = info
log_min_error_statement         = warning
log_min_duration_statement      = 0

# - What to Log -
log_checkpoints                 = on
log_connections                 = on
log_disconnections              = on
log_duration                    = off
log_error_verbosity             = verbose
log_hostname                    = on
log_line_prefix                 = '%t [%p]: [%l] user=%u,db=%d,app=%a,host=%h'
log_lock_waits                  = on
log_statement                   = 'ddl'
log_temp_files                  = 0
log_hostname                    = on

Aqui deixamos o log mais verboso para pegar possíveis erros. Em geral o volume de logs nunca é tão grande como na produção, pois a base não é utilizada com a mesma intensidade.

Alterando parâmetros em pleno vôo

Certamente você vai querer alterar alguns parâmetros em alguns momentos, particularmente em produção para pegar casos específicos. Um exemplo seria habilitar o log de conexões e desconexões, outro seria habilitar o log de arquivos temporários. Um caso realmente comum é o de se alterar o log_min_duration para zero e assim logar todos os comandos SQL por um período específico de tempo até que o problema que se deseja investigar se reproduza. Depois voltamos à condição anterior. Vejamos como fazer isso nas versões anteriores ao 9.4 do PostgreSQL (à partir do 9.4 você pode utilizar o ALTER SYSTEM para editar o arquivo postgresql.conf

1. Editar o arquivo postgresql.conf. Suponhamos aqui que iremos mexer especificamente nas configurações do log_min_duration_statement, log_connections e  log_disconnections:

   log_min_duration_statement      = 0
   log_connections                 = on
   log_disconnections              = on

   Você pode deixar comentada a opção que vai alterar e copiar a linha com o novo parâmetro para guardar como referência para quando for retornar à configuração anterior. Também pode tirar uma cópia do seu arquivo postgresql.conf e depois restaurar a cópia para voltar as configurações originais

2. Carregar as configurações e rotacionar o log. Além de enviar um sinal de SIGHUP para o postgres recarregar as configurações alteradas, seria bom rotacionar o log (claro, a não ser se você não utiliza uma configuração no log_filename que facilite isso) para isolar o arquivo que contem as configurações diferenciadas:

   SELECT pg_rotate_logfile(), pg_reload_conf();

3. Esperar o evento que você quer verificar ocorrer.  Monitore o diretório pg_log e verifique o tamanho e volume dos arquivos gerados. Não seria uma boa ideia deixar a partição lotar com logs. Monitorar é importante. Claro que você deve sempre colocar o pg_log numa partição separada da raiz. Mesmo assim, monitore o volume de logs gerados.
4. Depois que o evento ocorreu e você acha que já coletou logs por tempo suficiente, edite o postgresql.conf novamente e vote para a configuração original;
5. Recarregue novamente as configuraçõeserotacioneolog, da mesma forma que fizemos no passo 2:

   SELECT pg_rotate_logfile(), pg_reload_conf();

Ferramentas para análise de logs

Analisar logs pode ser uma tarefa árdua. Um bom editor de texto é uma ferramenta importantíssima. Uma das coisas que você deverá fazer com frequência é seguir uma sessão do inicio ao fim. Para isso o grep será seu grande amigo. Você pode fazer algo simples como:

cat postgresql-2015-01-20_000000.log | grep 'user=user_teste' > teste.sql

Também pode filtrar por aplicação ou mesmo por PID, para pegar uma sessão específica. Isso ajuda muito a avaliar o comportamento da aplicação e ver o que realmente está acontecendo no banco de dados. Uma coisa que descobrimos como DBA é que o desenvolvedor muitas vezes não sabe o que a sua própria aplicação faz no banco de dados. Você descobre problemas crônicos apenas com este tipo de análise.

Mas haverá momentos em que você deverá descobrir onde está um gargalo de performance e existe um caso bem chato de pegar: quando um comando é repetido milhares de vezes apenas mudando os parâmetros. Por exemplo: a aplicação resolve atualizar em 10% o preço de todos os produtos e resolve fazer um UPDATE em cada produto um por vez ao invés de fazer um único UPDATE para todos os produtos. Nesta situação, outros métodos de análise falham em achar gargalos deste tipo, pois se baseiam em olhar comandos SQL lentos. Acontece que um UPDATE simples em si é bem rápido. Mas o conjunto de milhares de UPDATEs é bem lento. Uma ferramenta de analise de logs vai te ajudar nesta tarefa com muita eficiência.

pgBadger

O pgBadger é a ferramenta mais utilizada e mais eficiente que eu conheço para analisar logs do PostgreSQL. Fácil de instalar e muito rápida, ela analisa vários logs de uma vez, um intervalo de tempo específico, tem várias opções bacanas, mas se você não utilizar nenhuma delas, provavelmente já terá um resultado excepcional. Apenas tome cuidado com o parâmetro log_line_prefix, que pode ter que ser ajustado.  Segue aqui um exemplo de geração de relatório analítico do pgBadger:

~/pgbadger-6.2$ ./pgbadger --prefix '%t [%p]: [%l] user=%u,db=%d,app=%a,remote=%r ' postgresql-2015-01-20_000000.log
[========================>] Parsed 67110115 bytes of 67110115 (100.00%), queries: 87556, events: 1015
LOG: Ok, generating html report...
~/pgbadger-6.2$ ls -lh out.html
-rw-r--r-- 1 telles telles 2,0M Jan 20 17:23 out.html

O arquivo out.html pode ser aberto em qualquer navegador e possui dezenas de informações úteis. Veja aqui um exemplo de relatório gerado por ele.

Outras ferramentas

• pgFouine: Ferramenta de analise de logs largamente utilizada antes do advento do pgBadger. Caiu em desuso.
• Logs em CSV: Você pode gerar logs no formato CSV e utilizar outras ferramentas externas para analisar os logs. Pode inclusive utilizar o comando COPY  e importar os logs numa tabela. Assim você pode utilizar comandos SQL para filtrar e analisar os logs;
• auto_explain: Esta ferramenta gera o EXPLAIN de comandos SQL no log que obedecerem alguns critérios.
• Elasticsearch: Uma plataforma de analise de dados com inúmeras opções avançadas.

Conclusão

Uma parte considerável do trabalho do DBA é gasta analisando logs. É a melhor forma de se avaliar o que aconteceu no passado. Um log bem configurado possibilita um trabalho bem feito. E a chance do seu problema ser resolvido aumenta em probabilidade, velocidade e qualidade. Outra coisa importante é manter o log limpo. É comum ver aplicações que geram lixo no log ou cometem “erros inocentes” que não geram nenhum problema na prática, mas entopem o log de lixo. O log é uma fonte imprescindível de informações no PostgreSQL. Ele possui capacidades bem avançadas para trabalhar com seus logs, mas você precisa pelo menos configura-los corretamente.