Ch.2 CS Drill Down (2) - System Call이 왜 비싼가

< print()는 어디로 가는가 | 정리 >

---

이전 페이지에서 print("a")가 결국 write() System Call을 호출해서 커널까지 간다는 걸 확인했다. 그런데 거기서 끝내면 정작 "왜 느린가"는 못 푼 거다. 커널에 부탁 한 번 하는 게 함수 호출 하나보다 그렇게까지 비쌀 이유가 있나? 이번 페이지는 그 의심을 들고 System Call 자체를 한 겹 더 판다. 비용을 만드는 게 무엇인지, 그게 얼마짜리인지, 그리고 우리 코드가 그걸 몇 번이나 하는지를 차례로 본다.

가설 — System Call 한 번에 도대체 뭐가 들길래?

함수 호출이 비싸봤자 얼마나 비싸냐는 의심을 풀려면, System Call이 보통 함수 호출과 뭐가 다른지를 봐야 한다. 공항 출국장을 떠올려보자. 일반인(User Mode)은 공항 로비까지만 갈 수 있다. 활주로에 나가서 비행기에 짐을 직접 실을 수는 없다. 반드시 보안 검색대를 통과하고, 항공사 직원(커널)에게 부탁해야 한다. 이 "보안 검색대 통과" 과정이 System Call이고, 이 통과에는 시간이 든다.

User Mode / Kernel Mode (사용자 모드 / 커널 모드)

CPU가 동작하는 두 가지 권한 수준이다.

• User Mode: 일반 프로그램이 실행되는 모드. 하드웨어에 직접 접근할 수 없다.
• Kernel Mode: 운영체제 커널이 실행되는 모드. 모든 하드웨어와 메모리에 접근 가능하다.

이 구분은 CPU 하드웨어 레벨에서 강제된다. 소프트웨어적으로 우회할 수 없다.

