1초에서 10ms로: API Gateway에서 Prometheus 지연 시간 줄이기

ZhengSong Tu

January 31, 2023

Technology

1~2초 지연 요청

APISIX 커뮤니티에서 사용자들이 신비로운 현상을 보고했습니다: 정상적으로 배포된 APISIX 클러스터에 트래픽 요청이 들어올 때, 소수의 요청이 12초의 비정상적으로 긴 지연을 보이는 것입니다. 사용자의 QPS 규모는 약 10,000이며, 이러한 비정상적인 요청은 드물게 발생하며, 몇 분마다 13회 정도 나타납니다.

사용자들은 이슈에서 고지연 요청의 캡처를 제공했습니다. 이 스크린샷에서 볼 수 있듯이, 실제로 고지연 요청이 있으며, 일부는 초 단위까지 도달할 수 있습니다.

고지연 요청 1.png

고지연 요청 2.png

이와 함께 또 다른 눈에 띄는 현상이 있습니다: 작업자 프로세스 중 하나의 CPU 사용률이 100%에 도달합니다.

100% CPU.png

개발 팀은 이 현상이 발생하는 조건을 파악했습니다:

  1. Prometheus 플러그인이 활성화되어 있고, Prometheus Exporter가 APISIX의 /apisix/prometheus/metrics 엔드포인트에 접근하여 메트릭을 수집합니다.
  2. Prometheus 플러그인이 계산하는 메트릭의 수가 일정 규모에 도달합니다. 일반적으로 수만 개 수준입니다.

이 현상을 업계에서는 **"긴 꼬리 요청(long tail requests)"**이라고 부릅니다. 이는 요청 그룹에서 소수의 요청이 비정상적으로 긴 요청 시간을 가지는 반면 대부분의 요청은 정상적인 응답 시간을 가지는 상황을 의미합니다. 이는 백엔드 시스템의 성능 병목, 리소스 부족 또는 기타 이유로 인해 발생할 수 있습니다. 치명적인 버그는 아니지만, 최종 사용자 경험에 심각한 영향을 미칩니다.

문제 분석

APISIX는 오픈소스 Lua 라이브러리 nginx-lua-prometheus를 기반으로 Prometheus 플러그인을 개발하여 메트릭 추적 및 수집 기능을 제공합니다. Prometheus Exporter가 APISIX가 노출한 Prometheus 지표 엔드포인트에 접근할 때, APISIX는 nginx-lua-prometheus 라이브러리가 제공하는 함수를 호출하여 메트릭 계산 결과를 노출합니다.

개발 팀은 문제를 특정했습니다: nginx-lua-prometheus에서 메트릭 지표를 노출하는 데 사용되는 prometheus:metric_data() 함수입니다.

그러나 이는 단순히 초기 추론일 뿐이며, 긴 꼬리 요청이 이와 관련이 있다는 직접적인 증거가 필요하며, 다음 문제를 명확히 해야 합니다:

  1. 이 함수는 정확히 무엇을 하는가?
  2. 이 함수가 왜 긴 꼬리 요청을 유발하는가?

개발 팀은 문제를 재현하기 위해 로컬 환경을 구축했습니다. 이 환경은 주로 다음 시나리오를 시뮬레이션합니다:

  1. 시뮬레이션된 클라이언트가 APISIX를 통해 업스트림으로 프록시되는 정상 요청을 보냅니다.
  2. Prometheus Exporter가 5초마다 /apisix/prometheus/metrics에 접근하여 APISIX가 prometheus:metric_data() 함수를 호출하도록 합니다.

재현 환경:

재현 환경.png

테스트를 수행할 때, wrk2의 테스트 결과에서 P100 및 기타 지표를 관찰하여 긴 꼬리 요청 현상이 있는지 확인했습니다. 또한 APISIX의 플레임 그래프를 생성하여 긴 꼬리 요청이 발생할 때의 CPU 사용량을 관찰했습니다.

wrk2 테스트 결과:

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
   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

