파이썬 프로파일링 실측: 진짜로 빨라진 최적화만

시리즈: 파이썬 강좌 6/6 (고급). 파이썬 코드가 돌아가긴 하는데 느리고, 꼼수 목록이 아니라 "방법"을 알고 싶은 분을 위한 글입니다. 다 읽으면 재기 → 진짜 병목 찾기 → 고치기 → 고쳐졌음을 증명하기를 스스로 돌릴 수 있고, 무시해도 되는 "속도 팁"도 가려낼 수 있습니다.

크롤링으로 모은 데이터 집계 스크립트가 너무 오래 걸리거나, 코딩 테스트에서 파이썬만 시간 초과가 나서 루프를 세 번이나 고쳐 썼는데 거의 그대로였던 경험이 있다면 이 글이 맞습니다. 일부러 느리게 짠 프로그램 하나를 프로파일하고, 단계마다 시간을 재면서 고칩니다. 결론부터 말하면 변경 하나로 프로그램 전체가 78배 빨라졌고, 유명한 미세 최적화 대부분은 측정 오차만큼도 안 움직였습니다.

측정은 모두 Apple Silicon Mac(M1 Pro)의 Python 3.9.6 입니다. Python 3.11 도 있지만 Rosetta 2 변환 위에서 도는 빌드라 시간 측정에는 전혀 쓰지 않았습니다. 이 이야기는 마지막에 다시 합니다.

느린 프로그램

단어 빈도를 세는 프로그램입니다. 무작위로 만든 단어 5,000개 사전에서 20만 단어를 뽑고(seed 42 고정), 소문자로 맞추고, 처음 나온 순서대로 중복을 거르고, 개수를 세서 상위 5개를 출력합니다. 첫 버전에서 흔히 보는 방식으로 짰습니다.

# wordfreq_slow.py
import random

def make_words(n=200_000, vocab=5_000, seed=42):
    rnd = random.Random(seed)
    letters = "abcdefghijklmnopqrstuvwxyz"
    pool = ["".join(rnd.choice(letters) for _ in range(rnd.randint(3, 9))) for _ in range(vocab)]
    return [rnd.choice(pool) for _ in range(n)]

def normalize(words):
    text = ""
    for w in words:
        text += w.lower() + " "          # string concat in a loop
    return text.split()

def unique_in_order(words):
    seen = []
    for w in words:
        if w not in seen:                 # list membership: O(n)
            seen.append(w)
    return seen

def count(words):
    counts = {}
    for w in words:
        if w in counts:
            counts[w] = counts[w] + 1
        else:
            counts[w] = 1
    return counts

def top(counts, k=5):
    return sorted(counts.items(), key=lambda kv: (-kv[1], kv[0]))[:k]

def main():
    words = normalize(make_words())
    uniq = unique_in_order(words)
    counts = count(words)
    return len(words), len(uniq), top(counts)

if __name__ == "__main__":
    import time
    t = time.perf_counter()
    print(main())
    print(f"{time.perf_counter() - t:.2f} s")

(200000, 4985, [('mor', 96), ('jwc', 90), ('fyg', 89), ('tksm', 86), ('bef', 82)])
4.08 s

더 읽기 전에 어디가 느린지 맞혀 보세요. 대부분 문자열 연결을 고릅니다. 모든 입문 글이 경고하니까요.

1단계: timeit 으로 제대로 재기

몇 초 걸리는 작업이면 전체를 time.perf_counter() 로 감싸면 충분합니다. 그보다 짧은 건 timeit 을 씁니다. 문장을 여러 번 실행하고 그걸 5번 반복하니, 최솟값을 봅니다(최솟값이 다른 프로세스의 방해를 가장 덜 받은 회차입니다).

$ python3 -m timeit -s "from wordfreq_slow import make_words" "make_words()"
5 loops, best of 5: 81.7 msec per loop

흔한 실수: 입력을 바꾸는 작업을 재기

$ S="import random; random.seed(1); data = [random.random() for _ in range(100_000)]"
$ python3 -m timeit -s "$S" "data.sort()"
1000 loops, best of 5: 215 usec per loop
$ python3 -m timeit -s "$S" "sorted(data)"
20 loops, best of 5: 12.4 msec per loop
$ python3 -m timeit -s "$S" "d = data[:]; d.sort()"
20 loops, best of 5: 12.5 msec per loop