(출처: Intel 64 and IA-32 Architectures Software Developer's Manual, Volume 3, Chapter 5 - Protection)

핵심은 여기 있다. 보통 함수 호출은 같은 User Mode 안에서 점프했다 돌아오는 거라 거의 공짜다. 그런데 System Call을 호출하면, CPU는 User Mode에서 Kernel Mode로 권한 자체를 전환한다. 이때 벌어지는 일:

네 프로그램 (User Mode)
    |
    | write(1, "a\n", 2) 요청
    |
    v
==================================
  System Call 경계 (모드 전환)
  - 현재 작업 상태를 임시 저장
  - CPU 권한 수준 변경
  - 커널 코드로 점프
==================================
    |
    v
커널 (Kernel Mode)
    | 터미널 드라이버에 데이터 전달
    |
    v
==================================
  복귀 (모드 전환)
  - CPU 권한 수준 복원
  - 저장해둔 작업 상태 복원
  - 사용자 코드로 복귀
==================================
    |
    v
네 프로그램 계속 실행 (User Mode)

이 왕복을 모드 전환(Mode Switch)이라고 부른다. 참고로, 이후 챕터에서 다룰 Context Switch(프로세스/스레드 간 전환)와는 다른 개념이다. Mode Switch는 같은 프로그램 안에서 권한만 바뀌는 것이고, Context Switch는 아예 다른 프로그램으로 전환하는 것이다. 당연히 Context Switch가 더 비싸다.

그러니까 가설의 답은 "그냥 함수 호출이 아니라 권한 경계를 넘는 왕복"이라는 거다. 상태를 저장하고, 권한을 바꾸고, 점프하고, 다시 원상복구한다. 일이 많다. 그런데 "일이 많다"는 감만으로는 부족하다. 정말 print마다 이 왕복이 일어나긴 하는지부터 눈으로 확인하고, 그 한 번이 몇 사이클짜리인지 숫자로 봐야 한다.

눈으로 확인 — 정말 print마다 write()가 가는가

write() System Call

파일(또는 파일처럼 취급되는 대상)에 데이터를 쓰는 System Call이다.

형태: write(fd, buffer, count)

• fd: 어디에 쓸지 (File Descriptor 번호)
• buffer: 무엇을 쓸지 (데이터가 담긴 메모리 주소)
• count: 얼마나 쓸지 (바이트 수)

print("a")는 결국 write(1, "a\n", 2)로 변환된다.

fd=1은 stdout이므로 터미널 화면에 출력되는 것이다.

(출처: Linux man page - write(2))

이걸 실제로 눈으로 확인할 수 있다. Linux에서 strace라는 도구를 쓰면 프로그램이 호출하는 System Call을 추적할 수 있다.

strace

Linux에서 프로그램이 호출하는 System Call을 추적하는 디버깅 도구다.

프로그램이 커널에 어떤 요청을 보내는지 실시간으로 볼 수 있어서, 성능 문제나 버그의 원인을 찾을 때 유용하다.

macOS에서는 dtruss가 유사한 역할을 한다. 다만 macOS는 SIP(System Integrity Protection)가 걸려 있어서 sudo dtruss로 실행해도 제한이 있다. csrutil disable로 SIP를 끌 수 있지만 보안 위험이 있으니 추천하지 않는다.

macOS 사용자는 아래 strace 결과만 확인해도 이 챕터를 따라가는 데 문제없다.

# Linux에서 실행
strace -e trace=write python3 -c "
for i in range(5):
    print('a')
"

출력 (Python 초기화 과정의 출력은 생략):

write(1, "a\n", 2)    = 2
write(1, "a\n", 2)    = 2
write(1, "a\n", 2)    = 2
write(1, "a\n", 2)    = 2
write(1, "a\n", 2)    = 2

print() 5번 호출 = write() System Call 5번 발생. 1:1 대응이다. 가설대로 print마다 커널 왕복이 정말 일어난다.

그러면 우리 테스트 코드에서는?

for _ in range(100):                    # 100번 반복
    for i in range(len(message)):       # UUID는 36글자
        print(message[i])              # 매 글자마다 print

한 번의 요청당: 100 x 36 = 3,600번의 print() = 약 3,600번의 write() System Call = 3,600번의 모드 전환.

"3,600번이 실무에서 현실적인 수치인가?" 이 코드 자체는 극단적이다. 하지만 동시 접속자 수백 명이 요청을 보내면, 개별 요청의 System Call 수가 적더라도 누적되면 같은 수준에 도달한다. 원리를 체감하기 위한 실험이라고 보면 된다.

반면 dontPrint 버전에서는? 이 루프 안에서 write() System Call이 0번이다. 문자열 연결(ret += message[i])은 순수하게 User Mode에서 메모리 조작만으로 끝나는 작업이니까.

여기까지로 횟수는 잡혔다. 한쪽은 요청당 3,600번 커널을 부르고, 한쪽은 0번이다. 남은 건 그 한 번이 정말 비싼가다. 한 번 왕복이 싸구려라면 3,600번이라도 별것 아닐 테니까. 단가를 재보자.

단가 — 모드 전환 한 번이 몇 사이클인가

이 모드 전환 하나하나가 얼마나 비싼지 숫자로 보자.

CPU Cycle (CPU 사이클)

CPU가 하나의 기본 동작을 수행하는 데 걸리는 시간 단위다.

현대 CPU의 클럭 속도가 3GHz라면, 1초에 30억 번의 사이클이 돌아간다. 1 사이클은 약 0.33 나노초다.

단순한 덧셈은 1 사이클이면 되지만, 메모리 접근은 수십~수백 사이클, System Call은 수백~수천 사이클이 필요하다.

작업	대략적인 CPU 사이클 수
변수 간 덧셈	1 사이클
메인 메모리(DRAM) 읽기 (캐시 미스 시)	100~300 사이클
System Call (단순)	수백~수천 사이클
System Call + 실제 I/O	수천~수만 사이클

(출처: Ulrich Drepper, "What Every Programmer Should Know About Memory", 2007 / Livio Soares & Michael Stumm, "FlexSC", OSDI 2010. 현대 Linux에서는 Spectre/Meltdown 보안 패치(KPTI) 이후 모드 전환 비용이 더 증가했다.)

CPU 내부에서 변수를 더하는 건 1 사이클이면 된다. 메인 메모리까지 가면 수백 사이클(CPU 캐시에 있으면 수~수십 사이클로 줄어든다). System Call은 수천 사이클. 자릿수가 다르다.

그런데 잠깐 - 단순 함수 호출도 레지스터를 저장하고 복원한다. 그건 한두 사이클이다. 모드 전환은 왜 수천 사이클인가? "상태를 저장/복원한다"만으로는 이 자릿수가 설명되지 않는다. 진짜 범인은 따로 있다.

• TLB flush: CPU는 가상→물리 주소 변환 결과를 TLB라는 작은 캐시에 들고 있다(Ch.4에서 자세히 다룬다). 커널로 전환하면, 특히 Meltdown 보안 패치(KPTI) 이후로는 유저용·커널용 페이지 테이블이 분리돼 있어 전환마다 TLB의 상당 부분이 무효화된다. 그러면 직후의 메모리 접근마다 주소 변환을 처음부터 다시 하느라(page table walk) 수십~수백 사이클씩 샌다.
• 파이프라인 flush: 현대 CPU는 명령 수십 개를 미리 겹쳐 실행한다(파이프라인). 권한 경계를 넘으면 이 파이프라인을 비우고 다시 채워야 해서 스톨이 생긴다.
• 캐시 cold: 커널 코드와 데이터가 CPU 캐시에 없으면(cold) 캐시 미스가 연쇄로 터진다.

위 출처가 "KPTI 이후 모드 전환이 더 비싸졌다"고 한 것도 바로 이 TLB flush 때문이다. 정리하면, "레지스터 저장/복원"은 빙산의 일각이고, 수천 사이클이라는 자릿수는 TLB·파이프라인·캐시에서 나온다.

ret += message[i]는 메모리 조작이니까 수십~수백 사이클. print(message[i])는 System Call을 포함하니까 수천 사이클 이상.

이제 단가와 횟수가 둘 다 손에 들어왔다. 한 번에 수천 사이클짜리 작업을 요청당 3,600번. 반대쪽은 수십~수백 사이클짜리를 같은 횟수. 곱해보면 그 차이가 수십 배의 응답 시간 차이로 나타나는 거다. 처음 의심했던 "함수 하나 더 부르는 정도 아니냐"는 여기서 깨진다. 자릿수가 다른 작업을, 수천 번, 매 요청마다 하고 있었다.

반전 — 그런데 버퍼가 이걸 막아줘야 하는 거 아닌가?

여기서 한 번 더 의심해보자. 매번 System Call을 하면 비효율적인 걸 OS 설계자들이 몰랐을 리 없다. 운영체제나 Python이 뭔가 방어 장치를 두지 않았을까? 그렇다면 3,600번이 실제로는 훨씬 적게 나가야 맞는 거 아닌가?

실제로 그런 장치가 있다. Buffer라는 건데, 데이터를 임시로 모아뒀다가 한 번에 내보내는 메커니즘이다.

Buffer (버퍼)

데이터를 임시로 모아두는 메모리 공간이다.

매번 조금씩 I/O를 하면 비효율적이니까, 일정량을 모았다가 한 번에 처리하기 위해 사용한다.

마트에서 장 볼 때 물건 하나 살 때마다 계산대를 가는 게 아니라, 카트에 모아서 한 번에 계산하는 것과 같다.

I/O (Input/Output, 입출력)

프로그램이 외부와 데이터를 주고받는 모든 행위를 말한다.

화면 출력, 파일 읽기/쓰기, 네트워크 통신, 키보드 입력 등이 전부 I/O다.

I/O는 CPU 연산에 비해 압도적으로 느리다. 성능 문제의 대부분은 I/O에서 발생한다.

그러니까 의심은 정당하다. 버퍼가 있다면 3,600번의 print가 훨씬 적은 write로 뭉쳐져야 한다. Python의 stdout에도 분명히 내부 버퍼가 있다. 그런데 함정은 이 버퍼의 동작 모드에 있다.

상황	버퍼링 모드	동작
터미널에 연결	라인 버퍼링	\n(줄바꿈)이 들어오면 즉시 flush
파일/파이프로 리다이렉트	풀 버퍼링	버퍼가 가득 차면 flush (보통 4~8KB)

flush (플러시)

버퍼에 쌓아둔 데이터를 실제로 내보내고 버퍼를 비우는 행위다.

라인 버퍼링에서는 줄바꿈(\n)이 들어올 때, 풀 버퍼링에서는 버퍼가 가득 찰 때, 또는 프로그램이 명시적으로 flush()를 호출할 때 발생한다.

flush가 일어나면 그때 비로소 write() System Call이 호출된다.

여기서 의심이 풀린다 — 정확히는, 버퍼가 막아주리라던 기대가 깨진다. print()는 기본적으로 끝에 \n을 붙인다. 그리고 우리 서버(uvicorn)는 터미널에서 실행하고 있다. 터미널 연결 = 라인 버퍼링 = 줄바꿈마다 flush = 매 print()마다 write() System Call 발생.

결국 버퍼가 있음에도, print()의 기본 동작(\n 추가)과 라인 버퍼링의 조합 때문에 방어 장치가 무력화된다. 모아서 한 번에 보내라고 만든 버퍼인데, 줄바꿈마다 비워지니 사실상 모이질 않는 거다.

검증 — 세 가지 버퍼링을 strace로 직접 비교

방어 장치가 무력화된다는 말이 진짜인지, 버퍼링 모드만 바꿔가며 strace로 확인해보자. 같은 코드(print('a') 5번)를 실행 환경만 바꿔 돌린 결과다. (아래는 Linux에서 실제로 캡처한 출력이고, Python 초기화 단계의 write(3, ...)는 생략했다.)

1) 라인 버퍼링 — 터미널에 연결된 경우 (우리 서버를 터미널에서 띄울 때)

