Lost connection to MySQL server during query: Quem é o culpado?

Contexto: atendemos cerca de 20k requests por minuto na aplicação, mantendo uma média de 250 conexões ativas no banco de dados e com uso de CPU em torno de 40%.

Ao longo de vários meses vínhamos recebendo o infame Lost connection to MySQL server during query. Nunca conseguimos rastrear ao certo a raiz do problema, as vezes parecia relacionado a peering entre VPCs, em outros aparentava estar relacionado aos processos de deploys e volta e meia surgia durante horários de pico também. No fim, a melhor hipótese sempre parecia a clássica desculpa de "problema aleatório de rede" e com isso a vida seguiu em relativa paz… Até que tudo mudou.

A quantidade de erros começou a aumentar na medida que o número de instâncias EC2 necessárias para o sistema aumentava. Agora realmente precisávamos achar a raiz disso antes que algo pior ocorresse. Na internet, tudo girava em torno do wait_timeout e outros parâmetros, cuja a documentação do MySQL faz um bom trabalho em explicar:

• https://dev.mysql.com/doc/refman/5.6/en/server-system-variables.html#sysvar_wait_timeout
• https://dev.mysql.com/doc/refman/5.6/en/communication-errors.html
• https://dev.mysql.com/doc/refman/5.6/en/error-lost-connection.html

Porém, nenhuma das sugestões pareciam relacionadas ao nosso caso específico. O que acabamos percebendo é que os erros ocorriam, mas não sempre, quando havia um pico no uso de CPU do servidor da aplicação e não no banco de dados como se poderia esperar. Apesar de monitorarmos os usos de CPU por contêiner, não sabíamos de fato o que cada processo estava usando dentro host. Acabamos implementando uma cron simples no host para enviar o resultado do docker stats e ps para os logs do CloudWatch. E foi assim que achamos o nosso culpado, ou melhor dizendo, os dois culpados:

• /etc/cron.daily/mlocate responsável por manter os índices do comando mlocate atualizado.
• unattended-upgrade responsável por manter os updates de segurança mais atuais instalados.

Esse pessoal "da pesada", vem ativo por padrão no Ubuntu 18.04 LTS.

mlocate

Esse aplicativo permite procurar arquivos no disco. Ele até tem bug aberto:

Bug #1190696 "updatedb.mlocate uses 100% of the hdd IO. The OS ..." : Bugs : mlocate package …

Não ocorre sempre, mas de fato faz a CPU bater no teto. Para desativar é simples:

chmod -x /etc/cron.daily/mlocate

Isto remove a permissão de execução da cron, impedindo que ela atualize os os índices do comando. Isto realmente não faz falta alguma, já que nosso server só existe para rodar a aplicação, nossos ambientes são stateless, raramente precisamos acessar eles e muito menos utilizar o comando locate.

unattended-upgrade

Esse era o causador do “problema aleatório difícil de rastrear”. Motivo? Por padrão ele realmente roda em horários aleatórios. Veja o arquivo de configuração em /lib/systemd/system/apt-daily.timer:

Roda as 6 e as 18, com um atraso aleatório de até 12 horas.

Instalação/Compilação de updates é inerentemente CPU intensive e quando essas atualizações ocorrem com o ambiente de produção rodando em horário comercial, as coisas ficam ainda piores. Some isso a chance de até bibliotecas relacionadas a rede/MySQL estarem sendo atualizadas com o “avião voando” e temos a receita do desastre. Diferentemente do mlocate a correção aqui não pode ser apenas desativar, afinal ele é responsável por instalar os patches de segurança que realmente devem estar atualizados. A solução vai variar conforme o setup do seu ambiente, mas no nosso caso foi o seguinte:

• Nossas AMIs são geradas antes de cada publicação, que ocorre várias vezes por dia.
• Nesse processo, que utiliza o Packer, forçamos a execução manual dos updates com o comando unattended-upgrades -d.
• Depois de atualizado desativamos o upgrade automático com sed -i 's/1/0/g' /etc/apt/apt.conf.d/20auto-upgrades. Como nosso build ocorre várias vezes por dia não ficamos expostos a falhas, não mais que um dia ao menos.

Após desativado, nossos "problemas de conectividade aleatórios" acabaram. Parece que o os upgrades não eram bem unattended afinal de contas.

A verdadeira piada foi ter sofrido tanto, por algo tão simples.

Conclusão

• Lembra do SOLID, e o Interface Segregation Principle? Isso vale para tanto para o seu framework web cheio de recursos, quanto para o seu SO. Sempre considere pegar apenas o mínimo necessário para solucionar seu problema, nunca se sabe que tipo de problema pode surgir daquele monte de recurso que você nem se importa. Talvez usar um Debian mais seco ou alguma outra distro mais enxuta seja algo para considerarmos.
• Monitoramento a nível de processo é bem útil. Saber que o contêiner web ficava a 99% de CPU não ajudou muito, inclusive correlacionamos, de forma errônea, com algumas partes da aplicação que de fato eram CPU intensive. Bastou conseguir ver os dois processos estranhos, ocupando a maior parte da CPU para resolver o problema.
• Quando o uso de CPU fica fora de controle, todo tipo de problema pode aparecer. Se hoje você tem algum spike de CPU "misterioso e recorrente", resolva isso antes de passar semanas caçando um problema no lugar errado. Nosso problema de conectividade com o MySQL, no final das contas, não tinha nada a ver com MySQL.