실제로 일어나는 일: setup 은 한 번만 실행됩니다. 첫 data.sort() 가 리스트를 제자리에서 정렬하고, 나머지 4,999번은 이미 정렬된 리스트를 정렬합니다. Timsort 는 그걸 한 번 훑고 끝내기 때문에 215µs 라는 결과는 58배나 낙관적입니다. 고치는 법: 재는 문장 안에서 복사하고(d = data[:]; d.sort()), 필요하면 복사만의 시간(data[:] 은 150µs)을 따로 재서 뺍니다. sort, pop, 딕셔너리 갱신, 캐시처럼 입력을 바꾸는 작업의 벤치마크는 전부 이 문제가 있습니다.

2단계: cProfile 과 pstats 로 병목 찾기

$ python3 -m cProfile -s tottime wordfreq_slow.py
(200000, 4985, [('mor', 96), ('jwc', 90), ('fyg', 89), ('tksm', 86), ('bef', 82)])
4.33 s
         1562316 function calls (1562289 primitive calls) in 4.335 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    4.111    4.111    4.111    4.111 wordfreq_slow.py:16(unique_in_order)
   235049    0.055    0.000    0.074    0.000 random.py:237(_randbelow_with_getrandbits)
   230049    0.046    0.000    0.125    0.000 random.py:343(choice)
        1    0.024    0.024    0.037    0.037 wordfreq_slow.py:10(normalize)
        1    0.022    0.022    0.132    0.132 wordfreq_slow.py:8(<listcomp>)
        1    0.018    0.018    0.018    0.018 wordfreq_slow.py:23(count)

tottime 은 함수 안에서만 쓴 시간, cumtime 은 호출한 함수까지 포함한 시간입니다. unique_in_order 함수 하나가 4.34초 중 4.11초(95%) 입니다. 다들 의심한 문자열 연결 normalize 는 전부 합쳐 0.037초입니다. 그걸 먼저 "고쳤다면" 4초짜리 실행에서 많아야 0.01~0.04초를 줄였을 겁니다.

코드 안에서 특정 부분만 프로파일하고 누적 시간 순으로 보려면 이렇게 합니다.

import cProfile, pstats, wordfreq_slow as m
pr = cProfile.Profile(); pr.enable(); m.main(); pr.disable()
pstats.Stats(pr).strip_dirs().sort_stats("cumulative").print_stats(8)

         1560940 function calls in 4.153 seconds

   Ordered by: cumulative time
   List reduced from 28 to 8 due to restriction <8>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    4.153    4.153 wordfreq_slow.py:35(main)
        1    3.934    3.934    3.934    3.934 wordfreq_slow.py:16(unique_in_order)
        1    0.000    0.000    0.159    0.159 wordfreq_slow.py:4(make_words)
        1    0.022    0.022    0.131    0.131 wordfreq_slow.py:8(<listcomp>)
   230049    0.045    0.000    0.125    0.000 random.py:343(choice)

cProfile 은 파이썬 수준 함수 호출마다 오버헤드가 붙는다는 점에 주의하세요. make_words 가 여기서는 0.159초지만 timeit 으로는 81.7ms 였습니다. 프로파일러로는 "어디"를 찾고, "얼마나"는 timeit 으로 잽니다.

3단계: 병목부터 고치고, 매번 재기

아래 각 버전은 원래 코드와 중복 제거 결과·개수가 완전히 같은지 스크립트 안의 assert 로 확인한 다음, 5회(v0 만 3회) 중앙값을 냈습니다. 단어 생성은 빼고 처리 부분만 잰 시간입니다.

최종 버전은 짧습니다.

# wordfreq_fast.py
from collections import Counter
from wordfreq_slow import make_words

def main():
    words = [w.lower() for w in make_words()]
    uniq = list(dict.fromkeys(words))        # keeps first-seen order (3.7+)
    counts = Counter(words)
    top = sorted(counts.items(), key=lambda kv: (-kv[1], kv[0]))[:5]
    return len(words), len(uniq), top

단어 생성까지 포함해 0.12초, 출력은 같습니다. 이제는 make_words(82ms)가 가장 무거워졌으니, 다음에 프로파일러가 가리킬 곳은 거기입니다.

1단계 하나로 78배가 된 이유: 리스트에 대한 w not in seen 은 원소를 하나씩 비교하므로 20만 단어 × 최대 4,985개로 수억 번 비교합니다. set 은 해시를 한 번 계산하면 끝입니다. 단계별 마이크로 벤치마크(timeit, 5회 최솟값):

