Dissecando logs no Varnish

Imagine você, sentado no sofá assistindo algo interessante, quando lhe vem de repente na sua mente: “Caramba! Será que meu Varnish está rodando bem o suficiente?” Então se levanta, bebe alguma coisa e se depara com o terminal do servidor. E agora, o que fazer? :-)

Logs! Logs e estatísticas são sempre seus amigos para você fazer esse tipo de avaliação: desempenho, resolução de problemas, estatísticas…

O varnish, sendo um ótimo programa, fornece várias ferramentas que te ajudam a ver o que exatamente está acontecendo em seu servidor. Neste tutorial, vamos ver como usar essas ferramentas ao seu favor. Lembre-se que é sempre importante você avaliar o que está acontecendo e mexer para sempre deixar melhor do que estava!

Onde os registros são gerados

Diferente de alguns outros servidores que vemos por aí, o varnish por padrão não costuma gravar seus logs em um arquivo. Ao invés disso, tudo que ele está fazendo é mandado em tempo real para um log compartilhado em memória. Os acessos, contadores de estatísticas e estado do varnish em si, todos estes são gravados nesse log compartilhado em memória. Isso significa que os dados estão disponíveis para todos que acessarem esse log.

Esse log em memória compartilhada funciona da seguinte forma: os vários processos (e threads) do varnish, quando precisam registrar alguma coisa (exemplo: um usuário acessando a Home do site), acessam o log, obtém um lock de escrita, manda o registro e tira o lock. O lock garante que apenas um processo está escrevendo ao mesmo tempo. Isso é feito continuamente para tudo que o varnish faz. Por ser algo em memória compartilhada (e que fica na memória RAM), é extremamente rápido.

À medida que novos dados vão sendo incluídos nesse log, o varnish descarta automaticamente os velhos (pense em uma fila). Dessa forma, o log em memória nunca vai ocupar mais que por volta de 90MB de espaço, segundo sua documentação. Os registros são incluídos e excluídos com muita rapidez, em duas seções:

Contadores: fornecem números sobre o estado atual do varnish, como por exemplo: quantos usuários conectados, quantas requisições servidas, o quanto foi cacheado, entre outros;
Requisições: todos os detalhes sobre uma requisição feita, tanto para usuários quanto para os backends.

Uma vez que o log em memória compartilhada está disponível, o varnish fornece outras ferramentas, separadas do executável principal, que acessam esse log e lêem os dados. Como eles só precisam ler os dados, não precisam obter o lock citado anteriormente, e por isso não influenciam na velocidade da inclusão de registros. Com isso, você pode utilizar as ferramentas para fazer análise desses dados o quanto quiser, com quantos processos simultâneos quiser.

Curiosidade: quer saber onde fica esse log, também conhecido como Varnish Shared Memory (VSM)? Com o varnish rodando, execute o seguinte comando no terminal (como root):

lsof -n | grep varnish | grep vsm

Vão aparecer várias linhas como esta:

varnishd 4356 4362 nobody mem REG 253,1 84934656 2623469 /var/lib/varnish/eowyn.localdomain/_.vsm

Cada linha indica uma thread do varnish que está com o arquivo VSM aberto, que no caso está no arquivo /var/lib/varnish/eowyn.localdomain/_.vsm. O conteúdo desse arquivo, apesar de parecer estar no disco, é alocado diretamente na memória do sistema operacional, e o próprio S.O. lida com as mudanças em memória.

varnishncsa

O varnishncsa, como o nome diz, gera logs de acesso em formato NCSA, o mesmo formato utilizado por padrão em outros servidores web existentes. Esse formato é útil para você analisar os dados, criar estatísticas, saber quem acessa o que, onde, entre outros. Usar ele é muito fácil! Em um terminal com o varnish rodando e sendo acessado, digite:

Pronto! Até você dar CTRL+C, seu terminal verá linhas e linhas com todos os acessos HTTP feitos no Varnish. Exemplo:

127.0.0.1 - - [05/Mar/2013:22:20:49 -0300] "GET http://localhost:81/ HTTP/1.1" 301 0 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.17 (KHTML, like Gecko) Chrome/24.0.1312.70 Safari/537.17"

(Não vou explicar o que cada parte da linha significa, pois isso já é bem difundido por aí há anos! Caso não saiba, procure por formato web log NCSA.)

Agora supomos que você queira imitar os servidores web e gravar esses dados em um arquivo. O varnishncsa pode fazer isso, utilizando a seguinte linha de comando:

