1s para 10ms: Reduzindo o Atraso do Prometheus no API Gateway

Solicitações com Atrasos de 1 a 2 Segundos

Na comunidade APISIX, os usuários relataram um fenômeno misterioso: quando as solicitações de tráfego entram em um cluster APISIX normalmente implantado, um pequeno número de solicitações tem um atraso excepcionalmente longo de 1 a 2 segundos. A escala de QPS do usuário é de cerca de 10.000, e esse tipo de solicitação anormal é rara, aparecendo apenas 1 a 3 vezes a cada poucos minutos.

Os usuários forneceram capturas de solicitações de alta latência em issues. Pode-se ver nessas capturas de tela que há realmente solicitações com alta latência, algumas podem até atingir o nível de segundos.

Outro fenômeno perceptível acompanha isso: o uso da CPU de um dos processos worker atinge 100%.

A equipe de desenvolvimento aprendeu as condições para que esse fenômeno ocorra:

1. O plugin Prometheus está habilitado, e o Prometheus Exporter acessa o endpoint /apisix/prometheus/metrics do APISIX para coletar métricas.
2. O número de métricas que o plugin Prometheus conta atinge uma certa escala, geralmente dezenas de milhares.

Esse fenômeno é chamado de "solicitações de cauda longa" na indústria. Refere-se à situação em que uma pequena porcentagem de solicitações tem um tempo de solicitação anormalmente longo, enquanto a maioria das solicitações tem um tempo de resposta normal em um grupo de solicitações. Pode ser devido a um gargalo de desempenho no sistema de backend, recursos insuficientes ou outras razões. Não é um bug fatal, mas afeta seriamente a experiência do usuário final.

Analisando o Problema

Com base em uma biblioteca Lua de código aberto nginx-lua-prometheus, o APISIX desenvolveu um plugin Prometheus que fornece a função de rastrear e coletar métricas. Quando o Prometheus Exporter acessa o endpoint de indicadores Prometheus expostos pelo APISIX, o APISIX chamará a função fornecida pela biblioteca nginx-lua-prometheus para expor os resultados do cálculo das métricas.

A equipe de desenvolvimento localizou o problema: a função prometheus:metric_data() usada para expor indicadores de métricas em nginx-lua-prometheus.

No entanto, isso é apenas uma inferência preliminar, e evidências diretas são necessárias para provar que as solicitações de cauda longa estão relacionadas a isso, e as seguintes questões precisam ser esclarecidas:

1. O que exatamente essa função faz?
2. Por que essa função causa solicitações de cauda longa?

A equipe de desenvolvimento construiu um ambiente local para reproduzir o problema, que simula principalmente os seguintes cenários:

1. O cliente simulado envia uma solicitação normal que é encaminhada para o upstream pelo APISIX.
2. Simula que o Prometheus Exporter acessa /apisix/prometheus/metrics a cada 5 segundos, acionando o APISIX a chamar a função prometheus:metric_data().

Ambiente Reproduzido:

Ao realizar o teste, observamos P100 e outros indicadores nos resultados do teste do wrk2 para confirmar se há um fenômeno de solicitação de cauda longa. Geramos um gráfico de chamas do APISIX para observar o uso da CPU quando ocorre uma solicitação de cauda longa.

Resultados do teste do wrk2:

  Distribuição de Latência (HdrHistogram - Latência Não Corrigida (medida sem considerar atrasos iniciais))
   50.000%    1.13ms
   75.000%    2.56ms
   90.000%    4.82ms
   99.000%   14.70ms
   99.900%   27.95ms
   99.990%   74.75ms
   99.999%  102.78ms
  100.000%  102.78ms

De acordo com esse resultado de teste, pode-se concluir que, durante o teste, 99% das solicitações foram concluídas em 14,70 milissegundos, e um pequeno número de solicitações levou mais de 100 milissegundos. E usamos o número de métricas como uma variável para realizar vários testes, e descobrimos que o número de métricas aumentou linearmente com o atraso do P100. Se as métricas atingirem o nível de 100.000, o P100 atingirá o nível de segundos.

O gráfico de chamas resultante:

Como visto na pilha de funções do gráfico de chamas, prometheus:metric_data() ocupa a maior largura horizontal, provando um grande consumo de CPU, e determina diretamente que prometheus:metric_data() causa solicitações de cauda longa.

Vamos analisar brevemente o que a função prometheus:metric_data() faz.

prometheus:metric_data() buscará métricas da memória compartilhada, as categorizará e as processará em um formato de texto compatível com o Prometheus. Nesse processo, todas as métricas serão classificadas em ordem lexicográfica, e o prefixo das métricas será processado com expressões regulares. Como regra geral, essas são operações muito caras.

Uma Tentativa de Otimização Imperfeita