--- dedupe 200k words (min of 5 repeats, 1 loops each)
  list membership                     4252.94 ms   x  1.00
  set membership                         3.87 ms   x1099.67
  dict.fromkeys                          4.03 ms   x1056.10
--- build text (min of 5 repeats, 20 loops each)
  str += in loop                        29.19 ms   x  1.00
  join(generator)                       22.31 ms   x  1.31
  join([list comp])                     19.33 ms   x  1.51
--- count words (min of 5 repeats, 20 loops each)
  if w in d                             13.18 ms   x  1.00
  d.get(w, 0) + 1                       13.77 ms   x  0.96
  try/except KeyError                   12.01 ms   x  1.10
  defaultdict(int)                      10.53 ms   x  1.25
  Counter(words)                         6.27 ms   x  2.10

join(제너레이터) 보다 join([리스트 컴프리헨션]) 이 빨랐던 건 str.join 이 받은 제너레이터를 어차피 리스트로 만든 뒤 처리하기 때문입니다. 제너레이터는 수고만 더합니다. Counter(words) 가 이긴 건 세는 루프가 C 로 돌기 때문이고, c[w] += 1 을 손으로 돌리면 이 차이는 나지 않습니다.

흔한 실수: 속성에 += 하면 제곱 비용

normalize 의 문자열 연결이 쌌다는 데 놀란 분이 많을 겁니다. CPython 에는 최적화가 있어서, text += ... 의 왼쪽이 그냥 변수이고 그 문자열을 다른 누구도 참조하지 않으면 문자열을 제자리에서 늘립니다. 단, 대입 대상이 변수 이름일 때만입니다. 속성에 대입하면 사라집니다.

# concat_attr.py
import time
from wordfreq_slow import make_words

class Buf:
    def __init__(self): self.text = ""

def local_concat(words):
    text = ""
    for w in words:
        text += w + " "
    return text

def attr_concat(words):
    b = Buf()
    for w in words:
        b.text += w + " "        # attribute target: no in-place resize
    return b.text

for n in (50_000, 100_000, 200_000):
    words = make_words(n)
    for f in (local_concat, attr_concat):
        t = time.perf_counter(); f(words); dt = time.perf_counter() - t
        print(f"{f.__name__:<13} n={n:>7,}: {dt*1000:8.1f} ms")

local_concat  n= 50,000:      4.5 ms
attr_concat   n= 50,000:    203.8 ms
local_concat  n=100,000:      8.9 ms
attr_concat   n=100,000:    717.7 ms
local_concat  n=200,000:     17.7 ms
attr_concat   n=200,000:   2948.9 ms

실제로 일어나는 일: 지역 변수 버전은 입력에 비례해 늘어납니다(4.5 → 8.9 → 17.7ms). 속성 버전은 입력이 2배가 될 때마다 약 4배가 됩니다(204 → 718 → 2,949ms). += 할 때마다 지금까지의 문자열 전체를 복사하기 때문입니다. 고치는 법: 조각을 리스트에 모았다가 마지막에 한 번 "".join(parts) 하거나, 지역 변수로 만든 뒤 마지막에 속성에 대입합니다. "join 을 써라"가 여전히 맞는 조언인 이유가 이것입니다. 빠른 경로는 CPython 구현 세부일 뿐이라, 코드를 클래스로 리팩터링하는 순간 사라집니다.

지역 변수 조회, 컴프리헨션, map

--- 1M items: len(str(i)) (min of 5 repeats, 3 loops each)
  for + out.append (globals)           162.38 ms   x  1.00
  for + local aliases                  125.72 ms   x  1.29
  list comprehension                   139.07 ms   x  1.17
  map(len, map(str, ...))               93.13 ms   x  1.74
  map(lambda ...)                      132.86 ms   x  1.22

"지역 변수 별칭" 꼼수(append = out.append, 기본 인자로 len=len)는 진짜로 효과가 있어서 3.9 에서 시간이 22% 줄었습니다. 지역 변수 조회가 전역·내장 이름 조회보다 싸고, out.append 를 매번 다시 꺼내지 않기 때문입니다. 컴프리헨션은 그 효과의 일부를 공짜로 얻으면서 읽기도 쉽습니다. 내장 함수를 넘긴 map 이 가장 빨랐던 건 원소마다 파이썬 프레임이 돌지 않기 때문이고, lambda 를 넘기면 그 장점이 사라집니다. 실제 코드라면 컴프리헨션을 고르겠습니다. 별칭 꼼수로 얻는 건 100만 개당 13ms 이고, 대신 가독성을 잃습니다.