varnishncsa -a -w /var/log/varnish/access.log -D

Sobre os parâmetros:

-a: ao invés de sobrescrever o arquivo, adicionar conteúdo nele;
-w /var/log/varnish/access.log: ao invés de mostrar na tela, grava no arquivo especificado;
-D: (Bonus!) coloca o processo em plano de fundo, para que não seja necessário ficar com o terminal aberto.

Em outras palavras, esse comando pode ser rodado como um serviço. E na verdade, os pacotes de distribuições já tem um serviço pronto para ser usado, usando esse comando.

O que é bastante útil, por exemplo, para centralizar os logs. Se você tem vários servidores backend, ao invés de coletar os dados em todos os servidores e juntá-los, basta olhar no log centralizado do varnish, que terá todas as requisições de todos os servidores.

Outra coisa bem útil, que ajuda bastante na resolução de problemas é saber o que o varnish fez com o item (leia-se: fez cache ou não?). Para isso, podemos personalizar o formato da linha com o parâmetro -F. Lembre-se que ao usar esse comando, você estará saindo do padrão NCSA, o que pode tornar o log impróprio para ferramentas de análise.

No nosso exemplo, vamos adicionar três campos no final da linha:

O cabeçalho HTTP Cookie, recebido pelo cliente;
Se usou o cache (hit) ou teve que ir pegar no backend (miss);
Quanto tempo, em segundos, a resposta veio do servidor backend.

E aqui vai o comando:

varnishncsa -F '%h %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i" "%{Cookie}i" "%{Varnish:hitmiss}x" "%{Varnish:time_firstbyte}x"'

127.0.0.1 - - [05/Mar/2013:22:36:48 -0300] "GET http://localhost:81/ HTTP/1.1" 301 0 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.17 (KHTML, like Gecko) Chrome/24.0.1312.70 Safari/537.17" "wp-settings-time-1=1362450241" "miss" "0.111469746"

varnishlog

Com o varnishlog, a gente consegue um pouquinho mais de informações que o varnishncsa. E quanto eu digo pouquinho, estou sendo bem sarcástico! O varnishlog fornece todas as informações que você precisa sobre todas as requisições que chegam no varnish. Se um usuário acessou um arquivo chamado noticias-maluca.html, o varnishlog te fornecerá todo o conteúdo dessa requisição, todo o conteúdo da requisição do backend, por onde a requisição passou no VCL (recv, lookup, hit, pass, fetch, error, etc), qual a resposta para o cliente, e tudo isso repleto de informação!

Pra começar, vejamos um exemplo de uma requisição no arquivo /phpinfo.php:

