Mover um relatório do monitor das 4:12 para antes do envio da tarde

Às 14:49 chegou uma mensagem. O admin estava “super lento para carregar”. Suspeitei da nossa execução da tarde, então pedi a um agente de IA para investigar. Ele só tinha acesso de leitura e não podia reiniciar nem encerrar nada sem a minha autorização.

Quando ele verificou, a lentidão já tinha passado. Às 15:20, a página inicial, o /admin/ e uma página de equipe carregaram em 0,09 a 0,17 segundo cada. As amostras por minuto do servidor, de 14:50 a 15:17, estavam tranquilas, com CPU entre 10 e 28% e de 0 a 4 requisições lentas por minuto.

O que a “execução da tarde” realmente era

Eu vinha chamando de nossa, mas na verdade é o job diário “Afternoon” do próprio monitor da plataforma. Ele dispara no primeiro ping depois das 14:23. O agente descobriu que nada no nosso repositório de operações, nenhuma sessão de agente e nenhum deploy coincidia com ele.

Entre 14:24 e 14:28, o próprio IP do servidor web enviou cerca de 125 e-mails de ciclo de vida. Um deles foi o mailer 27, “Unsubscribe Batch (Bad Email Addresses)”. Para cada endereço inválido, o código dele executava uma busca com LIKE '%email%' (curinga no início) nas listas do mailer. Hoje isso significou 39 buscas entre 14:25:35 e 14:27:50, cerca de 1.127 segundos de CPU de SQL. A CPU de SQL chegou a 89% às 14:26 e 14:27, e voltou ao patamar normal de 27% às 14:29.

Ou seja, a execução da tarde causa um pico de CPU real e repetível. Essa parte foi confirmada.

Onde eu errei

Eu tinha começado suspeitando que a execução da tarde era a causa. Aquele pico terminou mais de 20 minutos antes da mensagem das 14:49, e o relatório do agente dizia o que ele não conseguiu confirmar: que esse pico era o que a pessoa sentiu.

O mais provável eram duas paradas às 14:48 e 14:49. Cerca de 15 requisições de admin e de equipe, sem relação entre si, ficaram travadas de 15 a 28 segundos e depois terminaram todas juntas. A CPU de SQL naquele momento estava em apenas 27 a 31%. Algumas dessas requisições pareciam de uma sessão de funcionário, possivelmente de quem reportou. Uma importação em massa de agenda de um cliente estava rodando na mesma hora. O agente chamou o bloqueio de palpite, e eu também. Não temos um snapshot de bloqueios das 14:49 para provar.

Tirando a busca do horário nobre

Olhei a parte confirmada e decidi que era um padrão ruim por si só. Colocamos a busca à tarde porque queríamos contatar as pessoas à tarde. A busca pode rodar de manhã, com os resultados guardados, e o job da tarde só precisa enviar o mailer.

Precisava sair como hotfix, porque depende de configurações guardadas direto no banco de dados. O ticket foi aberto primeiro como STAGING, então pedi para mudar o tipo para HOTFIX. Um subagente alterou o tipo do problema e leu o ticket de volta no sistema para confirmar. O status continuava em preparação, a Fix Version continuava vazia e mais nada no ticket mudou. O limite de 8 palavras para o título na ferramenta de tickets também cortou o título das 10 palavras que estavam no pedido.

A mudança foi para produção. Veja como funciona:

• O relatório earlyMorning do Monitor, que roda às 4:12, faz a busca por meio de uma ação somente leitura, email_badEmailScan. Ele registra {email: [listID, ...]} na linha dbo.monitor daquela execução.
• O job da tarde carrega essa linha da manhã e lê apenas essas listas, pela chave primária. Ele ainda faz todas as remoções, marcações e notificações por conta própria.
• Se um endereço é novo desde as 4h, ou se não existe linha da manhã para a mesma data do relatório, o job da tarde volta à busca antiga, endereço por endereço. Sem a ação da manhã configurada, o comportamento não muda.

A configuração que liga a busca da manhã foi o passo seguinte, depois que o código foi para produção, e outros dois tickets acompanham a verificação das duas execuções. A partir do dia seguinte, o pico da tarde deve sumir.

O que ainda está em aberto

O que consegui medir foram as 39 buscas e o pico de 89% de CPU, e foi isso que tiramos do horário nobre. A causa da lentidão das 14:49 continua em aberto. Se a parada das 14:49 acontecer de novo, um snapshot do que está bloqueando naquele momento resolveria a dúvida.