Python のプロファイリング実測：本当に速くなった最適化

シリーズ：Python 講座 6/6（上級）。 Python のコードは動くけれど遅い、そして小技の一覧ではなく「手順」を知りたい人向けです。読み終えると、測る → 本当のホットスポットを見つける → 直す → 直ったことを証明する、という流れを自分で回せるようになり、無視してよい「高速化の定番」も見分けられます。

社内のログ集計スクリプトが夜間バッチの時間内に終わらない。速くしようとループを三つ書き直したのに、ほとんど変わらなかった。この講座はそういう経験のある人のためのものです。わざと遅く書いたプログラムを一つ用意し、プロファイルを取り、段階ごとに時間を測りながら直していきます。結果を先に書くと、変更一つでプログラム全体が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 には Python レベルの関数呼び出しごとにオーバーヘッドがある点に注意してください。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 が最速だったのは、要素ごとに Python のフレームが動かないためで、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 側に移す工夫は効き、Python の書き方を入れ替えるだけの工夫はたいてい効きません。

メモリ：tracemalloc

コストは時間だけではありません。normalize は全単語をつないだ大きな文字列を作り、そこからリストを作ります。tracemalloc で Python が確保したメモリを測ります。

# 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 のログファイルなら、これが「動く」と「OOM で落ちる」の差になります。ジェネレーターの詳しい話は第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回） ・ Java の JIT・GC・メモリ ・ ソートアルゴリズム