17 BackendOpen  b default_4 127.0.0.1 34305 127.0.0.1 92
17 TxRequest    b GET
17 TxURL        b /phpinfo.php
17 TxProtocol   b HTTP/1.1
17 TxHeader     b User-Agent: Wget/1.14 (linux-gnu)
17 TxHeader     b Accept: */*
17 TxHeader     b Host: localhost:81
17 TxHeader     b X-Varnish: 1515988988
17 TxHeader     b Accept-Encoding: gzip
17 RxProtocol   b HTTP/1.1
17 RxStatus     b 200
17 RxResponse   b OK
17 RxHeader     b Date: Wed, 06 Mar 2013 01:54:23 GMT
17 RxHeader     b Server: Apache/2.4.3 (Fedora) PHP/5.4.11
17 RxHeader     b X-Powered-By: PHP/5.4.11
17 RxHeader     b Transfer-Encoding: chunked
17 RxHeader     b Content-Type: text/html; charset=UTF-8
17 Fetch_Body   b 3(chunked) cls 0 mklen 1
17 Length       b 49992
17 BackendReuse b default_4
 5 SessionOpen  c 127.0.0.1 49127 :81
 5 ReqStart     c 127.0.0.1 49127 1515988988
 5 RxRequest    c GET
 5 RxURL        c /phpinfo.php
 5 RxProtocol   c HTTP/1.1
 5 RxHeader     c User-Agent: Wget/1.14 (linux-gnu)
 5 RxHeader     c Accept: */*
 5 RxHeader     c Host: localhost:81
 5 RxHeader     c Connection: Keep-Alive
 5 VCL_call     c recv lookup
 5 VCL_call     c hash
 5 Hash         c /phpinfo.php
 5 Hash         c localhost:81
 5 VCL_return   c hash
 5 VCL_call     c miss fetch
 5 Backend      c 17 balanceamento default_4
 5 TTL          c 1515988988 RFC 120 -1 -1 1362534864 0 1362534863 0 0
 5 VCL_call     c fetch
 5 TTL          c 1515988988 VCL 30 -1 -1 1362534864 -0
 5 VCL_return   c deliver
 5 ObjProtocol  c HTTP/1.1
 5 ObjResponse  c OK
 5 ObjHeader    c Date: Wed, 06 Mar 2013 01:54:23 GMT
 5 ObjHeader    c Server: Apache/2.4.3 (Fedora) PHP/5.4.11
 5 ObjHeader    c X-Powered-By: PHP/5.4.11
 5 ObjHeader    c Content-Type: text/html; charset=UTF-8
 5 VCL_call     c deliver deliver
 5 TxProtocol   c HTTP/1.1
 5 TxStatus     c 200
 5 TxResponse   c OK
 5 TxHeader     c Server: Apache/2.4.3 (Fedora) PHP/5.4.11
 5 TxHeader     c X-Powered-By: PHP/5.4.11
 5 TxHeader     c Content-Type: text/html; charset=UTF-8
 5 TxHeader     c Content-Length: 49992
 5 TxHeader     c Accept-Ranges: bytes
 5 TxHeader     c Date: Wed, 06 Mar 2013 01:54:23 GMT
 5 TxHeader     c X-Varnish: 1515988988
 5 TxHeader     c Age: 0
 5 TxHeader     c Via: 1.1 varnish
 5 TxHeader     c Connection: keep-alive
 5 Length       c 49992
 5 ReqEnd       c 1515988988 1362534863.993273497 1362534863.995902061 0.000078201 0.002552986 0.000075579
 5 SessionClose c EOF
 5 StatSess     c 127.0.0.1 49127 0 1 1 0 0 1 282 49992

Dê uma olhada melhor nas linhas acima… Tente acompanhar a requisição como ela aconteceu no fluxo do Varnish. Observe:

O varnish teve que abrir uma conexão com o backend para pegar a página, ou seja, não usou o cache;
As linhas com a tag VCL_call dizem qual o fluxo da requisição dentro do varnish: recebeu a requisição (recv), procurou no cache (lookup), não encontrou (miss), pegou do backend (fetch), entregou pro cliente (deliver);
Os cabeçalhos HTTP recebidos pelo cliente são identificados pela tag RxHeader;
Os cabeçalhos HTTP enviados pelo servidor são identificados pela tag TxHeader.

Ou seja, com essa linha você tem todas as informações possíveis sobre a requisição. Se um cabeçalho HTTP estranho tiver na requisição, você verá. Se está fora do fluxo que você queria no VCL, pode ver pra onde a requisição está indo e tentar consertar na lógica do VCL. Pode ver o código de status http recebido pelo backend, a URL exatamente como foi pedida, entre outros…

Note que cada linha tem basicamente 4 campos, separados por um ou mais espaços:

O ID único da requisição: As linhas que começam com o mesmo número estão relacionadas, assim você pode ver uma requisição entre muitas simultâneas;
A tag: Uma palavra única que referencia algo ou uma ação;
Tipo de requisição: Se for uma requisição do lado do cliente, será c, se for com o backend, será b, e rotinas internas será um hífen (-);
O conteúdo da tag: Os dados referentes á tag. Por exemplo: a URL, o cabeçalho HTTP, o IP de sessão, etc.

É muita informação! E isso para apenas uma requisição. Se você rodar esse comando em um servidor que tenha centenas de requisições por segundo, tenha cuidado, seu terminal pode explodir com tanta linha passando.

Antes de você começar a usar o comando grep para filtrar as informações do comando varnishlog, não se preocupe! O pessoal que fez o varnish forneceu filtros para que você consiga apenas as informações que te importarem. Mas isso veremos mais adiante.

Déjà vu! Assim como o varnishncsa, o varnishlog também pode escrever em um arquivo (com o parâmetro -w). Ele também usa os parâmetros -a e -D para se tornar um serviço.

Além das requisições, o varnishlog também registra outras coisas como:

A comunicação entre a CLI (exemplo: varnishadm) e o varnish em si;
Os probes dos backends (muito útil);
Erros nas threads que servem os clientes.

O log de probe, por exemplo, pode lhe salvar de muita dor de cabeça. Veja este exemplo de linha:

