A Cauda É Uma Requisição Travada

Em 4 de setembro o serviço de notificações entregou a primeira notificação push de produção sem o AWS SNS no caminho. Vinte e um tipos de notificação, a nossa própria query de fan-out, uma requisição HTTP por dispositivo para o Firebase, com limite de concorrência 32.

O ADR havia modelado quanto isso custaria. Mantive os números modelados no documento em vez de corrigi-los para fora, porque o conteúdo interessante é o tamanho e a direção do erro.

As duas direções estão erradas. O volume foi três vezes maior que o esperado e o custo por dispositivo foi mais barato do que o modelo implicava, o que por acaso se cancela num sistema que funciona bem e num modelo que não estava prevendo nada.

De onde veio o 308

O 308 não era um chute. Era o maior fan-out observado em 499 comparações atribuídas em produção durante a sombra, e a decisão de fazer o cutover foi autorizada em parte por ele.

A sombra estava fazendo o trabalho dela corretamente. Ela provou que a query de destinatários estava certa: cada ausência encontrada era atribuível a uma inscrição obsoleta ou a uma preferência desligada, e as ausências inexplicadas ficaram em zero. O que ela não podia fazer era garantir que a amostra dela incluísse uma partida grande, e não incluiu.

Então a lição é mais estreita que "a sombra estava errada" e mais útil. Um veredito limpo de sombra diz que a query está certa. Não diz nada sobre o volume, porque o volume depende de quais partidas por acaso rodaram durante a janela. São perguntas separadas e eu vinha tratando uma resposta como se cobrisse as duas.

Sem multicast, em nenhuma das plataformas

Uma revisão anterior do ADR afirmava que o FCM oferecia um endpoint multicast aceitando 500 tokens por requisição, e contrastava isso favoravelmente com o APNs não ter nenhum. Era simplesmente falso. O endpoint de envio em lote do FCM foi descontinuado e parou de funcionar depois de 21 de junho de 2024. O HTTP v1 aceita exatamente um token de dispositivo por requisição, e o helper de multicast do Admin SDK dispara uma requisição HTTP por token do lado do cliente.

Nenhuma das plataformas tem multicast. Um fan-out de 2.400 dispositivos são cerca de 2.400 requisições HTTP de qualquer jeito, e o que governa a cauda não é lote e sim concorrência HTTP/2 limitada. É por isso que internal/fcm nasceu com um limite de concorrência configurável no primeiro commit em vez de adquirir um depois, sob pressão.

Os fan-outs reais

Maiores primeiro, do primeiro dia em produção:

GOAL          1005 destinatários   985 entregues   20 mortos   2999 ms   envio mais lento  372 ms   2,98 ms/disp
GOAL          1002                 982             20          2947 ms                     548 ms   2,94 ms/disp
VAR            853                 838             15          3602 ms                    1747 ms   4,22 ms/disp
CORNER         409                 395             14          1317 ms                     320 ms   3,22 ms/disp
CORNER         289                 283              6          1012 ms                     208 ms   3,50 ms/disp

Mil dispositivos em cerca de três segundos. O orçamento de produto para uma notificação de gol é de segundos, e este serviço já atrasa correções deliberadamente por cinco segundos inteiros no caminho de deduplicação, então um atraso intencional no nosso próprio código é maior que o fan-out completo. Latência nunca ia decidir esta arquitetura e agora não decide por uma razão medida em vez de estimada.

Os dois mais lentos não foram os maiores

Aí isto, que é a descoberta de fato:

GOAL  1018 destinatários   997 entregues   retried=5   duração=18074 ms   envio mais lento 15371 ms
GOAL  1016                 995             retried=4   duração=17563 ms                    15360 ms
GOAL  1023                                             duração= 2927 ms   ← mesmo tamanho, 6x mais rápido

Três fan-outs de tamanho essencialmente idêntico. Um levou 2,9 segundos e dois levaram 18.

A causa está na coluna de envio mais lento. Um punhado de requisições individuais ao FCM travou por cerca de 15 segundos cada, e com limite de concorrência 32 uma requisição travada segura um slot, então o fan-out inteiro espera pelo worker mais lento. Dá 17,75 milissegundos por dispositivo contra 2,86 normais.

Nada foi perdido. Os retries recuperaram todos os nove envios afetados, e a contagem de falhas transientes ficou em zero. O custo foi puramente latência.

Dois detalhes valem destacar. O backoff de retry de 250 milissegundos é irrelevante nessa escala: o que custa 15 segundos é a primeira tentativa, não a espera antes da segunda. E http.Client{Timeout: 30 * time.Second} significa que uma trava de 15 segundos cabe confortavelmente dentro do orçamento e nunca é cortada, o que é funcionar como configurado e não um bug.

Quão raro é, e por que deixei como estava

