fbpx

Diagnosticando Problemas de Latência no Redis

folder_openSem Categoria
commentNenhum comentário

Recentemente tivemos uma aplicação monitorada que passou a apresentar alto uso de CPU e alta latência no Redis, resultando em lentidão na aplicação, vou descrever o passo a passo de como diagnosticamos e resolvemos o problema.

Top
Resultado do comando “top” na linha de comando do Linux, é possível ver o serviço do Redis consumindo 12% nesse momento (em horário de pico, chegava a mais de 30%)

A primeira vista, não parecia um problema sério, pois o Load do servidor estava sob controle, e o próprio Redis estava longe do limite (lembrando que o Redis roda sob uma única Thread, então o máximo que ele consome é 100% de uma única CPU, não expandindo para outras CPUs em um servidor com múltiplas CPUs).

Mas haviam impactos na aplicação que não eram aparentes, que acabariam escalonando em algum momento de stress.

O primeiro instinto foi reiniciar o serviço, pensando ser um mal funcionamento, mas não surtiu efeito.

Para quem já estudou um pouco mais a fundo o Redis, sabe que ele mantém uma cópia do banco de dados em disco (snapshot), fazendo update nesse banco em intervalos determinados, salvando quando é desligado e recarregando quando é iniciado.

A forma de desligar esse banco no disco é comentando as linhas “save” no /etc/redis.conf:

Desligando a opção save no redis
Para desligar, basta descomentar a primeira linha e comentar as demais

O snapshot do banco do Redis tem por objetivo que o banco de dados não inicie vazio, gerando persistência do mesmo. Claro que, salvando a cada 60 segundos, não é algo sirva para consistência a nível de banco de dados, mas pode salvar muitas requisições para um Cache.

Ao invés de apagar o arquivo do banco, optamos por apenas limpar o Cache do Redis para ver se era algo relacionado (atenção, alguns ambientes podem ter impactos grandes ao limpar o Cache, recomendamos pular para as próximas etapas e tentar isso posteriormente):

FLUSHALL no Redis
Executando o comando FLUSHALL no Redis

Isso aliviou momentaneamente, o uso de CPU do Redis caiu para perto de 0%, mas depois de algumas horas (quando o banco do Redis cresceu novamente), o problema voltou.

Nosso primeiro diagnóstico foi tentar entender quantas chaves e uso de memória nesse servidor Redis e comparar com outro em situação similar de uso, para isso, conectamos no servidor Redis na linha de comando e usamos o comando INFO

Obtendo informações
Resultado do comando INFO no Redis
Resultado do comando INFO, cortamos algumas partes para mostrar os dados que analisamos como relevantes

