Wrapture 도구로 느린 코드 찾아내기
1. 이게 뭔가요?
이 글은 파이썬(Python) 기반 웹 서비스에서 특정 기능의 처리 속도가 느려졌을 때 원인이 되는 코드 위치를 정확하게 찾아내는 소프트웨어 추적 도구인 랩처(wrapture)의 활용법을 설명합니다. 글쓴이는 가상의 온라인 쇼핑몰에서 결제 내역을 기록하는 장부 함수에 0.03초 동안 실행을 멈추는 지연 코드를 넣어 두고, 랩처를 사용해 상위 작업이 느린 이유가 자신이 직접 수행한 연산 때문인지 아니면 호출한 하위 작업 때문인지를 계층 구조로 명확히 분석하는 과정을 보여줍니다.
2. 왜 화제인가요?
프로그램이 느려졌을 때 함수 앞뒤에 직접 시간 측정 코드를 넣는 전통적인 방식은 원본 소스코드를 일일이 수정해야 하고, 기록된 측정값이 흩어져 개별 요청과 연결되지 않으므로 빠른 요청 사이에 섞인 느린 요청을 가려내기 어렵습니다. 반면 프로그램 전체를 감시하는 프로파일러는 웹 프레임워크 내부의 방대한 동작까지 전부 수집하여 특정 소수 함수에 대한 순수 처리 시간을 따로 계산해 내지 못합니다. 랩처는 원본 코드를 어지럽히지 않고도 부모와 자식 작업의 호출 관계를 자동으로 파악해 순수한 자체 소요 시간을 정확히 분리해 낼 수 있어 성능 저하 지점을 효율적으로 밝혀냅니다.
3. 핵심 내용
글쓴이는 파이썬 기반 웹 제작 도구인 플라스크(Flask)로 제작한 쇼핑몰의 주문 접수 주소(/order)가 느려진 상황을 분석합니다. 사용자가 주문을 요청하면 주문 화면을 처리하는 뷰(view)가 주문 서비스를 호출하고, 서비스는 결제 대행 장치인 게이트웨이를 거쳐 장부 기록(Ledger.record) 함수를 실행합니다. 글쓴이는 이 흐름 중 장부 기록 함수에 0.03초 멈춤(time.sleep(0.03))을 넣어 두고 성능 측정을 시작합니다. 단일 주문 요청을 보냈을 때 랩처가 출력한 계층 구조를 보면 전체 웹 요청에 총 37.3밀리초(1밀리초는 1,000분의 1초)가 걸렸습니다. 이 중 뷰 단계는 36.3밀리초, 주문 서비스 단계는 35.9밀리초, 장부 기록 단계는 35.1밀리초가 소요된 반면 결제 게이트웨이는 8마이크로초(1마이크로초는 100만분의 1초)만 사용했습니다. 이를 분석하면 장부 기록이 주문 서비스 소요 시간의 거의 전부를 차지하고, 주문 서비스가 뷰 전체 시간의 대부분을 차지하고 있음을 알 수 있습니다. 즉 주문 서비스와 뷰는 자신이 호출한 하위 작업이 늦게 끝나 겉보기에만 느려 보였을 뿐이며, 장부 기록은 호출한 하위 작업 없이 순수하게 자기 자신의 연산 동작 때문에 느렸던 것입니다. 이처럼 전체 작업 시간에서 자신이 불러낸 하위 작업들이 소비한 시간을 뺀 순수한 시간을 '자체 시간(Self time)'이라고 부릅니다. 랩처는 하위 작업이 끝날 때마다 부모 작업과의 연결 관계를 바탕으로 이 자체 시간을 자동으로 계산해 줍니다. 글쓴이는 자동 검사(테스트) 코드에서 주문 처리, 결제, 장부 기록을 감시 대상(바인딩)으로 지정하고 카드 번호는 보안상 기록에 남지 않도록 숨기도록(redact) 설정했습니다. 그런 뒤 pytest 도구로 검사를 실행하여 주문 서비스의 순수 자체 시간은 전체 주문 소요 시간의 10% 미만(실제 31.0밀리초 중 173마이크로초만 자체 시간)이고, 장부 기록의 순수 자체 시간은 전체의 90%를 초과(30.8밀리초)한다는 조건을 통과시킴으로써 장부 기록이 지연의 핵심 원인임을 입증했습니다. 단 한 번의 요청 분석에 그치지 않고 여러 요청을 종합 분석하는 기법도 다룹니다. 랩처의 '집계 수집기(Aggregate collector)'는 감시 대상 위치마다 시작 및 완료된 작업 수, 오류 발생 횟수, 총 소요 시간, 순수 자체 시간, 최단 및 최장 시간을 집계하여 자체 시간을 기준으로 정렬해 보여줍니다. 이 수집기는 개별 요청의 상세한 사건 데이터를 쌓아두지 않고 통계 수치만 갱신하므로 트래픽이 늘어나도 메모리 사용량이 감시 지점의 수에 비례하여 일정하게 유지됩니다. 설정 파일에서 'stats'라는 측정 기간(윈도우)을 지정하고 정상 주문 10건, 결제 거절 주문 10건, 견적 조회 10건으로 이루어진 총 30건의 요청을 1.6초 동안 보낸 뒤 집계한 결과, 10건의 장부 기록 작업이 총 358.3밀리초의 자체 소요 시간을 기록하며 최상위 지연 원인으로 집계되었습니다. 결제 거절 10건의 오류는 게이트웨이 단계와 이를 상위로 넘긴 주문 서비스 단계에서 각각 잡혀 총 20회로 기록되었습니다. 특정 고객사(테넌트)나 계정에서만 발생하는 속도 저하를 추적하는 방법도 제시합니다. 랩처의 annotate() 기능은 인터넷 요청 머리말(헤더)에 들어 있는 고객 식별 정보를 현재 진행 중인 감시 기록에 안전하게 덧붙여 주며, 감시가 꺼져 있을 때는 아무 동작도 하지 않아 운영 코드에 영구적으로 남겨두기 적합합니다. 요청 직전에 실행되는 통로(before_request)에 고객 정보를 붙이는 한 줄의 코드를 넣어두면, jsonlines 파일 저장소에 저장된 기록에서 특정 고객의 요청만 골라 분석할 수 있습니다. 실제로 정상 결제 고객(acme)의 주문은 32.5밀리초에서 35.9밀리초가 걸렸던 반면, 결제가 거절된 고객의 주문은 장부에 도달하지 않고 관문에서 거절되어 약 1밀리초 안팎에 불과했습니다. 마지막으로 정밀한 소요 시간 대신 실행 횟수만 세는 '카운터 수집기'를 소개합니다. 자원을 거의 소모하지 않는 이 수집기를 데이터베이스 실행 함수에 연결하고 테스트마다 허용할 조회 횟수 상한선을 설정해 두면, 데이터 하나를 읽을 때마다 불필요하게 조회가 연쇄적으로 일어나는 고전적인 성능 결함(N+1 문제)을 명확한 초과 횟수와 함께 사전에 잡아낼 수 있습니다.
4. 나에게 어떤 영향이 있나요?
일반 이용자에게는 결제나 주문 같은 웹 기능이 느려졌을 때 시스템 관리자가 그 원인을 더 빠르고 명확하게 찾아내 개선할 수 있는 기술적 환경이 마련됩니다. 소프트웨어를 개발하고 운영하는 입장에서는 코드 곳곳에 임시 측정 코드를 삽입하지 않고도 상하 호출 관계에 따른 순수 자체 소요 시간을 확인해 병목 구간을 신속하게 파악할 수 있습니다. 아울러 고객 식별 정보를 기록과 연계해 개별 환경의 성능 저하를 추적하거나, 자동화 검사에 가벼운 카운터를 도입해 불필요한 데이터베이스 조회가 급증하는 성능 결함을 조기에 방지할 수 있습니다.