Medido ao longo de um dia mais completo: uma vez.

Em 101.471 destinatários os contadores ainda leem retried = 9 e slowest_send_ms = 15371. Idênticos aos valores registrados em 15.887 destinatários. As duas travas pertencem a um único episódio do Firebase em torno de 17:20 UTC e nada chegou perto desde então. A duração média de fan-out é 227 milissegundos.

Então isto entra no registro como observação e não como recomendação, e o raciocínio é uma troca que quero poder apontar depois.

Limitar uma requisição em algo próximo de cinco segundos teria limitado aqueles dois fan-outs a cerca de 5,5 segundos em vez de 18. A máquina de retry para absorver as requisições cortadas existe e está provada, porque acabou de absorver nove. Isso é uma melhoria real num número real.

Contra isso: um episódio em 101.471 envios. E um timeout mais apertado transforma envios lentos-mas-bem-sucedidos em retries, o que dobra a contagem de requisições exatamente nos dias em que o Firebase já está sofrendo. Dois fan-outs chegando quinze segundos atrasados é um resultado pior que nada, e melhor que dobrar sistematicamente a nossa carga sempre que o provedor degrada.

O que mudaria a resposta está escrito ao lado da decisão: retried subindo de forma constante em vez de num único agrupamento, ou slowest_send_ms alcançando 15 segundos regularmente em vez de uma vez. Os dois já estão na saída do script de soak e no log de entrega, então o gatilho não precisa de instrumentação nova. Até esse padrão aparecer, ficam os 30 segundos.

Qualidade de entrega

Primeiros 101.471 destinatários:

101.471 destinatários · 99.175 entregues (97,74%) · 2.296 falhas
2.296 token_dead · 0 token_invalid · 0 transient · 0 credential · 9 retried
duração média de fan-out 227 ms

Cada falha, sem exceção, é device token is no longer registered, um HTTP 404 do Firebase, que significa que o app foi desinstalado. Nenhum erro de credencial, que para um primeiro dia num caminho de entrega novo era o número que mais me deixava nervoso.

O que eu quero sublinhar é que o SNS estava descartando essas mesmas notificações, para esses mesmos dispositivos mortos, todo esse tempo. Ele reportava sucesso, porque da perspectiva dele a publicação teve sucesso e a falha por endpoint ia para um log de feedback que alimentava um job de poda. A mudança não é que começamos a falhar. É que as falhas agora são contadas onde o envio acontece, numa linha que diz quantos de quantos.

Contar um retry sem contar o destinatário duas vezes

O design de retry tem uma propriedade que se pagou imediatamente.

Uma falha transiente é retentada uma vez após 250 milissegundos. Tokens mortos, tokens inválidos e falhas de credencial não são retentados, porque retentar não pode dar certo. Um destinatário retentado produz exatamente um resultado, então entregues + falhas continua igual à contagem de destinatários, e a contagem de retries é reportada em campo próprio.

Essa separação é o motivo pelo qual as nove travas foram visíveis. Um fan-out todo entregue com contagem de retry subindo é o Firebase degradando enquanto a linha de saúde lê perfeitamente limpa. Se o retry tivesse sido dobrado dentro das contagens de resultado, aqueles nove apareceriam como nove sucessos e nada mais, e o único sintoma seria uma duração que ninguém estava olhando.

Uma ressalva para ler qualquer um desses números

A mesma consulta de 24 horas, rodada duas vezes com 88 segundos de diferença e sem mudança de tráfego, reportou 2.730 destinatários e depois 6.453.

O atraso de ingestão do CloudWatch Logs significa que uma consulta cobrindo uma janela que inclui o passado recente subconta, às vezes por mais da metade. Qualquer leitura tirada perto dos eventos é um limite inferior, não uma medição. Já caí nessa duas vezes, uma em cada direção, e a única defesa que encontrei é rodar a consulta de novo mais tarde e comparar em vez de confiar numa leitura única.

O que eu levei disso

Um modelo mantido ao lado da medição vale mais que um modelo corrigido em silêncio. As duas direções do meu erro estão visíveis agora, e o tamanho do desvio é o que diz à próxima pessoa quanto confiar na próxima estimativa.

Um veredito limpo de um harness de comparação cobre a lógica que ele comparou. Volume, distribuição e comportamento de cauda são propriedades separadas, e uma amostra que nunca conteve um caso grande não amostrou isso.

Quando você encontra um outlier dramático, meça com que frequência ele se repete antes de mudar qualquer coisa. Meu instinto foi apertar o timeout, e a contagem honesta montou o argumento contra.

E conte retries separadamente dos resultados. Um retry que desaparece dentro de um sucesso é um provedor degradando de forma invisível.

---

Parte de Removendo um Gargalo, sobre o incidente de throttling no SNS Subscribe e a migração para entrega direta via FCM.