매일 돌리는 파이썬 스크립트가 점점 느려지는데 어디가 느린지 모를 때, 감으로 코드를 고치기 시작하면 엉뚱한 곳에 시간을 쓰기 쉽습니다. 파이썬 cProfile 사용법을 알면 설치 없이 명령 한 줄로 “어느 함수가 몇 번 불려 몇 초를 썼는지” 표로 볼 수 있습니다. 접속 로그 10만 줄을 요약하는 스크립트로 직접 해 보니, 처음 버전은 2.92초가 걸렸고 cProfile 표를 보고 두 군데를 고친 뒤 0.32초가 됐습니다. 다만 표만 믿었다면 잘못 짚을 뻔한 지점도 있었습니다. 이 글에서는 cProfile 실행법, 표 읽는 법, 결과를 저장해 골라 보는 법, 그리고 cProfile이 보여 주지 않는 것까지 실측 출력으로 정리합니다. 환경은 윈도우 11, Python 3.12.10이고 표준 라이브러리만 썼습니다.
느린 스크립트 준비: 접속 로그 10만 줄 요약
시험용으로 시각, 사용자, 페이지, 상태 코드, 응답 시간 다섯 열짜리 CSV를 10만 행 만들었습니다. 사용자는 u0001~u3000 3,000명입니다. 아래는 이 파일에서 시간대별 요청 수, 순방문자 수, 오류율을 내는 스크립트입니다. 흔히 처음 짜는 모양 그대로입니다.
"""접속 로그 요약 (처음 짠 버전): 시간대별 요청 수, 순방문자 수, 오류율"""
import csv
from datetime import datetime
def load(path):
with open(path, encoding="utf-8") as f:
return list(csv.DictReader(f))
def parse_time(s):
return datetime.strptime(s, "%Y-%m-%d %H:%M:%S")
def summarize(rows):
by_hour = {}
visitors = []
errors = 0
for r in rows:
hour = parse_time(r["time"]).hour
by_hour[hour] = by_hour.get(hour, 0) + 1
if r["user"] not in visitors:
visitors.append(r["user"])
if r["status"] != "200":
errors += 1
return by_hour, len(visitors), errors / len(rows)
def main():
rows = load("access_log.csv")
by_hour, uniq, err_rate = summarize(rows)
busiest = max(by_hour, key=by_hour.get)
print(f"전체 {len(rows):,}건, 순방문자 {uniq:,}명, 오류율 {err_rate:.1%}")
print(f"가장 바쁜 시간대: {busiest}시 ({by_hour[busiest]:,}건)")
if __name__ == "__main__":
main()$ python slow_report.py
전체 100,000건, 순방문자 3,000명, 오류율 10.0%
가장 바쁜 시간대: 0시 (4,800건)
[exit 0, 2.92초]10만 줄에 3초 가까이 걸립니다. 같은 명령을 다시 돌려도 2.86초, 2.52초였습니다. 읽어서 세는 것뿐인데 왜 느린지, 코드만 봐서는 바로 답이 나오지 않습니다.
명령 한 줄로 프로파일하기: python -m cProfile
스크립트를 고치지 않고 앞에 -m cProfile만 붙이면 됩니다. -s cumtime은 누적 시간 순으로 정렬하라는 옵션입니다.
python -m cProfile -s cumtime slow_report.py실제 출력의 앞부분입니다. 원래 결과 두 줄이 먼저 나오고 그 아래 표가 붙습니다.
$ python -m cProfile -s cumtime slow_report.py
전체 100,000건, 순방문자 3,000명, 오류율 10.0%
가장 바쁜 시간대: 0시 (4,800건)
3210678 function calls (3210518 primitive calls) in 3.350 seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
5/1 0.000 0.000 3.350 3.350 {built-in method builtins.exec}
1 0.008 0.008 3.350 3.350 slow_report.py:1(<module>)
1 0.000 0.000 3.340 3.340 slow_report.py:29(main)
1 1.754 1.754 3.098 3.098 slow_report.py:15(summarize)
100000 0.030 0.000 1.331 0.000 slow_report.py:11(parse_time)
100000 0.080 0.000 1.301 0.000 {built-in method strptime}
100000 0.086 0.000 1.218 0.000 _strptime.py:650(_strptime_datetime)
100000 0.604 0.000 1.132 0.000 _strptime.py:392(_strptime)
100002 0.027 0.000 0.266 0.000 _strptime.py:27(_getlang)
1 0.014 0.014 0.242 0.242 slow_report.py:6(load)
100002 0.042 0.000 0.239 0.000 locale.py:582(getlocale)
100001 0.128 0.000 0.228 0.000 csv.py:112(__next__)열의 뜻은 다음과 같습니다.
| 열 | 뜻 | 이 표에서 볼 것 |
|---|---|---|
| ncalls | 호출 횟수 | parse_time·strptime이 각각 100,000번 |
| tottime | 그 함수 자신만 쓴 시간(안에서 부른 함수 제외) | summarize 자신이 1.754초 |
| cumtime | 안에서 부른 함수까지 포함한 시간 | summarize 3.098초 중 parse_time 1.331초 |
| percall | 앞 열을 호출 횟수로 나눈 값 | 0.000처럼 너무 작으면 의미 없음 |
읽는 순서는 이렇습니다. cumtime이 큰 줄을 위에서부터 따라 내려가면 “시간이 어느 함수 아래로 흘러갔는지”가 보입니다. 이 표에서는 main → summarize(3.098초)로 내려가고, 그 안에서 parse_time이 1.331초를 씁니다. strptime은 10만 번 불릴 때마다 로케일 확인(getlocale)까지 하고 있었습니다. 맨 위 3210678 function calls는 이 짧은 스크립트가 함수를 321만 번 불렀다는 뜻입니다.
tottime에 숨어 있는 1.75초
눈여겨볼 줄은 summarize의 tottime 1.754입니다. 이 함수 안에서 부른 다른 함수를 빼고도 1.75초를 자기 코드에서 썼다는 뜻인데, 표 어디에도 그 시간이 무엇인지는 나오지 않습니다. cProfile은 함수 단위로 시간을 재기 때문에, 함수 호출이 아닌 코드는 감싸고 있는 함수의 tottime으로 뭉쳐 들어갑니다.
summarize가 부른 함수 목록을 따로 뽑아 봤습니다(방법은 다음 절에서 설명합니다).
Function was called by...
ncalls tottime cumtime
slow_report.py:11(parse_time) <- 100000 0.036 1.553 slow_report.py:15(summarize)
Function called...
ncalls tottime cumtime
slow_report.py:15(summarize) -> 100000 0.036 1.553 slow_report.py:11(parse_time)
2 0.000 0.000 {built-in method builtins.len}
3000 0.001 0.001 {method 'append' of 'list' objects}
100000 0.015 0.015 {method 'get' of 'dict' objects}parse_time, len, append, dict.get뿐입니다. 범인은 함수가 아닌 이 한 줄이었습니다.
if r["user"] not in visitors: # visitors는 list리스트에서 in은 앞에서부터 하나씩 비교합니다. 순방문자가 3,000명까지 쌓이면 줄마다 최대 3,000번을 비교하고, 그걸 10만 줄 반복합니다. 표에서 tottime이 큰데 호출하는 함수로 설명이 안 되면, 함수 안의 반복문과 in·문자열 더하기 같은 연산을 의심하면 됩니다.
결과를 파일로 저장하고 pstats로 골라 보기
명령줄 출력은 수백 줄이라 원하는 부분을 찾기 어렵습니다. 결과를 파일로 저장해 두면 다시 실행하지 않고 여러 번 정렬해 볼 수 있습니다. 명령줄에서는 python -m cProfile -o report.prof slow_report.py처럼 -o를 주면 되고, 코드 안에서는 아래처럼 합니다.
"""프로파일 결과를 파일로 저장한 뒤 pstats로 골라 보기"""
import cProfile
import pstats
import sys
import slow_report
sys.stdout.reconfigure(encoding="utf-8")
cProfile.run("slow_report.main()", "report.prof")
st = pstats.Stats("report.prof")
st.strip_dirs().sort_stats("tottime").print_stats(5) # 자기 시간 상위 5개
st.print_callers("strptime") # strptime을 누가 불렀나sort_stats("tottime")로 자기 시간 순으로 정렬하고 print_stats(5)로 상위 5개만 출력한 결과입니다.
3210597 function calls (3210414 primitive calls) in 4.095 seconds
Ordered by: internal time
List reduced from 285 to 5 due to restriction <5>
ncalls tottime percall cumtime percall filename:lineno(function)
1 2.229 2.229 3.798 3.798 slow_report.py:15(summarize)
100000 0.714 0.000 1.317 0.000 _strptime.py:392(_strptime)
100001 0.154 0.000 0.267 0.000 csv.py:112(__next__)
100000 0.100 0.000 1.418 0.000 _strptime.py:650(_strptime_datetime)
100000 0.094 0.000 1.517 0.000 {built-in method strptime}여기서 처음 실수를 했습니다. print_callers("strptime")으로 strptime을 누가 불렀는지만 보려 했는데, 인자가 정규식이라 _strptime.py 파일 안의 함수까지 23개가 전부 걸려 출력이 화면을 넘겼습니다(List reduced from 285 to 23). 괄호까지 넣어 함수 이름을 정확히 지정하니 한 줄만 나왔습니다. 앞 절의 출력이 이 코드로 뽑은 것입니다.
"""저장해 둔 report.prof에서 특정 함수만 골라 보기 (이름 인자는 정규식)"""
import pstats
import sys
sys.stdout.reconfigure(encoding="utf-8")
st = pstats.Stats("report.prof").strip_dirs()
st.print_callers(r"\(parse_time\)")
st.sort_stats("cumtime").print_callees(r"\(summarize\)")저장된 파일을 읽기만 하므로 이 스크립트는 0.13초에 끝났습니다. 느린 스크립트를 매번 다시 돌릴 필요가 없다는 게 저장의 장점입니다.
하나씩 고치며 재 보기: 표의 숫자와 실제 절약은 달랐다
표만 보면 strptime(cumtime 1.331초)이 가장 큰 덩어리처럼 보입니다. 그래서 고칠 후보 두 가지를 하나씩 바꿔 가며, 프로파일러 없이 summarize 루프 시간만 따로 쟀습니다.
$ python steps.py
0) 처음 버전 (strptime + list) 2.584초
1) list -> set 0.568초
2) set + fromisoformat 0.034초
3) set + 문자열 자르기 s[11:13] 0.032초결과는 표의 인상과 반대였습니다. 리스트를 set으로 바꾸자 약 2.0초가 줄었고, strptime을 datetime.fromisoformat으로 바꾼 효과는 약 0.5초였습니다(두 번째 실행에서는 각각 1.77초, 0.46초). 프로파일러 없이 잰 strptime 비용 0.5초 안팎은 cProfile 표의 1.331초보다 훨씬 작습니다.
이유는 cProfile의 동작 방식에 있습니다. 함수가 불리고 끝날 때마다 시간을 기록하기 때문에, 작은 함수를 수십만 번 부르는 부분은 그 기록 비용만큼 부풀려집니다. 실제로 같은 스크립트가 그냥 돌리면 2.5~2.9초인데 cProfile 아래에서는 3.35초, 결과를 파일로 저장한 실행에서는 4.10초로 나왔습니다. 반대로 함수 호출이 없는 리스트 검색은 거의 부풀지 않고 tottime 속에 숨어 있습니다. 그래서 cProfile로 후보를 찾고, 고친 효과는 프로파일러 없이 따로 재서 확인하는 순서가 안전합니다.
시각 문자열에서 시(hour)만 필요하다면 int(s[11:13])처럼 잘라도 되는데, fromisoformat과 0.002초 차이밖에 나지 않아서 읽기 쉬운 fromisoformat을 골랐습니다. fromisoformat은 2026-10-01 00:00:03처럼 ISO 형식에 가까운 문자열에만 쓸 수 있으니, 형식이 다른 로그라면 strptime을 그대로 쓰되, 바꾼 뒤 시간을 다시 재서 판단하세요.
고친 버전과 다시 프로파일한 결과
두 군데를 고친 최종본입니다. 바뀐 곳은 visitors = set(), visitors.add(), datetime.fromisoformat() 세 줄입니다.
"""접속 로그 요약 (고친 버전): 순방문자는 set, 날짜는 fromisoformat"""
import csv
from datetime import datetime
def load(path):
with open(path, encoding="utf-8") as f:
return list(csv.DictReader(f))
def summarize(rows):
by_hour = {}
visitors = set()
errors = 0
for r in rows:
hour = datetime.fromisoformat(r["time"]).hour
by_hour[hour] = by_hour.get(hour, 0) + 1
visitors.add(r["user"])
if r["status"] != "200":
errors += 1
return by_hour, len(visitors), errors / len(rows)
def main():
rows = load("access_log.csv")
by_hour, uniq, err_rate = summarize(rows)
busiest = max(by_hour, key=by_hour.get)
print(f"전체 {len(rows):,}건, 순방문자 {uniq:,}명, 오류율 {err_rate:.1%}")
print(f"가장 바쁜 시간대: {busiest}시 ({by_hour[busiest]:,}건)")
if __name__ == "__main__":
main()$ python fast_report.py
전체 100,000건, 순방문자 3,000명, 오류율 10.0%
가장 바쁜 시간대: 0시 (4,800건)
[exit 0, 0.32초]결과 세 줄은 처음 버전과 똑같고, 시간은 2.92초에서 0.32초가 됐습니다(다시 돌리면 0.28초). 고친 뒤에 다시 프로파일해 보면 병목이 어디로 옮겨 갔는지 보입니다.
$ python -m cProfile -s tottime fast_report.py
전체 100,000건, 순방문자 3,000명, 오류율 10.0%
가장 바쁜 시간대: 0시 (4,800건)
902133 function calls (902121 primitive calls) in 0.409 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
100001 0.170 0.000 0.291 0.000 csv.py:112(__next__)
100002 0.065 0.000 0.066 0.000 {built-in method builtins.next}
1 0.049 0.049 0.085 0.085 fast_report.py:11(summarize)
200001 0.035 0.000 0.035 0.000 csv.py:98(fieldnames)
200105 0.021 0.000 0.021 0.000 {built-in method builtins.len}
1 0.017 0.017 0.309 0.309 fast_report.py:6(load)
1 0.014 0.014 0.409 0.409 fast_report.py:1(<module>)
100000 0.013 0.000 0.013 0.000 {method 'add' of 'set' objects}
100000 0.013 0.000 0.013 0.000 {built-in method fromisoformat}
100012 0.009 0.000 0.009 0.000 {method 'get' of 'dict' objects}함수 호출은 321만 번에서 90만 번으로 줄었고, 이제 가장 큰 부분은 CSV를 읽는 csv.py:112(__next__), 즉 load(0.309초)입니다. summarize는 0.085초입니다. 더 줄이려면 CSV 읽기를 손봐야 하지만, 전체가 0.3초라 여기서 멈췄습니다. 병목 찾기는 “가장 큰 것 하나 고치고, 다시 재고, 충분하면 멈추기”의 반복입니다.
| 항목 | 처음 버전 | 고친 버전 |
|---|---|---|
| 전체 실행(파이썬 시작 포함) | 2.52~2.92초 | 0.28~0.32초 |
| cProfile 아래 실행 | 3.350초 | 0.409초 |
| 함수 호출 수 | 3,210,678 | 902,133 |
| summarize 루프만 | 2.27~2.58초 | 0.034초 |
주의할 점
- cProfile은 줄 단위가 아닙니다. 함수 안의 반복문·
in·연산은 그 함수의 tottime으로 합쳐집니다. tottime이 큰 함수가 있으면 그 함수 안을 직접 읽거나, 의심되는 부분을 작은 함수로 빼서 다시 프로파일하세요. - 작은 함수가 많이 불리는 부분은 부풀려집니다. 이번에는 strptime이 표에서 1.3초, 실제로는 0.5초 안팎이었습니다. 고친 효과는
time.perf_counter()로 프로파일러 없이 재세요. - 한 번 잰 시간은 흔들립니다. 같은 스크립트가 2.52초~2.92초로 나왔습니다. 비교할 때는 두세 번 돌려 범위로 보세요.
- 윈도우 콘솔 한글 깨짐: 시험 데이터 생성 스크립트의 출력이
100,000�� ����처럼 깨졌습니다. 출력을 파일로 남기거나 비교할 때는PYTHONIOENCODING=utf-8을 주고 실행하세요. print_callers·print_stats의 문자열 인자는 정규식입니다. 이름 일부만 주면 비슷한 함수가 줄줄이 걸립니다.
마무리
느린 이유를 짐작으로 고치지 말고, 명령 한 줄로 재고, 고친 효과는 다시 재서 확인합니다.
가장 작은 첫걸음은 이렇습니다.
- 평소 느리다고 느낀 스크립트 하나에
python -m cProfile -s cumtime 스크립트.py를 그대로 실행해 봅니다. cumtime이 큰 줄을 따라 내려가고,tottime이 큰데 설명이 안 되는 함수가 있으면 그 안의 반복문과in을 봅니다.- 한 곳만 고치고
time.perf_counter()로 전후 시간을 재서, 줄어든 만큼이 표의 숫자와 맞는지 확인합니다.
다음 글에서는 AI에 보낼 프롬프트의 토큰 수를 미리 세는 방법과, 글자 수로 어림한 값과 실제 토큰 수가 얼마나 다른지 실측해 보겠습니다.