Uma vez que localizamos o código que causou o atraso, o próximo passo é combinar o gráfico de chamas para analisar o código em detalhes e encontrar espaço para otimização.

A partir do gráfico de chamas, localizamos a função fix_histogram_bucket_labels. Ao revisar essa função, encontramos duas funções sensíveis: string:match e string:gusb. Nenhuma dessas duas funções pode ser compilada JIT pelo LuaJIT. Elas só podem ser interpretadas e executadas.

LuaJIT é um compilador JIT para a linguagem de programação Lua, que pode compilar código Lua em código de máquina e executá-lo. Isso pode fornecer um desempenho maior do que usar um interpretador para executar código Lua.

Uma das vantagens de usar LuaJIT para executar código Lua é que ele pode aumentar muito a velocidade de execução do código. Isso permite que o APISIX mantenha baixa latência ao processar um grande número de solicitações e tenha um desempenho melhor em um ambiente de alta concorrência.

Portanto, o código que o LuaJIT não pode compilar se tornará um gargalo de desempenho potencial.

Compilamos as informações acima e enviamos issue: otimizar o fenômeno de solicitação de cauda longa para o nginx-lua-prometheus, onde nos conectamos com o autor Knyar deste projeto e exploramos o espaço que poderia ser otimizado. Knyar respondeu prontamente, e esclarecemos os lugares que poderiam ser otimizados. Então, um PR foi enviado: chore: use ngx.re.match em vez de string match para melhorar o desempenho para otimização.

Neste PR, principalmente concluímos:

• Usar ngx.re.match em vez de string:match
• Substituir string:gusb por ngx.re.gsub

Após concluir essa otimização, sabemos que o desempenho que ela melhora é limitado, não pode resolver o problema fundamentalmente. O problema raiz é:

O NGINX é uma arquitetura de multiprocessos de thread único. Todos os processos worker monitorarão conexões TCP (Protocolo de Controle de Transmissão), mas uma vez que uma conexão entra em um processo worker, ela não pode ser migrada para outros processos worker para processamento.

Isso significa que, se um processo worker estiver muito ocupado, outras conexões dentro desse processo worker podem não ser processadas a tempo. Por outro lado, o modelo de thread único dentro de um processo significa que todas as tarefas intensivas em CPU e IO devem ser executadas sequencialmente. Se uma tarefa demorar muito tempo para ser executada, outras tarefas podem ser ignoradas, resultando em tempos de processamento de tarefas desiguais.

prometheus:metric_data() ocupa uma grande quantidade de fatias de tempo da CPU para cálculo, espremendo os recursos da CPU para processar solicitações normais. É por isso que você vê um processo worker com 100% de uso da CPU.

Com base nesse problema, continuamos a analisar após concluir a otimização acima e capturamos o gráfico de chamas:

O gráfico de chamas acima builtin#100 representa funções da biblioteca luajit/lua (como string.find), que podem ser acessadas através de https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua neste projeto para obter o nome da função correspondente.

Como usar:

$ luajit ljff.lua 100
FastFunc table.sort

Como o cálculo das métricas ocupa uma quantidade excessiva de fatias de tempo da CPU, consideramos desistir das fatias de tempo da CPU ao calcular as métricas.

Para o APISIX, a prioridade de processar solicitações normais é a mais alta, e os recursos da CPU devem ser inclinados para isso. Ao mesmo tempo, prometheus:metric_data() só afetará a eficiência de obter métricas do Prometheus Exporter.

No mundo OpenResty, há uma maneira oculta de ceder fatias de tempo da CPU: ngx.sleep(0). Introduzimos esse método em prometheus:metric_data(). Ao processar métricas, desistiremos das fatias de tempo da CPU após processar um certo número de métricas (como 200 métricas) para que novas solicitações recebidas tenham a chance de serem processadas.

Enviamos um PR para essa otimização: feat: otimização de desempenho.

Em nosso cenário de teste, quando o número total de métricas atinge o nível de 100.000, os resultados obtidos ao testar com wrk2 antes de introduzir essa otimização:

  Distribuição de Latência (HdrHistogram - Latência Não Corrigida (medida sem considerar atrasos iniciais))
 50.000%   10.21ms
 75.000%   12.03ms
 90.000%   13.25ms
 99.000%   92.80ms
 99.900%  926.72ms
 99.990%  932.86ms
 99.999%  934.40ms
100.000%  934.91ms

Resultados do wrk2 após a otimização:

  Distribuição de Latência (HdrHistogram - Latência Não Corrigida (medida sem considerar atrasos iniciais))
 50.000%    4.34ms
 75.000%   12.81ms
 90.000%   16.12ms
 99.000%   82.75ms
 99.900%  246.91ms
 99.990%  349.44ms
 99.999%  390.40ms