write(1, "a\n", 2)                      = 2
write(1, "a\n", 2)                      = 2
write(1, "a\n", 2)                      = 2
write(1, "a\n", 2)                      = 2
write(1, "a\n", 2)                      = 2

\n이 들어올 때마다 flush → print() 5번 = write() 5번. 1:1 대응이다. 버퍼가 있어도 안 모인다.

2) 풀 버퍼링 — 파이프/리다이렉트로 실행한 경우 (기본값)

write(1, "a\na\na\na\na\n", 10)         = 10

write()가 단 1번. 5번의 print()가 버퍼에 쌓였다가 종료 시점에 한 번에 flush됐다. 같은 코드인데 System Call이 1/5로 줄었다 — 실행 환경만 바뀌었을 뿐이다. 버퍼가 제 역할을 하면 이렇게 된다.

3) Unbuffered — PYTHONUNBUFFERED=1 (또는 python3 -u)

write(1, "a", 1)                        = 1
write(1, "\n", 1)                       = 1
write(1, "a", 1)                        = 1
write(1, "\n", 1)                       = 1
... (총 10번, 글자와 줄바꿈이 각각 따로)

버퍼링을 완전히 끄면 글자와 줄바꿈이 따로 나가서 오히려 write()가 10번이 된다.

위 세 결과를 직접 재현하는 명령 (macOS는 Docker/podman으로)

