Avaliando a fundo a performance do Varnish Cache através de seus logs

Como todo bom sysadmin sabe, logs e estatísticas são seus grandes amigos, principalmente quando temos que identificar problemas de performance.

A grande maioria está familiarizada em como debugar logs de acesso e erros de web servers mais populares, como Apache e Nginx, porém, quando falamos do Varnish, essa situação se inverte. Muitas são as causas dessa falta de familiaridade:

• Seus logs são complexos, ainda mais em um cenário com múltiplos domínios;
• A documentação oficial segue o estilo de man page, não provendo exemplos práticos de como tirar informações pertinentes;
• A documentação de terceiros (mesmo em outros idiomas) é focada em versões mais antigas do Varnish, não se aplicando às versões mais atuais devido às mudanças aplicadas a partir da versão 4.0.

Então, como fazer com que os logs do Varnish possam trabalhar a nosso favor?

Em primeiro lugar, faz-se necessário conhecer um pouco mais as opções e tipos de informações (chamadas de tags) que o Varnish nos fornece, que são bastante pertinentes:

• Qual IP e porta remota fez a requisição (ReqStart), qual o tipo da requisição (ReqMethod) e URL (ReqURL);
• Os cabeçalhos enviados pelo cliente e/ou configurados pelo Varnish no processamento inicial da requisição (ReqHeader);
• Os passos que foram realizados pelo Varnish para processar a requisição (VCL_return e VCL_call);
• Qual status HTTP e resposta do back-end (RespStatus e RespReason);
• Os cabeçalhos retornados pelo back-end, juntamente com os definidos pelo Varnish no processo de resposta (RespHeader).

Tendo conhecimento desses dados em mãos, podemos colocar em prática a análise desses logs. Para exemplificar, vamos utilizar um ambiente VPS que possuo, no qual se encontram hospedados dois domínios pessoais (vou chamá-los de dominio1.net e dominio2.net), ambos rodando WordPress e servidos pela mesma instância do Varnish, com seus back-ends utilizando Nginx, PHP-FPM e MariaDB.

Para avaliar a eficiência do Varnish em sua principal funcionalidade, temos que descobrir qual o percentual das requisições servidas por ele. Para isso, julgo importante levantarmos estas duas estatísticas:

• Quantas requisições foram servidas do cache (cache_hits);
• Quantas requisições foram repassadas para o back-end (cache_miss).

E como levantamos isso? Através da primeira ferramenta que irei apresentar hoje, que é o varnishstat. Ela nos provê justamente as estatísticas da instância do Varnish em execução.

A mera execução do comando, sem quaisquer parâmetros, nos traz uma chuva de estatísticas que normalmente não são úteis. Para torná-la uma ferramenta poderosa de análise, temos que fazer uso de seus parâmetros. Para este exemplo, irei utilizar dois deles:

• -1: indica para o comando imprimir as estatísticas apenas uma vez, levando em consideração os dados desde o início da execução do Varnish;
• -f: mostra apenas as estatísticas de interesse (neste exemplo, MAIN.cache_hit e MAIN.cache_miss).

Executando em meu ambiente, tenho o seguinte retorno:

Fazendo uma conta rápida, temos que 883 requisições resultaram em entrega de conteúdo pelo Varnish, e apenas 18,59% do conteúdo servido foram providos pelo cache em memória por ele armazenado. Como esse percentual é abaixo de 90%, valor por mim considerado ideal, devem ser avaliadas as causas por tantas requisições repassadas para o back-end, se são intencionais ou não.

Agora, temos que identificar qual domínio é responsável por não consolidar cache em nossa instância. Para isso, apresento outra ferramenta que o Varnish nos disponibiliza e que nos ajudará nessa análise: o varnishtop, que lê os logs em memória e apresenta uma lista atualizada das entradas de log mais comuns.

Da mesma forma que o varnishstat, sua execução sem a utilização de parâmetros adicionais não traz informações relevantes. Por isso, vamos passar dois deles para sermos mais efetivos:

• -1: imprime as estatísticas apenas uma vez, levando em consideração o início da execução do serviço;
• -I: para mostrar apenas um campo específico que possua uma determinada tag; nesse caso, “ReqHeader:Host”, para mostrar apenas o header “Host” requisitado pelo cliente.

Disparando o comando com os parâmetros em questão, temos:

Aqui, fica demonstrado que o dominio1.net é o host que recebe mais requisições, e que as requisições em MISS ultrapassam o total de requisições para o dominio2.net. Portanto, vamos aprofundar a análise, a partir daqui, para o primeiro.

Agora, vamos validar que as requisições em MISS estão sendo retornadas por esse domínio. Para isso, vamos mudar a forma como iremos disparar o comando varnishtop, passando a utilizar um terceiro parâmetro, o “-q”:

• -q: indica a passagem de uma consulta aos VSL (Varnish Shared Memory Logs). Nesse caso, perguntaremos por requisições que tenham o header Host igual ao domínio desejado.

Abaixo, temos o resultado dessa consulta para solicitações realizadas ao host dominio1.net, que teve o valor do parâmetro “-I” alterado para essa execução:

Esse cenário demonstra que 461 das 733 requisições entregues pelo Varnish (ou seja, 62,9%) para esse domínio retornaram MISS. Outras 167 requisições (22,7%) foram redirecionadas para o back-end devido a regras de exceção de cache, e apenas 15% foram entregues pelo cache.

O que nos dizem esses números? Que pode haver URLs com headers forçando a não execução de cache ou, ainda, um TTL (time-to-live) excessivamente baixo, sinais que devem ser investigados com maior profundidade.

Você pode estar se perguntando: cadê as outras requisições? Simples: quase 90% foram geradas por redirecionamento para HTTPS, causadas por regra aplicada em sua configuração (arquivo VCL). Entrega de conteúdo mesmo são os outros 10% representados e comentados acima.

Ficou interessado? Leia a documentação oficial, pratique mais, e leia também sobre os comandos varnishlog e varnishncsa! Com certeza você irá tirar proveito das ferramentas poderosas que o Varnish possui!

***

Artigo publicado na revista iMasters, edição #28: https://issuu.com/imasters/docs/imasters_28_v5_issuu