Measure the slow part, don't guess it

Goal

The most expensive mistake in a performance problem is fixing the wrong place. If you pick "this looks slow" by reading the code, you are usually off the mark.

Here you measure, read, fix, and then measure again to confirm the time went down.

Materials

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

First, copy them into a working directory.

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

Files to produce

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      왜 그런지

What the three numbers tell apart

Time slowapp.py with time, save real · user · sys to 01-time.txt, and write one line on what it means that real is larger than user+sys.

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

user is the time your code spent on the CPU, sys is the time the kernel spent on your behalf, and real is the wall-clock time.

If real is larger than user+sys, the difference is time spent waiting. No matter how much faster you make the CPU work, that part does not shrink.

The first line is not the place to fix

Run cProfile sorted by self time (tottime), save the top ten lines to 02-tottime.txt, and write why the biggest line is not the place to fix.

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

The top line should be time.sleep. But that is time spent waiting without using the CPU, so you cannot reduce it by making the code faster.

What you can fix is further down.

Is it slow itself, or does it call something slow?

This time, run it sorted by cumulative time (cumtime) and save the output to 03-cumtime.txt. Write what it means that the tottime of enrich is close to 0 while its cumtime is large.

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

tottime is the time spent directly inside that function, and cumtime is the time including everything it calls.

If tottime is 0 but cumtime is large, the function itself is not at fault; the problem is what it calls. The place to fix is the callee.

Fix it and measure again

Copy slowapp.py to fastapp.py, fix only the slow part, and save the times before and after the fix to 04-fix.txt. Also write one line on why it was slow.

parse builds a string by appending one character at a time with +=. A string is an immutable value, so every append creates an entirely new string. The cost grows with the square of the length.

You can build it in one go with ''.join(...) or a list comprehension.

After the fix, measure again the same way. If you do not measure, you cannot know whether it is fixed.

Adding threads does not make it faster

Run iowork.py cpu three ways, sequential, threads, and processes, save the results to 05-gil.txt, and write why threads do not speed it up.

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

Threads should stay about the same, and only processes should get faster.

Python has a lock (the GIL) that lets only one thread execute bytecode at a time. A job that only computes never releases that lock, so adding threads is the same as running one after another. Each process has its own interpreter, so it also has its own lock.

The same tool behaves the opposite way

This time, run iowork.py wait sequentially and with threads, save the results to 06-wait.txt, and write why threads do speed this one up.

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

While a thread is waiting, it releases that lock. That lets other threads do work in the meantime.

So the question "are threads faster?" has no single answer. It depends on what the job is waiting for: if it waits on the network, disk, or database, threads win; if it is computation, processes win.

For the next person who reads this

Pick four or more of the things you saw here and summarize them in 07-notes.md. Write not what you did but why it happens.

Imagine it is yourself, months from now, reading this while facing a performance problem. "I ran cProfile" does not help. "If the line with the big tottime is sleep, it is not a CPU problem — what you can fix is further down" does.