Zettelkasten

New Relic 파이썬 에이전트의 패키지 목록 수집이 gevent 허브를 harvest마다 최대 2초 막는다

·수정 2회
geventnew-relicpythonblockingobservability

요약

  • New Relic 파이썬 에이전트는 60초마다 도는 harvest에서 설치된 패키지 목록을 모으는데, 이때 importlib.metadata.packages_distributions()가 venv 전체의 METADATA 파일을 읽는다. 파일 읽기는 gevent가 논블로킹으로 못 바꾸므로 허브가 통째로 멈춘다.
  • harvest 한 번당 최대 2초 예산이라 1초 임계로 감지하면 워커마다 분당 한 건씩 잡힌다. sys.modules 스냅샷을 다 소진하면 끝나며, 관측상 워커 4개 환경에서 기동 후 약 17분 걸렸다.
  • NEW_RELIC_PACKAGE_REPORTING_ENABLED=false로 harvest 경로는 끌 수 있다. 다만 계측 훅이 모듈을 처음 임포트할 때 하는 버전 조회는 남으므로 완전히 없어지지는 않는다.

본문

증상 (관측됨)

gunicorn gevent 워커로 도는 Django 앱에서 허브 블로킹을 계측했더니, 요청과 무관한 블로킹이 분당 4~6건씩 꾸준히 잡혔다. 워커 4개였으니 워커당 분당 1.25건이다. 잡힌 스택은 전부 패키지 메타데이터를 읽는 경로였다.

contextlib.py:446:__exit__
  < importlib_metadata:948:read_text
  < importlib_metadata:491:metadata
  < importlib/metadata/__init__.py:1076:packages_distributions

pathlib.py:1044:open < pathlib.py:1058:read_text
  < importlib_metadata:955:read_text
  < importlib/metadata/__init__.py:1081:_top_level_declared

트랜잭션 이름이 붙지 않았고 스택 어디에도 애플리케이션 프레임이 없었다. 요청 처리 중이 아니라는 뜻이다.

원인 (에이전트 소스로 확인, newrelic 10.16.0)

# newrelic/core/agent.py         60초마다 harvest
self._scheduler.enter(60.0, 2, self._harvest_default, ())

# newrelic/core/application.py   harvest 안에서 2초 예산만큼 제너레이터를 소비
while (configuration
       and configuration.package_reporting.enabled
       and self._remaining_plugins
       and ((time.time() - stopwatch_start) < MAX_PACKAGE_CAPTURE_TIME_PER_SLOW_HARVEST)):
    module_info = next(self.plugins)

# newrelic/core/environment.py   sys.modules 스냅샷을 돌며 버전을 조회
for name, module in sys.modules.copy().items():
    version = get_package_version(name)

# newrelic/common/package_version_utils.py
distributions = importlib_metadata.packages_distributions()

packages_distributions()는 설치된 모든 배포판을 훑어 top-level 모듈 이름 → 배포판 이름 매핑을 만든다. 배포판마다 METADATA 파일을 읽고 email 파서로 파싱하므로, 의존성이 많은 환경에서는 한 번 호출에 초 단위가 든다.

같은 스캔을 수십 번 반복한다

_get_package_version(name)에는 @lru_cache()가 붙어 있지만, 그 안에서 부르는 packages_distributions()에는 캐시가 없다. 그래서 캐시 미스가 난 모듈 이름마다 venv 전체를 다시 훑는다. 낭비의 실체는 "스캔을 한다"가 아니라 "같은 스캔을 N번 반복한다"다.

배포판 242개 환경에서 재보면 이렇다. 실제 프로세스는 이름 수백 개를 조회하므로 격차는 더 벌어진다.

스캔 1회                        184ms
이름 25개 조회 (캐시 없음)   스캔 23회 / 1,625ms   ← 전체 시간의 100%가 스캔
이름 25개 조회 (캐시 씌움)   스캔  1회 /   181ms

에이전트 최신 13.4.0에도 같은 코드라 업그레이드로는 안 풀린다. upstream에 이슈로 올려뒀다.

왜 gevent에서 특히 문제인가

monkey.patch_all()은 소켓·시간·스레드는 바꾸지만 파일 I/O는 그대로 둔다. 파일을 읽는 동안 허브로 제어권이 넘어가지 않으므로 그 워커의 모든 greenlet이 멈춘다. 같은 코드가 스레드 기반 워커에서는 한 스레드만 느려지고 끝난다. gevent에서만 전면 정지가 된다.

언제 끝나나

