Ch.2 로그를 뺐더니 빨라졌어요? (1) - System Call과 커널¶

결론부터 말한다. print() 한 줄 찍을 때마다 너의 프로그램은 운영체제의 가장 깊은 곳, 커널까지 다녀온다. 그 왕복 비용이 수천 번 쌓이면 API 응답이 수십 배 느려진다. "로그 좀 빼봐"라는 선배의 말이 감이 아니라 과학이라는 걸, 이번 챕터에서 직접 증명한다.

이 챕터에서 답할 질문¶

print()는 왜 느린가? (사례·측정)
print() 한 줄이 내부적으로 무엇을 호출하는가? (bytecode → write())
System Call은 왜 비싼가? (Mode Switch와 CPU Cycle)
운영에서는 어떻게 로그를 다뤄야 하는가? (logging 레벨, QueueHandler, ORM 쿼리 로그)

목차¶

1. 환경 세팅¶

이번 챕터에서 사용할 도구는 다음과 같다.

도구	버전	용도	왜 이걸 쓰는가
Python	3.12+	서버, bytecode 분석	이 강의의 기본 언어
FastAPI	0.111+	테스트용 API 서버	가볍고 빠르다. 비동기 지원도 쉬움
uvicorn	-	ASGI 서버	FastAPI의 기본 서버
k6	최신	부하 테스트	Go로 만들어서 Python 기반 도구(Locust 등)보다 가볍고 강력하다
dis (Python 내장)	-	bytecode 분석	설치 없이, 내 코드가 내부적으로 어떻게 변환되는지 바로 볼 수 있다

k6

Grafana Labs에서 만든 오픈소스 부하 테스트 도구다.

Go 언어로 작성되어 있어서 Python 기반 부하 테스트 도구(Locust 등)보다 리소스를 적게 먹고, 더 많은 가상 사용자를 시뮬레이션할 수 있다.

테스트 스크립트를 JavaScript로 작성하고, CLI에서 바로 실행한다.

설치: https://grafana.com/docs/k6/latest/set-up/install-k6/

Bytecode (바이트코드)

사람이 작성한 소스 코드(Python, Java 등)를 컴퓨터가 실행하기 직전 단계로 변환한 중간 코드다.

Python의 경우 .py 파일을 실행하면 내부적으로 bytecode로 변환한 뒤, Python 가상 머신(CPython VM)이 이 bytecode를 한 줄씩 해석하며 실행한다.

__pycache__ 폴더에 .pyc 파일로 캐싱되는 게 바로 이 bytecode다.

도구 한 줄 안내 (Ch.2 외부 용어)¶

poetry: Python 의존성 관리 도구 (pip + venv 합본). 없으면 brew install poetry 또는 공식 설치 스크립트
uvicorn / ASGI: FastAPI 기본 서버. ASGI는 WSGI의 비동기 버전이라고 생각하면 된다
csbe-study: 이 저장소 루트의 실습 코드 디렉토리. git clone 후 그 안으로 이동해서 진행

설치 확인:

python3 --version         # Python 3.12+ 확인
cd csbe-study && poetry install  # 의존성 설치
k6 version                # k6 설치 확인

dis 모듈은 Python 내장이라 별도 설치가 필요 없다. Python이 내 코드를 내부적으로 어떻게 처리하는지(bytecode) 들여다볼 수 있는 도구다.

참고: 이번 챕터의 벤치마크는 서버를 PYTHONUNBUFFERED=1 환경에서 실행한다. 이게 뭔지, 왜 필요한지는 03-syscall-cost.md의 Buffer 섹션에서 설명한다. 지금은 "벤치마크 결과를 정확하게 만들기 위한 설정"이라고만 알아두면 된다.

macOS에서 strace가 안 돼요

strace는 Linux 전용이다. macOS는 dtruss가 있지만 SIP 때문에 제약이 많다. 직접 재현하고 싶다면 Docker(또는 podman)로 Linux 환경에서 돌리는 게 간단하다:

docker run --rm --cap-add SYS_PTRACE -it python:3.12 bash -c \
  "apt-get update -qq && apt-get install -y -qq strace && \
   strace -e trace=write python3 -c 'for i in range(5): print(i)'"

실제로 돌리면 이렇게 찍힌다 (Python 초기화 단계의 write(3, ...) 출력은 생략):

write(1, "0\n", 2)                      = 2
write(1, "1\n", 2)                      = 2
write(1, "2\n", 2)                      = 2
write(1, "3\n", 2)                      = 2
write(1, "4\n", 2)                      = 2
+++ exited with 0 +++

print() 5번이 정확히 write() 5번으로 1:1 대응한다. 위 결과는 미리 Linux(podman)에서 실행해 캡처한 것이므로, mac에서 따라 돌리지 않아도 이 출력만 보면 된다. (단, 위 명령은 -it로 터미널에 붙어 라인 버퍼링이 적용된 경우다. -it 없이 파이프로 돌리면 버퍼링이 달라져 결과가 한 줄로 합쳐진다 — 자세한 건 03-syscall-cost.md의 Buffer 섹션.)

다음: 사례: print를 뺐더니 수십 배 빨라졌다 >