효과 없던 "최적화 팁" (이번 측정에서)

3.9 실측 기준으로, 이런 종류의 코드에서는 따를 가치가 없었던 조언입니다.

"흔한 팁은 다 틀렸다"고 결론 내리지 않도록, 효과가 있었던 것도 두 가지 적습니다. i ** 2 대신 i * i(100만 번에 214.50ms 대 34.97ms, 6.1배), 그리고 while 카운터 대신 for i in range(N)(57.43ms 대 28.68ms)입니다. 둘 다 인터프리터 루프 안의 일을 줄이는 것이고, sum(range(N))(10.25ms)은 루프 자체를 C 에 맡겨서 둘 다 이깁니다. 경향은 분명합니다. 일을 C 쪽으로 옮기는 요령은 효과가 있고, 파이썬 문법만 바꿔 끼우는 요령은 대개 효과가 없습니다.

메모리: tracemalloc

비용은 시간만이 아닙니다. normalize 는 모든 단어를 이은 큰 문자열을 만들고 거기서 리스트를 만듭니다. tracemalloc 으로 파이썬이 할당한 메모리를 잽니다.

# mem.py
import tracemalloc
from collections import Counter
from wordfreq_slow import make_words, normalize

words = make_words()

tracemalloc.start()
counts = Counter(normalize(words))            # builds one big string, then a list
cur, peak = tracemalloc.get_traced_memory()
print(f"normalize + Counter : peak {peak/1e6:5.1f} MB")
tracemalloc.stop()

tracemalloc.start()
counts2 = Counter(w.lower() for w in words)   # streams one word at a time
cur, peak = tracemalloc.get_traced_memory()
print(f"generator + Counter : peak {peak/1e6:5.1f} MB")
assert counts == counts2

snap = tracemalloc.take_snapshot()
for stat in snap.statistics("lineno")[:3]:
    print(stat)
tracemalloc.stop()

normalize + Counter : peak  14.0 MB
generator + Counter : peak   0.4 MB
~/demo/mem.py:15: size=268 KiB, count=4986, average=55 B
.../python3.9/collections/__init__.py:679: size=144 KiB, count=1, average=144 KiB
.../python3.9/abc.py:123: size=1459 B, count=16, average=91 B

스트리밍 버전의 최고점은 14MB 가 아니라 0.4MB 입니다. 스냅샷에는 아직 살아 있는 것, 즉 4,986개의 작은 문자열(Counter 키로 남은 서로 다른 단어)과 Counter 의 해시 테이블이 보입니다. 2GB 로그 파일이라면 이것이 "돈다"와 "메모리 부족으로 죽는다"의 차이입니다. 제너레이터 이야기는 3강에서 자세히 다뤘습니다.

판단표

솔직한 한계와 버전 메모

• 시간은 모두 Apple M1 Pro 의 Python 3.9.6 으로 쟀습니다. 다른 작업도 도는 상태였고, timeit 은 5회 최솟값, 전체 측정은 5회 중앙값입니다. 절대값은 환경마다 다르니 비율을 비교하세요.
• Python 3.11 의 "Faster CPython" 효과는 재지 않았습니다. 3.11 릴리스 노트는 pyperformance 기준으로 3.10 보다 평균 약 1.25배 빠르다고 합니다. 이 맥의 3.11 은 Rosetta 2 위에서 도는 x86_64 빌드라, 재 봤자 인터프리터가 아니라 변환 계층을 재는 셈입니다. 위의 차이 중 일부(i ** 2 대 i * i, 전역 이름 조회 비용 등)는 3.11 이후에 줄었을 수 있지만, 얼마나인지는 말할 수 없습니다.
• str += 의 제자리 확장은 CPython 구현 세부이고, 여기서는 3.9 에서 관찰한 것입니다. PyPy 같은 다른 구현은 보장하지 않습니다.
• dict.fromkeys 가 삽입 순서를 지키는 건 dict 순서가 3.7 부터 언어 사양으로 보장되기 때문입니다.
• cProfile 수치에는 프로파일러 오버헤드가 들어 있습니다. make_words 는 프로파일러 아래에서 0.159초, timeit 으로는 81.7ms 였습니다.

이전: 5강 스레드·프로세스·asyncio 와 GIL · 처음부터: 1강 타입과 가변성

관련: 이터레이터·제너레이터와 메모리(3강) · 자바 JIT·GC·메모리 · 정렬 알고리즘