이 테스트 결과에 따르면, 테스트 중 99%의 요청은 14.70밀리초 이내에 완료되었으며, 소수의 요청은 100밀리초 이상 소요되었습니다. 또한 메트릭 수를 변수로 여러 테스트를 수행한 결과, 메트릭 수가 증가함에 따라 P100의 지연 시간도 선형적으로 증가하는 것을 확인했습니다. 메트릭이 100,000 수준에 도달하면 P100은 초 단위에 도달합니다.

결과 플레임 그래프:

플레임 그래프1.png

플레임 그래프의 함수 스택에서 볼 수 있듯이, prometheus:metric_data()가 가장 긴 수평 너비를 차지하며, 이는 많은 CPU 소비를 증명하며, prometheus:metric_data()가 긴 꼬리 요청을 유발한다는 것을 직접적으로 결정합니다.

prometheus:metric_data() 함수가 무엇을 하는지 간단히 분석해 보겠습니다.

prometheus:metric_data()는 공유 메모리에서 메트릭을 가져와 분류하고, Prometheus와 호환되는 텍스트 형식으로 처리합니다. 이 과정에서 모든 메트릭은 사전순으로 정렬되며, 메트릭의 접두사는 정규 표현식으로 처리됩니다. 경험상, 이러한 작업은 매우 비용이 많이 드는 작업입니다.

불완전한 최적화 시도

지연을 유발한 코드를 특정한 후, 다음 단계는 플레임 그래프를 결합하여 코드를 상세히 분석하고 최적화할 여지를 찾는 것입니다.

플레임 그래프에서 fix_histogram_bucket_labels 함수를 특정했습니다. 이 함수를 검토한 결과, string:match와 string:gusb라는 두 가지 민감한 함수를 발견했습니다. 이 두 함수는 LuaJIT에 의해 JIT 컴파일될 수 없으며, 인터프리터로만 실행될 수 있습니다.

LuaJIT는 Lua 프로그래밍 언어를 위한 JIT 컴파일러로, Lua 코드를 기계 코드로 컴파일하여 실행할 수 있습니다. 이는 인터프리터를 사용하여 Lua 코드를 실행하는 것보다 더 높은 성능을 제공할 수 있습니다.

LuaJIT를 사용하여 Lua 코드를 실행하는 장점 중 하나는 코드의 실행 속도를 크게 높일 수 있다는 것입니다. 이를 통해 APISIX는 대량의 요청을 처리할 때 낮은 지연 시간을 유지할 수 있으며, 높은 동시성 환경에서 더 나은 성능을 발휘할 수 있습니다.

따라서 LuaJIT가 컴파일할 수 없는 코드는 잠재적인 성능 병목이 될 수 있습니다.

우리는 위 정보를 정리하여 이슈: 긴 꼬리 요청 현상 최적화를 nginx-lua-prometheus에 제출했고, 이 프로젝트의 저자 Knyar와 연결되어 최적화할 수 있는 공간을 탐색했습니다. Knyar는 신속히 응답했고, 우리는 최적화할 수 있는 부분을 명확히 했습니다. 그래서 PR을 제출했습니다: chore: string match 대신 ngx.re.match 사용하여 성능 개선.

이 PR에서 우리는 주로 다음을 완료했습니다:

  • string:match 대신 ngx.re.match 사용
  • string:gusb를 ngx.re.gsub로 대체

이 최적화를 완료한 후, 우리는 이 최적화가 성능을 개선하는 데 한계가 있으며, 근본적인 문제를 해결할 수 없다는 것을 알았습니다. 근본적인 문제는 다음과 같습니다:

NGINX는 다중 프로세스 단일 스레드 아키텍처입니다. 모든 작업자 프로세스는 TCP(Transmission Control Protocol) 연결을 모니터링하지만, 한 번 연결이 작업자 프로세스에 들어가면 다른 작업자 프로세스로 이전되어 처리될 수 없습니다.