100.000%  397.31ms

O índice P100 é cerca de 1/3 a 1/2 do que era antes da otimização.

No entanto, isso não resolve esse problema perfeitamente. Ao analisar o gráfico de chamas otimizado:

Você pode ver que builtin#100 (table.sort) e builtin#92 (string.format) ainda ocupam uma largura considerável do eixo horizontal porque:

1. prometheus:metric_data() primeiro chamará table.sort para classificar todas as métricas. Quando as métricas atingem o nível de 100.000, é equivalente a classificar 100.000 strings, e table.sort não pode ser interrompido por ngx.sleep(0).
2. O local onde string.format e fix_histogram_bucket_labels são usados não pode ser otimizado. Após conversar com knyar, aprendi que essas etapas são necessárias para garantir que prometheus:metric_data() possa produzir métricas no formato correto.

Até agora, os métodos de otimização no nível de código foram esgotados, mas infelizmente, o problema ainda não foi resolvido perfeitamente. Ainda há um atraso perceptível nos índices P100.

O Que Fazer?

Vamos voltar ao problema central: prometheus:metric_data() ocupa uma grande quantidade de fatias de tempo da CPU para cálculo, espremendo os recursos da CPU para processar solicitações normais.

No sistema Linux, as fatias de tempo que a CPU está alocando são para um thread ou um processo? Para ser preciso, é para um thread, e o thread é a unidade real de trabalho. No entanto, o NGINX é uma arquitetura de multiprocessos de thread único, com apenas um thread em cada processo.

Nesse ponto, pensamos em uma direção de otimização: mover prometheus:metric_data() para outros threads (ou, mais precisamente, processos). Então investigamos duas direções:

1. Usar ngx.run_worker_thread para executar tarefas de cálculo de prometheus:metric_data(), equivalente a entregar tarefas intensivas em CPU para o pool de threads.
2. Usar um processo separado para lidar com as tarefas de cálculo de prometheus:metric_data(), esse processo não lidará com solicitações normais.

Após um PoC (prova de conceito), rejeitamos a opção 1 e adotamos a opção 2. A opção 1 é rejeitada porque ngx.run_worker_thread só é adequado para executar tarefas de cálculo independentes de solicitações, enquanto prometheus:metric_data() está relacionado a solicitações.

Implementação da opção 2: Fazer com que o privileged agent (processo privilegiado) lide com prometheus:metric_data(). Mas o processo privilegiado não escuta nenhuma porta ou lida com qualquer solicitação. Portanto, precisamos modificar o processo privilegiado para que ele possa escutar a porta.

Finalmente, usamos feat: permitir que o agente privilegiado escute a porta e feat(prometheus): suportar a coleta de métricas no agente privilegiado para implementar a opção 2.

Usamos o APISIX com essa otimização para testar e descobrimos que o atraso do índice P100 foi reduzido para um intervalo razoável, e o problema de solicitações de cauda longa não existe mais.

  Distribuição de Latência (HdrHistogram - Latência Não Corrigida (medida sem considerar atrasos iniciais))
 50.000%    3.74ms
 75.000%    4.66ms
 90.000%    5.77ms
 99.000%    9.99ms
 99.900%   13.41ms
 99.990%   16.77ms
 99.999%   18.38ms
100.000%   18.40ms

Essa é uma solução delicada e resolve o problema central. Observamos e verificamos essa solução no ambiente de produção. Ela eliminou o fenômeno de solicitação de cauda longa e não causou exceções adicionais.

Resumo

Quando estávamos corrigindo esse problema, surgiu um novo pensamento: a biblioteca de código aberto nginx-lua-prometheus é adequada para o APISIX?

Resolvemos o problema de prometheus:metric_data() no lado do APISIX. Ao mesmo tempo, também encontramos outros problemas no nginx-lua-prometheus e os corrigimos. Como corrigir vazamento de memória e eliminação de cache LRU.

O nginx-lua-prometheus foi originalmente projetado para o NGINX, não para o OpenResty e aplicativos baseados no OpenResty. No entanto, nenhum projeto de código aberto no ecossistema OpenResty se conecta ao ecossistema Prometheus de forma mais madura do que o nginx-lua-prometheus. Portanto, o nginx-lua-prometheus tem sido constantemente promovido pela comunidade de código aberto para o ecossistema OpenResty.

Talvez devêssemos explorar mais e encontrar uma maneira de nos conectar ao ecossistema Prometheus sem modificar o código-fonte do APISIX. Por exemplo, projetar uma biblioteca de dependência mais adequada para o APISIX, ou conectar-se a projetos maduros no ecossistema Prometheus de alguma forma, e mover o processo de coleta e cálculo de métricas para esses projetos maduros.