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.
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:
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):
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
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:
Nenhuma novidade, a performance estava compatível com outros servidores.
Próximo passo, saber a performance dos comandos executados:
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:
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.
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:
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:
- Documentação oficial para problemas de latência no Redis: https://redis.io/topics/latency
- Tutorial Redis Benchmark by Digital Ocean: https://www.digitalocean.com/community/tutorials/how-to-perform-redis-benchmark-tests
- Documentação do comando INFO: https://redis.io/commands/info
- Documentação do comando SLOWLOG: https://redis.io/commands/slowlog