이는 작업자 프로세스가 매우 바쁠 경우, 해당 작업자 프로세스 내의 다른 연결이 제때 처리되지 않을 수 있음을 의미합니다. 반면, 프로세스 내의 단일 스레드 모델은 모든 CPU 집약적 및 IO 집약적 작업이 순차적으로 수행되어야 함을 의미합니다. 작업이 오랜 시간 동안 실행되면 다른 작업이 무시될 수 있으며, 이는 작업 처리 시간의 불균형을 초래할 수 있습니다.

prometheus:metric_data()는 계산을 위해 많은 CPU 시간 조각을 차지하며, 정상 요청을 처리하기 위한 CPU 리소스를 압박합니다. 이것이 작업자 프로세스의 CPU 사용률이 100%에 도달하는 이유입니다.

이 문제를 기반으로, 우리는 위 최적화를 완료한 후 계속 분석을 진행했고, 플레임 그래프를 캡처했습니다:

플레임 그래프2.png

위 플레임 그래프에서 builtin#100은 luajit/lua 라이브러리 함수(예: string.find)를 나타냅니다. 이는 https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua를 통해 해당 함수 이름을 얻을 수 있습니다.

사용 방법:

$ luajit ljff.lua 100
FastFunc table.sort

메트릭 계산이 과도한 CPU를 차지하기 때문에, 우리는 메트릭을 계산할 때 CPU 시간 조각을 포기하는 것을 고려했습니다.

APISIX의 경우, 정상 요청을 처리하는 우선순위가 가장 높으며, CPU 리소스는 이에 기울어져야 합니다. 동시에, prometheus:metric_data()는 Prometheus Exporter 메트릭을 얻는 효율성에만 영향을 미칩니다.

OpenResty 세계에는 CPU 시간 조각을 양보하는 숨겨진 방법이 있습니다: ngx.sleep(0). 우리는 이 방법을 prometheus:metric_data()에 도입했습니다. 메트릭을 처리할 때, 일정 수의 메트릭(예: 200개)을 처리한 후 CPU 시간 조각을 포기하여 새로운 요청이 처리될 기회를 갖도록 합니다.

우리는 이 최적화를 위한 PR을 제출했습니다: feat: 성능 최적화.

우리의 테스트 시나리오에서, 총 메트릭 수가 100,000 수준에 도달할 때, 이 최적화를 도입하기 전에 wrk2로 테스트한 결과:

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 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

최적화 후 wrk2 결과:

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 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

P100 지표는 최적화 전의 약 1/3에서 1/2 수준입니다.

그러나 이는 이 문제를 완벽하게 해결하지 못합니다. 최적화된 플레임 그래프를 분석하면:

최적화 후 플레임 그래프.png

builtin#100 (table.sort)와 builtin#92 (string.format)이 여전히 상당한 수평 너비를 차지하고 있음을 볼 수 있습니다. 이는:

  1. prometheus:metric_data()는 먼저 table.sort를 호출하여 모든 메트릭을 정렬합니다. 메트릭이 100,000 수준에 도달하면, 이는 100,000개의 문자열을 정렬하는 것과 같으며, table.sort는 ngx.sleep(0)에 의해 중단될 수 없습니다.
  2. string.format과 fix_histogram_bucket_labels가 사용되는 부분은 최적화할 수 없습니다. knyar와의 소통을 통해, 이러한 단계는 prometheus:metric_data()가 올바른 형식의 메트릭을 생성할 수 있도록 하는 데 필수적임을 알았습니다.

지금까지 코드 수준의 최적화 방법은 모두 소진되었지만, 아쉽게도 문제는 여전히 완벽하게 해결되지 않았습니다. P100의 메트릭에서 여전히 눈에 띄는 지연이 존재합니다.

어떻게 해야 할까?

핵심 문제로 돌아가 봅시다: prometheus:metric_data()는 계산을 위해 많은 CPU 시간 조각을 차지하며, 정상 요청을 처리하기 위한 CPU 리소스를 압박합니다.