self.plugins와 _remaining_plugins는 Application 객체의 __init__에서만 설정된다. 세션이 재연결돼도 초기화되지 않으므로, StopIteration이 나면 그 프로세스에서는 다시 돌지 않는다. 대상 목록도 제너레이터 첫 호출 때 뜬 sys.modules.copy() 스냅샷이라 런타임에 늘지 않는다.

즉 상시 부하가 아니라 기동 후 일회성이다. 다만 프로세스 단위라 배포·스케일아웃으로 새 프로세스가 뜰 때마다 워커별로 처음부터 반복한다.

문서와 구현이 다르다

공식 문서는 "captures package and version information on startup"이라고 쓰지만, 구현은 startup에 한 번에 끝내지 않고 harvest마다 2초씩 나눠 처리한다. 그래서 기동 직후가 아니라 그 뒤 십수 분 동안 이어진다.

대응

  1. 끄기 — NEW_RELIC_PACKAGE_REPORTING_ENABLED=false. 잃는 것은 APM Environment 탭의 패키지 목록뿐이고 트랜잭션·에러·메트릭에는 영향이 없다. 단, 진입점이 두 개라 절반만 막는다. 이 설정은 harvest의 plugins 루프만 끈다. 계측 훅이 모듈을 처음 임포트할 때 하는 버전 조회는 그대로 남고, 그것도 같은 스캔을 부른다.
  2. 캐시 씌우기 — packages_distributions를 lru_cache(1)로 감싸면 N번 스캔이 1번이 된다. 컨테이너 안에서 패키지 목록은 안 바뀌므로 안전하다. 진입점 두 개를 모두 덮으므로 이쪽이 낫다. 에이전트 코드는 모듈 속성을 호출 시점에 조회하므로 속성 교체만으로 적용된다. 다만 stdlib 몽키패치라 프로세스 전역에 영향을 주고, 반환 매핑을 수정하는 호출자가 있으면 오염된다(에이전트는 읽기만 한다).
  3. 그냥 두기 — 어차피 끝난다. 배포가 잦지 않으면 우선순위가 낮다.

계측할 때 걸린 함정

gevent 모니터 스레드로 허브 블로킹을 감지할 때, 기본 monitor_blocking은 감지할 때마다 gc.get_objects()로 전체 힙을 훑어 greenlet 트리를 덤프한다. 진단하려다 더 큰 정지를 만들기 때문에 프로덕션에서는 쓰면 안 된다. 허브 스레드의 프레임만 찍는 구현으로 갈아끼우는 편이 낫다.

그리고 가장 안쪽 프레임만 기록하면 원인을 못 짚는다. 여기서도 pathlib.py:1013:stat만 보였다. 라이브러리 프레임을 건너뛴 첫 애플리케이션 프레임과 상위 몇 프레임을 함께 담아야 호출자를 알 수 있다. 이 경우엔 스택 전체가 stdlib과 site-packages라 애플리케이션 프레임이 아예 없다는 사실 자체가 "요청 처리가 아니다"라는 단서가 됐다.

또 gevent가 이벤트에 실어주는 blocking_time은 실제로 막힌 시간이 아니라 설정한 임계값 그대로다. 지속 시간은 알 수 없고 발생 횟수로만 봐야 한다.

검증 상태

  • 관측: 발생 빈도, 지속 시간, 스택 내용 — 직접 계측해 확인
  • 소스 확인: 위 코드 경로 네 곳, package_reporting.enabled 설정 (upstream 저장소와 공식 문서 양쪽)
  • 스택에 newrelic/ 프레임이 직접 찍히지는 않았다. 계측이 안쪽 4프레임만 담았고 caller는 site-packages를 건너뛰도록 만들어서, 에이전트 프레임이 구조적으로 안 보였다.
  • 반증 실험으로 확정. NEW_RELIC_PACKAGE_REPORTING_ENABLED=false만 바꿔 재배포했더니 harvest 유래 이벤트가 사라졌다. 그 전에는 1초라는 관대한 임계에서도 기동 3분 안에 20건 넘게 나왔는데, 끈 뒤에는 임계를 0.2초로 더 낮췄는데도 12분간 2건이었다.
  • 다만 그 2건이 두 번째 진입점을 드러냈다. 남은 이벤트의 스택은 packages_distributions가 아니라 importlib_metadata:514:version → :491:metadata였고, 요청 처리 중 지연 임포트가 계측 훅의 버전 조회를 부르는 경로였다. 설정 하나로 다 막힌다고 생각했던 게 틀렸다.

관련 노트

참고

이 문서를 참조하는 노트 (2)

함께 읽기 좋은 글