0 Backend_health - default_2 Still healthy 4--X-RH 5 3 5 0.000624 0.000796 HTTP/1.1 200 OK

Que indica que o backend default_2 ainda está funcionando (healthy) e retornou o esperado HTTP 200. Se um backend está falhando, você pode identificar em uma linha como essas qual tipo de código está sendo retornado e o que deve ter acontecido para o probe falhar, por exemplo. Acontece com certa frequencia o probe retornar um HTTP 301 ou 302 e você nem perceber (só vai perceber quando o site ficar fora do ar).

Outro recurso útil é saber que tipo de requisição você quer logar: de clientes ou de backend. Para isso usa-se os parâmetros:

# Para logar apenas as requisições de clientes
varnishlog -c
# Para logar apenas as requisições de backends
varnishlog -b

Filtragem de dados

Com tanta informação, fica difícil a gente monitorar só aquilo que a gente quer… Ainda mais quando você espera que seu servidor tenha centenas ou milhares de requisições por segundo. Para resolver esse problema e melhorar suas habilidades de troubleshooting, o pessoal do varnish oferece formas de você filtrar os dados tanto no comando varnishncsa quanto no varnishlog.

O principal campo que podemos filtrar é o campo da tag, que como explicado junto ao varnishlog, identifica algo ou alguma ação, junto com seu conteúdo. Mas deixando de lado um pouco a falácia, vamos começar com alguns exemplos:

# Todas as requisições de clientes para /pagina.php
varnishlog -c -m RxURL:/pagina.php
# Todas as requisições que deram http status 500 (Internal Server Error) no backend
varnishlog -b -m RxStatus:500
# Agora com varnishncsa (que aceita apenas o lado cliente), listando o mesmo erro 500:
varnishncsa -c -m 'TxStatus:500'
# Todas URLs enviadas pro backend (miss)
varnishlog -b -O -i TxURL

Aqui podemos ver que o parâmetro -m é bastante útil: ele filtra pelo conteúdo das tags. E tem mais, ele também aceita expressões regulares! Isso significa, por exemplo, que você pode procurar por requisições que contém um Cookie em específico…

# Somente requisições de usuários logados no WordPress

varnishlog -c -m "RxHeader:Cookie.*wordpress_logged_in"

Também, nos exemplos anteriores, eu usei o parâmetro -O para isolar apenas a tag que precisamos, que no caso foi o TxURL (URL enviada). Outro exemplo seria ver as requisições em uma página específica e que retornem erro 500:

varnishlog -b -m 'TxURL:/cadastro/' -m 'RxStatus:500'

(Usei dois parâmetros -m, o que indica uma regra de filto MAIS outra regra de filtro (operador lógico AND)).

varnishtop

Depois de tantos detalhes com o varnishncsa e o varnishlog, o varnishtop vem para te ajudar a ter uma visão geral de como seu varnish está funcionando. O varnishtop funciona como um agregador de tags. Ao especificar o varnishtop com uma tag, você consegue ver a quantidade de vezes que aquela tag aparece. As tags são ordenadas por essa quantidade, permitindo assim você ver números estatísticos interessantes sobre o seu cache. Exemplo:

varnishtop -i RxStatus
list length 3
     0.62 RxStatus       200
     0.54 RxStatus       301
     0.46 RxStatus       500

No exemplo, o status 200 é o que mais é retornado. Se o 500 está no topo, tem algo muito errado com seu sistema!

Outros exemplos:

# As URLs mais acessadas
varnishtop -i RxURL
# Os navegadores utilizados pelos clientes
varnishtop -i RxHeader -C -I ^User-Agent
# As URLs que estão sendo mais requisitadas nos backends (miss)
varnishtop -i TxUrl
# Quais os sites que mais referenciam sites no seu servidor (referrer)
varnishtop -i RxHeader -I Referrer

varnishstat

Até agora vimos ferramentas que consultam a parte de requisições do log em memória compartilhada. O varnishstat é uma ferramenta que observa os contadores do varnish, ou seja, números que nos indicam como o varnish está rodando desde que iniciou.

Algumas informações importantes mostradas pelo varnishstat:

A quantidade de hits em relação a miss (chamado de hitrate);
Quantos clientes conectaram e quantas requisições foram feitas;
Número de objetos alocados ao cache e quantidade de memória utilizada pelo mesmo;
Conexões aos backends, assim como falhas;
Quantos bytes transferidos, entre outros.