Linux 시스템에서, CPU가 할당하는 시간 조각은 스레드 또는 프로세스인가? 정확히 말하면, 스레드이며, 스레드는 실제 작업 단위입니다. 그러나 NGINX는 다중 프로세스 단일 스레드 아키텍처로, 각 프로세스에는 하나의 스레드만 있습니다.

이 시점에서 우리는 최적화 방향을 생각했습니다: prometheus:metric_data()를 다른 스레드(또는 더 정확히는 프로세스)로 이동시키는 것입니다. 그래서 우리는 두 가지 방향을 조사했습니다:

  1. ngx.run_worker_thread를 사용하여 prometheus:metric_data() 계산 작업을 실행합니다. 이는 CPU 집약적 작업을 스레드 풀에 넘기는 것과 같습니다.
  2. 별도의 프로세스를 사용하여 prometheus:metric_data()의 계산 작업을 처리합니다. 이 프로세스는 정상 요청을 처리하지 않습니다.

PoC(proof of concept)를 수행한 후, 우리는 옵션 1을 거부하고 옵션 2를 채택했습니다. 옵션 1은 ngx.run_worker_thread가 요청과 무관한 계산 작업을 실행하는 데만 적합하기 때문에 거부되었습니다. 반면 prometheus:metric_data()는 요청과 관련이 있습니다.

옵션 2의 구현: privileged agent(특권 프로세스)가 prometheus:metric_data()를 처리하도록 합니다. 그러나 특권 프로세스는 어떤 포트도 리스닝하지 않으며 어떤 요청도 처리하지 않습니다. 따라서 우리는 특권 프로세스를 수정하여 포트를 리스닝할 수 있도록 해야 합니다.

결국, 우리는 feat: allow privileged agent to listen port와 feat(prometheus): support collect metrics works in the privileged agent를 사용하여 옵션 2를 구현했습니다.

이 최적화를 적용한 APISIX를 테스트한 결과, P100 지표의 지연 시간이 합리적인 범위로 감소했으며, 긴 꼬리 요청 문제는 더 이상 존재하지 않았습니다.

  Latency Distribution (HdrHistogram - Uncorrected Latency (measured without taking delayed starts into account))
 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

이것은 섬세한 솔루션이며, 핵심 문제를 해결했습니다. 우리는 이 솔루션을 프로덕션 환경에서 관찰하고 검증했습니다. 이는 긴 꼬리 요청 현상을 제거했으며, 추가적인 예외를 발생시키지 않았습니다.

요약

이 문제를 해결할 때, 새로운 생각이 떠올랐습니다: 오픈소스 라이브러리 nginx-lua-prometheus가 APISIX에 적합한가?

우리는 APISIX 측에서 prometheus:metric_data() 문제를 해결했습니다. 동시에, 우리는 nginx-lua-prometheus의 다른 문제도 발견하고 수정했습니다. 예를 들어 메모리 누수 수정과 LRU 캐시 제거입니다.

nginx-lua-prometheus는 원래 NGINX를 위해 설계되었으며, OpenResty 및 OpenResty 기반 애플리케이션을 위해 설계되지 않았습니다. 그러나 OpenResty 생태계에서 Prometheus 생태계에 연결하는 더 성숙한 오픈소스 프로젝트는 nginx-lua-prometheus보다 없습니다. 따라서 nginx-lua-prometheus는 OpenResty 생태계를 위해 오픈소스 커뮤니티에 의해 지속적으로 추진되어 왔습니다.

아마도 우리는 더 탐구하고, APISIX의 소스 코드를 수정하지 않고도 Prometheus 생태계에 연결할 방법을 찾아야 할 것입니다. 예를 들어, APISIX에 더 적합한 종속 라이브러리를 설계하거나, Prometheus 생태계의 성숙한 프로젝트에 연결하여 메트릭 수집 및 계산 프로세스를 해당 프로젝트로 이동시키는 방법을 찾아야 할 것입니다.

Tags:
Plugin
Prometheus
APISIX Basics