O comando INFO não trouxe muita informação relevante, o Redis utilizava pouco mais de 200Mb de memória, tinha cerca de 327 mil chaves armazenadas, o uso de CPU era do próprio Redis e não do sistema operacional (para ter uma visão completa sobre o resultado do comando INFO, veja na documentação oficial: https://redis.io/commands/info).

Os números eram 2 a 3 vezes superiores aos servidores que rodavam em ambientes similares, talvez pelo ambiente em si, embora maiores, os números em si não assustavam.

O próximo passo foi tentar entender a performance do Redis, pra isso, existe o comando redis-benchmark que costuma vir instalado junto do pacote do próprio Redis:

Resultado redis-cli --latency
Resultado do comando redis-benchmark -q

Nenhuma novidade, a performance estava compatível com outros servidores.

Próximo passo, saber a performance dos comandos executados:

Resultado do comando redis-cli --latency
Resultado do comando redis-cli –latency

Aqui acendeu um alerta, a latência média dos comandos estava acima de 40ms!!! O normal para essa métrica é 0,1ms.

Pensando em retrocesso, isso impactava uma das funções da aplicação, se os comandos demoravam 40ms cada, poderíamos executar 25 comandos por segundo, o que era um número inaceitável para a aplicação.

Lembrando ainda que toda média é burra, no comando INFO pouco acima vimos que o Redis estava servindo 700 comandos por segundo, se o tempo médio deles estava em 40ms, significa que uma boa parcela deles estava rodando a menos de 0,1ms e alguns poucos deveriam estar acima de 100ms para chegar nessa média. Para exemplificar: (500 comandos a 0,1ms + 200 comandos a 150ms ) / 700 comandos por segundo = 42,9ms de média

Ok, agora precisamos mapear os comandos lentos e a causa.

Pela documentação do Redis, uma das razões do Redis ter alta latência é se a memória do mesmo estiver sendo alocada em Swap, para verificar isso, usamos os comandos:

Verificando Memória Swap no Redis
Verificando se o Redis está alocado na memória Swap

Pelo comando Top que tínhamos executado no início, sabíamos que não tinha muito uso de Swap no servidor, mas seguimos o roteiro de diagnóstico, o resultado indicava que o processo do Redis não usava nada de Swap.

Próximo passo, vamos entender os comandos que estão sendo executados, pra isso, o Redis conta com o comando SLOWLOG documentado aqui.

Resultado do comando SLOWLOG LEN
Resultado do comando SLOWLOG LEN

Um indicativo de problema, o log de comandos lentos estava cheio (128 entradas).

Como referência, pode-se executar: SLOWLOG RESET, contar 10 segundos e executar novamente SLOWLOG LEN para calcular quantos comandos lentos são executados em média. No nosso caso, depois de uns 20 segundos o Log estava cheio novamente com 128 entradas, o que dá uma média de ~6 comandos lentos por segundo.

Próximo passo, vamos ver esses comandos com o comando SLOWLOG GET:

Resultado do comando SLOWLOG GET
No exemplo, o resultado do comando SLOWLOG GET, separamos 3 registros (separados por uma linha)

Ok, esse print não é do servidor que estava com lentidão, é de um servidor com a mesma aplicação em um ambiente um pouco menor, mesmo assim, podemos ver que o problema acontece, com os comandos KEYS demorando cerca de 11ms.

Esse comando, dentro da aplicação, é usado para gerenciar uma fila, algumas partes do código inserem registros nessa fila, enquanto outras partes consomem essa fila para executar funções específicas.

Analizando a documentação do comando KEYS, é sugerido utilizar o comando SCAN para isso, possivelmente seria a solução ideal.

Aliás, na documentação do comando KEYS, eles indicam que em um Laptop simples com 1 milhão de chaves o Redis é capaz de executar o comando KEYS em 40ms, próximo ao nosso número. Talvez nossa performance estivesse pior por conta da concorrência, mas com certeza 40ms para uma consulta ao Cache é muita coisa.

Não estávamos no ponto de fazer essa alteração na aplicação nesse momento, então precisávamos pensar como o Redis funciona internamente para agir.

Aparentemente todo o problema é executar o comando KEYS com o * no final, isso faz com que o Redis tenha que percorrer todas as chaves para procurar pela chave desejada, o que, em 300k registros, pode ser um problema.

Por isso que, ao limpar a base com o FLUSHALL o problema era resolvido a princípio, pois a base ficava pequena novamente.

Bom, se com poucas chaves o comando KEYS executa de forma rápida, basta garantir que existam poucas chaves para essa consulta.

Por sorte, o Redis vem configurado por padrão com 16 bancos de dados (numerados de 0 a 15), isso é configurado no parâmetro “databases” no arquivo /etc/redis.conf

Olhando retroativamente, foi um erro do projeto usar o mesmo Database para Cache e para a função de Fila da aplicação.

Ajustamos rapidamente para que a conexão da Fila utilizasse o Database número 1 e mantivemos o Cache no Database número 0, separando as funções da aplicação.

O problema desapareceu, a aplicação voltou a performar, o uso de CPU diminuiu e tivemos um final feliz. Ainda temos uma lição e casa a fazer, trocar o comando KEYS para SCAN, mas não é mais uma emergência.

Mais referências:

Related Posts

Deixe uma resposta

O seu endereço de e-mail não será publicado. Campos obrigatórios são marcados com *

Preencha esse campo
Preencha esse campo
Digite um endereço de e-mail válido.
Você precisa concordar com os termos para prosseguir

Menu
Sky Monitor
Request a Demo!
Simply enter your email
address and our team will contact as soon as possible
SUBMIT NOW
close-link
Sky Monitor
Solicitar uma Demonstração!
Entre com seu e-mail e nossa equipe entrará em contato:
ENVIAR AGORA
close-link

Subscribe to our newsletter

Sign-up to get the latest news straight to your inbox.
SUBSCRIBE!
Give it a try, you can unsubscribe anytime.