Measure the slow part, don't guess it

목표

성능 문제에서 가장 비싼 실수는 틀린 곳을 고치는 것입니다. 눈으로 읽어 "여기가 느릴 것 같다" 를 고르면 대개 빗나갑니다.

여기서는 재고, 읽고, 고치고, 다시 재서 줄었는지 확인합니다.

재료

/opt/lab/perf/slowapp.py   느린 곳이 어디인지 눈으로는 안 보이는 프로그램
/opt/lab/perf/iowork.py    같은 일을 순차·스레드·프로세스로 해 보는 프로그램

먼저 작업 디렉터리로 가져옵니다.

mkdir -p /root/perf && cp /opt/lab/perf/* /root/perf/ && cd /root/perf

남길 것

01-time.txt      real·user·sys
02-tottime.txt   자체 시간 순
03-cumtime.txt   누적 시간 순
04-fix.txt       고치기 전과 후
05-gil.txt       CPU 바운드: 순차·스레드·프로세스
06-wait.txt      기다리는 일: 순차·스레드
07-notes.md      왜 그런지

세 숫자가 무엇을 가르나

slowapp.py 를 time 으로 재서 real · user · sys 를 01-time.txt 에 남기고, real 이 user+sys 보다 큰 것이 무슨 뜻인지 한 줄 적으세요.

{ time python3 slowapp.py ; } 2> 01-time.txt

user 는 내 코드가 CPU 를 쓴 시간, sys 는 커널이 나 대신 쓴 시간, real 은 시계로 잰 시간입니다.

real 이 user+sys 보다 크면 그 차이만큼 기다린 것입니다. CPU 를 아무리 빠르게 해도 그 부분은 안 줄어듭니다.

첫 줄이 고칠 자리는 아니다

cProfile 을 자체 시간(tottime) 순으로 돌려 상위 열 줄을 02-tottime.txt 에 남기고, 가장 큰 줄이 왜 고칠 자리가 아닌지 적으세요.

python3 -m cProfile -s tottime slowapp.py 2>&1 | head -12

맨 위가 time.sleep 일 겁니다. 그런데 그것은 CPU 를 쓰지 않고 기다린 시간이라, 코드를 빠르게 해서 줄일 수 있는 것이 아닙니다.

고칠 수 있는 것은 그 아래에 있습니다.

자기가 오래 걸리나, 남을 오래 부르나

이번에는 누적 시간(cumtime) 순으로 돌려 03-cumtime.txt 에 남기세요. enrich 의 tottime 은 0에 가까운데 cumtime 이 큰 것이 무슨 뜻인지 적습니다.

python3 -m cProfile -s cumtime slowapp.py 2>&1 | head -12

tottime 은 그 함수 안에서 직접 쓴 시간, cumtime 은 그 함수가 부른 것까지 합한 시간입니다.

tottime 이 0인데 cumtime 이 크면 그 함수 자체는 잘못이 없고 누구를 부르느냐가 문제입니다. 고칠 곳은 호출된 쪽입니다.

고치고 다시 잰다

slowapp.py 를 fastapp.py 로 복사해 느린 부분만 고치고, 고치기 전과 후의 시간을 04-fix.txt 에 남기세요. 왜 느렸는지도 한 줄 적습니다.

parse 가 문자열을 한 글자씩 += 로 이어 붙입니다. 문자열은 바뀌지 않는 값이라, 이어 붙일 때마다 새 문자열을 통째로 만듭니다. 길이에 제곱으로 늘어납니다.

''.join(...) 이나 리스트 컴프리헨션으로 한 번에 만들면 됩니다.

고친 뒤 같은 방법으로 다시 재세요. 안 재면 고쳤는지 알 수 없습니다.

스레드를 늘려도 안 빨라진다

iowork.py cpu 를 순차·스레드·프로세스 세 가지로 돌려 05-gil.txt 에 남기고, 왜 스레드로는 안 빨라지는지 적으세요.

for how in seq thread proc; do python3 iowork.py cpu $how; done

스레드는 거의 그대로이고 프로세스만 빨라질 겁니다.

파이썬에는 한 번에 하나의 스레드만 바이트코드를 실행하게 하는 잠금(GIL) 이 있습니다. 계산만 하는 일은 그 잠금을 놓지 않으므로, 스레드를 늘려도 순서대로 도는 것과 같습니다. 프로세스는 인터프리터가 따로라 그 잠금도 따로입니다.

같은 도구가 반대로 동작한다

이번에는 iowork.py wait 을 순차·스레드로 돌려 06-wait.txt 에 남기고, 왜 이쪽은 스레드로 빨라지는지 적으세요.

for how in seq thread; do python3 iowork.py wait $how; done

기다리는 동안에는 그 잠금을 놓습니다. 그래서 다른 스레드가 그동안 일할 수 있습니다.

그래서 "스레드가 빠른가" 라는 질문에는 답이 없습니다. 무엇을 기다리는 일인가로 갈립니다: 네트워크·디스크·데이터베이스를 기다리면 스레드가 이기고, 계산이면 프로세스가 이깁니다.

다음에 읽을 사람에게

여기서 본 것 중 넷 이상을 골라 07-notes.md 에 정리하세요. 무엇을 했는지가 아니라 왜 그런지를 적습니다.

몇 달 뒤에 성능 문제를 만난 자신이 읽는다고 생각하세요. "cProfile 을 돌렸다" 는 도움이 안 되고, "tottime 이 큰 줄이 sleep 이면 그것은 CPU 문제가 아니다 — 고칠 수 있는 것은 그 아래에 있다" 는 도움이 됩니다.