Executando apenas o comando varnishstat lhe coloca no modo interativo, atualizando de 1 em 1 segundo os contadores na tela. Para sair é só apertar a tecla q.

A primeira linha é o tempo que o serviço está rodando (uptime), no formato “dias+horas:minutos:segundos”.

Na segunda e terceira linha é mostrado o hitrate, ou seja, a quantidade de hits no cache em relação aos misses. Essas linhas dão uma média desde o segundo que você iniciou o varnishstat. A primeira coluna significa a média de 10 segundos, a segunda significa média de 100 segundos e a terceira de 1000 segundos. Repare que os segundos na segunda linha vão crescendo até chegar nesses limites. A terceira linha contém o hitrate em si, variando de 0 (sem hit nenhum do cache: ruim!) e 1.0 (tudo está sendo servido do cache, incrível!). É bom rodar o varnishstat por um tempo e ver o seu desempenho, quanto mais perto de 1, melhor para os seus backends.

A partir da terceira linha, temos o resto dos dados de contadores, em colunas separadas por um ou mais espaços:

Valor total
Média por segundo do período de atualização (padrão de 1 segundo)
Média por segundo de todo o período que o varnish está executando
Descrição

E pela descrição podemos ver alguns contadores interessantes:

client_conn: Quantas conexões de cliente o varnish recebe. Aqui você consegue ver quantos usuários simultâneos (e por segundo) estão utilizando seu varnish;
client_req: Quantas requisições o varnish recebe;
client_drop: Quantos clientes foram descartados pelo varnish. Se não for 0, pode estar dando algum erro de rede, ou faltando recursos de memória, threads, ou coisas do tipo no varnish.
cache_hit: Quantos páginas foram servidas diretamente do cache (hit);
cache_miss: Quantas páginas tiveram que ser pegas do backend (miss);
s_pass: Quantas requisições foram para o pass (passadas propositalmente sem cache);
backend_conn: Quantas conexões com o backend foram feitas;
backend_recycle: Quantas conexões de backend foram reutilizadas, ao invés de abrir uma nova conexão;
backend_fail: Número de falhas no backend, se está crescendo muito, pode haver problemas em seus sistemas web;
backend_req: Quantas requisições feitas aos backends;
n_backend: Número de backends configurados
n_object: Número de objetos alocados no cache;
n_lru_nuked: Número de objetos velhos que foram retirados do cache para colocar novos conteúdos. Um número estável significa que você tem um tamanho de cache bom.
s_bodybytes: Quantos bytes de corpo de requisição foram servidos;
n_wrk: Número de threads alocadas para servir requisiões;
n_wrk_queued: Número de threads que entraram na “fila de atendimento”, esperando o número máximo de threads abaixar, para ser servido;
n_wrk_dropped: Quantidade de vezes que uma thread é descartada pela fila do n_wrk_queued estar cheia, deve ser 0 (assim como o client_drop);
SMF.s0.*: Dados sobre o cache padrão (tamanho, uso, alocações);
SMF.s0.g_bytes: Bytes alocados no cache. Em outras palavras, quanto de memória está usando ativamente pelo cache;
SMF.s0.g_space: O tamanho do cache;
VBE.*: Contadores sobre backends, como referências VCL e probes.

Além disso, o varnishstat pode ser usado também em modo não-interativo: perfeito para uso em monitoração e scripts shell. Basta adicionar o parâmetro -1:

varnishstat -1
client_conn             644461        56.67 Client connections accepted
client_drop                  0         0.00 Connection dropped, no sess/wrk
client_req              644462        56.67 Client requests received
cache_hit               644315        56.65 Cache hits
cache_hitpass                0         0.00 Cache hits for pass
cache_miss                 147         0.01 Cache misses
backend_conn               147         0.01 Backend conn. success
[...]

Neste caso, a coluna 2 significa o valor do contador e a coluna 3 significa a média por segundo em toda a execução do varnish.

E se quisermos apenas mostrar um ou outro dado:

varnishstat -1 -f cache_hit,cache_miss
cache_hit               656020        57.36 Cache hits
cache_miss                 149         0.01 Cache misses

O parâmetro -x joga a saída como XML, enquanto o -j em JSON. Monitorar assim é fácil ;-)

Referências

man pages: varnishd, varnishstat, varnishtop, varnishncsa, varnishlog;
Varnish Book – Getting Started – https://www.varnish-software.com/static/book/Getting_started.html

Brito

Pesquisar este blog