# 공통 셸: 컨테이너 안에서 strace 설치 후 실행
# 1) 라인 버퍼링: -it 로 터미널에 붙인다
docker run --rm -it --cap-add SYS_PTRACE 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('a')\""

# 2) 풀 버퍼링: -it 없이(파이프) 돌린다
docker run --rm --cap-add SYS_PTRACE 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('a')\""

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

세 결과를 나란히 보면 핵심이 분명해진다. write() System Call 횟수는 코드가 아니라 버퍼링 모드가 결정한다. 그래서 벤치마크에서는 측정 환경을 통제해야 하고, 그 통제 장치가 바로 다음에 설명할 PYTHONUNBUFFERED=1이다.

측정 통제 — PYTHONUNBUFFERED=1은 뭔가

앞에서 벤치마크를 실행할 때 PYTHONUNBUFFERED=1을 설정했다. 이게 뭔가?

Python을 실행할 때 이 환경 변수를 설정하면, stdout과 stderr의 버퍼링을 완전히 끈다(unbuffered 모드). 매 write()마다 즉시 출력된다.

왜 이걸 설정했는가? 위의 버퍼링 모드 표를 다시 보자. 터미널에 직접 연결하면 라인 버퍼링이지만, 파이프나 백그라운드로 실행하면 풀 버퍼링이 적용된다. 풀 버퍼링이면 print()를 수천 번 호출해도 버퍼가 가득 찰 때까지 write() System Call이 몇 번만 발생한다. 그러면 "print가 느리다"는 결과가 제대로 나오지 않는다.

PYTHONUNBUFFERED=1을 설정하면, 어떤 환경에서 실행하든 매 print()마다 write() System Call이 발생하도록 강제할 수 있다. 측정 환경에 따라 결과가 왜곡되는 걸 방지하기 위한 설정이다.

(이렇게 벤치마크에서는 "측정하고 싶은 것"만 정확히 측정되도록 환경을 통제하는 게 중요하다. 변수가 하나라도 잘못 설정되면 결과가 완전히 달라질 수 있다.)

전체 그림

여러 겹의 의심을 차례로 판 결과, print() 한 줄이 왜 느린지가 다 모였다. 단가(모드 전환 수천 사이클) × 횟수(요청당 3,600번) × 버퍼링이 안 막아주는 조건. 전체 흐름을 한 장에 정리하면 이렇다.

graph TD
    A["print('a')"] --> B["sys.stdout.write('a#92;n')"]
    B --> C["stdout 버퍼에 기록"]
    C --> D{"'#92;n' 감지 - 라인 버퍼링"}
    D --> E["flush - 버퍼를 비운다"]
    E --> F["write(1, 'a#92;n', 2) System Call"]
    F --> G["User Mode -> Kernel Mode 전환"]
    G --> H["커널이 터미널 드라이버에 데이터 전달"]
    H --> I["Kernel Mode -> User Mode 복귀"]
    I --> J["다음 print() 호출"]
    J --> A

    style F fill:#f96,stroke:#333
    style G fill:#f96,stroke:#333
    style I fill:#f96,stroke:#333

이 사이클이 요청 한 번에 3,600번 반복된다.

반면 dontPrint 버전은:

graph TD
    A["ret += message[i]"] --> B["User Mode 메모리 조작"]
    B --> C["다음 반복"]
    C --> A

    style A fill:#6f6,stroke:#333
    style B fill:#6f6,stroke:#333

System Call이 없다. 모드 전환이 없다. 전부 User Mode에서 끝난다. 빠를 수밖에 없다.

---

< print()는 어디로 가는가 | 유사 사례, 실무 대안, 키워드 정리 >