Python 3.15のprofiling.sampling—稼働中プロセスを実測する

Python 3.15 で python -m profiling.sampling attach <pid> が入りました。動いているプロセスに外から挿して、コードを1行も触らずスタックを取る。手元で測ったところ、cProfile が 3.22秒かけた同じ処理を 1.61秒で計測できました(素の実行は1.55秒)。

検証環境は Python 3.15.0b3(macOS 15 / Apple Silicon)。3.15.0 の正式リリースは2026年10月1日予定です。

cProfile を本番プロセスに挿せない理由

計測対象は、20万行の辞書を5回ぶん正規化して SHA-256 を取るだけのスクリプトです。

import hashlib
import json


def build_rows(n):
    return [{"id": i, "name": f"user-{i}", "score": i * 7 % 101} for i in range(n)]


def hash_row(row):
    blob = json.dumps(row, sort_keys=True).encode()
    return hashlib.sha256(blob).hexdigest()


def normalize(rows):
    out = []
    for r in rows:
        out.append({k: str(v).strip().lower() for k, v in r.items()})
    return out


def main():
    total = 0
    for _ in range(5):
        rows = build_rows(200000)
        normalized = normalize(rows)
        digests = [hash_row(r) for r in normalized]
        total += len(digests)
    print("rows:", total)


if __name__ == "__main__":
    main()

これを3通りで回した実測値。

計測方法	実行時間(real)	素の実行比
計測なし	1.55秒	1.00倍
profiling.sampling run(1kHz)	1.62秒	1.05倍
profiling.sampling run(50kHz)	1.69秒	1.09倍
profiling.tracing(=cProfile)	3.22秒	2.08倍

全呼び出しに割り込むと2倍遅くなる

cProfile が遅いのは仕様どおりです。関数の呼び出し・リターン・例外のたびにフックが走る。今回のスクリプトは 19,003,944回の関数呼び出しを記録していました。

python3.15 -m profiling.tracing -s tottime app.py

rows: 1000000
         19003944 function calls (19003812 primitive calls) in 3.181 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        5    0.685    0.137    0.998    0.200 app.py:14(normalize)
  1000000    0.506    0.000    0.506    0.000 encoder.py:207(iterencode)
  1000000    0.352    0.000    1.312    0.000 __init__.py:184(dumps)
  1000000    0.334    0.000    1.898    0.000 app.py:9(hash_row)
  1000000    0.287    0.000    0.913    0.000 encoder.py:185(encode)
        5    0.157    0.031    0.157    0.031 app.py:5(build_rows)

1.55秒の処理が3.22秒。増えた1.67秒はフックの分で、I/O 待ちの絶対時間は変わりません。待ちの比率だけが半分近くに薄まり、細かい関数呼び出しが太って見えます。

サンプリングは別プロセスから覗く

profiling.sampling はターゲットのメモリを外部から読み、一定間隔でスタックを撮ります。公式ドキュメントの “What is statistical profiling?” にあるとおり、対象プロセスは自分が観測されていることを知りません。同じスクリプトの結果がこちら。

python3.15 -m profiling.sampling run -l 6 --no-summary app.py

rows: 1000000
Captured 1538 samples in 1.54 seconds
Sample rate: 997.76 samples/sec
Error rate: 17.17
Warning: missed 3 samples from the expected total of 1541 (0.19%)
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        330/330      25.9       330.000      25.9       330.000  app.py:17(normalize)
        186/186      14.6       186.000      14.6       186.000  encoder.py:263(JSONEncoder.iterencode)
        154/651      12.1       154.000      51.1       651.000  app.py:10(hash_row)
        143/158      11.2       143.000      12.4       158.000  app.py:6(build_rows)
         95/414       7.5        95.000      32.5       414.000  __init__.py:241(dumps)
         71/74        5.6        71.000       5.8        74.000  __init__.py:237(dumps)

デフォルトは 1kHz。1.54秒で1538サンプル取れています。ここで出ている tottime は実測時間ではなく、サンプル数×サンプリング間隔からの推定値。上位の顔ぶれは tracing と一致しました。

1秒未満のスクリプトには向かない

サンプリングを選ばないほうがいい場面が、公式ドキュメントの “When to use a different approach” に明記されています。

For very short scripts that complete in under one second, the profiler may not collect enough samples for reliable results.

正確な呼び出し回数が要る場合も対象外です。統計サンプリングはサンプル間で終わった関数を取りこぼすので、ncalls に相当する値を出せません。1〜2%の差を見るマイクロベンチも timeit の担当。

macOS で最初に出る権限エラーを消す

インストール直後に run を叩くと、こうなります。

🔒 Permission Error: Unable to access process memory on macOS

Tachyon needs elevated permissions to profile processes. Try one of these solutions:

1. Try running again with elevated permissions by running 'sudo -E !!'.

2. If targeting system Python processes:
   Note: Apple's System Integrity Protection (SIP) may block access to system
   Python binaries. Consider using a user-installed Python instead.

外部プロセスのメモリを読む以上、OS の許可が要る。公式ドキュメントの “Platform requirements” では、macOS は task_for_pid() 経由なので root 権限・com.apple.security.cs.debugger entitlement・SIP 無効化のいずれかが必要と書かれています。Linux は ptrace か process_vm_readv、Windows は SeDebugPrivilege。

codesign で entitlement を付けて sudo を外す

sudo -E は動きますが、毎回パスワードを打つのは面倒で、CI からも呼べません。Python バイナリのコピーに自己署名で entitlement を付ければ、sudo なしで通ります。

cat > ent.plist <<'EOF'
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//Apple//DTD PLIST 1.0//EN" "http://www.apple.com/DTDs/PropertyList-1.0.dtd">
<plist version="1.0">
<dict>
    <key>com.apple.security.cs.debugger</key>
    <true/>
    <key>com.apple.security.get-task-allow</key>
    <true/>
</dict>
</plist>
EOF

BIN=~/.local/share/uv/python/cpython-3.15.0b3-macos-aarch64-none/bin
cp "$BIN/python3.15" "$BIN/python3.15-prof"
codesign -s - --entitlements ent.plist -f "$BIN/python3.15-prof"
codesign -d --entitlements - "$BIN/python3.15-prof"

/Users/moha/.local/share/uv/python/cpython-3.15.0b3-macos-aarch64-none/bin/python3.15-prof: replacing existing signature
Executable=/Users/moha/.local/share/uv/python/cpython-3.15.0b3-macos-aarch64-none/bin/python3.15-prof
[Dict]
	[Key] com.apple.security.cs.debugger
	[Value]
		[Bool] true
	[Key] com.apple.security.get-task-allow
	[Value]
		[Bool] true

コピーを別名にしたのは、元の python3.15 の署名を壊さないため。この python3.15-prof をプロファイラ側として使えば、以降の run も attach も権限エラーなしで動きます。SIP を切る必要はありません。ad-hoc 署名(-s -)で足りたのは検証時点の macOS 15 での話で、署名要件が変わればここは崩れます。

プロファイラと対象のバージョンを揃える

“Version compatibility” の制約が pre-release では厳しくなります。

Additional restrictions apply to pre-release Python versions: if either the profiler or target is running a pre-release (alpha, beta, or release candidate), both must run the exact same version.

3.14 のプロセスに 3.15 のプロファイラを繋ぐ、という使い方はできません。beta 同士でも b3 と b4 の組み合わせは弾かれる。free-threading ビルドと通常ビルドをまたぐのも不可です(Python 3.14のfree-threadingでGILを外すで扱ったビルドの話がここでも効いてきます)。

稼働中プロセスに attach して中を見る

ループのなかで time.sleep(0.3) を挟むワーカーをバックグラウンドで起動し、PID を控えます。

dump は今どこにいるかだけ返す

python3.15-prof -m profiling.sampling dump 33453

Stack dump for PID 33453, thread 36201411 (main thread, idle; most recent call last):
  File "worker.py", line 28, in <module>
    wait_for_io()
  File "worker.py", line 22, in wait_for_io
    time.sleep(0.3)

スレッドの状態(idle)まで出るので、「刺さっているのか、単にI/O待ちなのか」の一次判断はこれで足ります。-a で全スレッド、--native で C 側のフレームも混ぜられる。

attach は期間を区切って集める

-d で秒数を指定すると、そのあいだだけサンプルを取って終了します。対象プロセスは止まりません。

python3.15-prof -m profiling.sampling attach -d 5 -l 5 --no-summary 33453

Captured 5000 samples in 5.00 seconds
Sample rate: 999.31 samples/sec
Error rate: 2.56
Warning: missed 3 samples from the expected total of 5003 (0.06%)
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      3865/3865      79.3         3.865      79.3         3.865  worker.py:22(wait_for_io)
        259/259       5.3         0.259       5.3         0.259  worker.py:18(normalize)
        221/222       4.5         0.221       4.6         0.222  worker.py:10(build_rows)
        149/469       3.1         0.149       9.6         0.469  worker.py:14(hash_row)
        118/118       2.4         0.118       2.4         0.118  encoder.py:263(JSONEncoder.iterencode)

行番号が cProfile とずれる

同じ normalize が、tracing では app.py:14、sampling では app.py:17 と表示されます。14 は def の行、17 は内包表記の行。サンプリングはその瞬間に実行中だった行を記録するので、関数の入口ではなく重い行を指します。関数単位で慣れていると一瞬混乱しますが、行が分かるぶん絞り込みは速い。

wall と cpu でランキングが入れ替わる

上の attach 結果は wait_for_io が79.3%。time.sleep(0.3) がそのまま乗っています。これがデフォルトの wall モードで、CPU を使っていない時間も1サンプルとして数える挙動です。

sleep が上位を埋めて中身が見えない

DB クエリの応答待ちや外部 API のレスポンス待ちを挟むワーカーは、全部この形になります。待ちが長いほど CPU 側の処理は数%に押し込まれ、順位が読めない。上の出力でも normalize は5.3%どまりでした。

cpu モードで同じプロセスを測り直す

--mode cpu を付けると、スレッドが実際に CPU に乗っているサンプルだけを残します。プロセスは同じ、測り直しただけです。

python3.15-prof -m profiling.sampling attach -d 5 -l 5 --mode cpu --no-summary 33453

Captured 5000 samples in 5.00 seconds
Sample rate: 999.31 samples/sec
Error rate: 4.40
Warning: missed 3 samples from the expected total of 5003 (0.06%)
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        224/230      24.9       224.000      25.5       230.000  worker.py:18(normalize)
        189/190      21.0       189.000      21.1       190.000  worker.py:10(build_rows)
        163/418      18.1       163.000      46.4       418.000  worker.py:14(hash_row)
         94/228      10.4        94.000      25.3       228.000  __init__.py:241(dumps)
         69/69        7.7        69.000       7.7        69.000  encoder.py:263(JSONEncoder.iterencode)

wait_for_io が消え、normalize が5.3%から24.9%に上がりました。単位も秒からミリ秒に変わっている。5秒のうち CPU が動いていたのは約0.9秒だけ、という読み方になります。

公式ドキュメントの “Comparing wall-clock and CPU profiles” は、この2つを両方撮って突き合わせる使い方を勧めています。wall で待ちの絶対量を出し、cpu で削る関数を決める。cpu だけ見て normalize を半分にしても、5秒のうち3.9秒は time.sleep のまま残ります。

gil と exception はいつ使うか

--mode に指定できる値と、それぞれが数えるサンプル。

モード	数えるサンプル	使う場面
wall(既定)	すべて	レイテンシの内訳を見る
cpu	スレッドが CPU 上にあるとき	計算量の重い関数を特定する
gil	スレッドが GIL を保持しているとき	マルチスレッドで待たされている箇所を探す
exception	例外処理中	例外が制御フローに使われている箇所を洗う

gil は -a(全スレッド)と組み合わせないと意味が薄い。シングルスレッドのスクリプトに掛けても、手元では cpu とほぼ同じ並び(normalize 25.1%)になりました。

asyncio は –async-aware なしだとイベントループしか見えない

asyncio.gather でタスクを並べ、各タスクが SHA-256 を6万回まわすスクリプトを、まず素のサンプリングで測ります。

Captured 2072 samples in 2.08 seconds
Sample rate: 998.33 samples/sec
Error rate: 0.92
Profile Stats:
       nsamples   sample%   tottime (s)    cumul%   cumtime (s)  filename:lineno(function)
      1426/1433      69.5         1.426      69.8         1.433  selectors.py:548(KqueueSelector.select)
        555/555      27.0         0.555      27.0         0.555  async_app.py:13(crunch)
          57/57       2.8         0.057       2.8         0.057  async_app.py:12(crunch)

トップが KqueueSelector.select で69.5%。イベントループが次のイベントを待っている時間です。自分が書いたコードは crunch の27.0%だけ。cProfile でも同じで、tracing では {method 'control' of 'select.kqueue' objects} が1.439秒で首位に来ます。

–async-aware はタスク境界でスタックを組み直す

python3.15-prof -m profiling.sampling run --async-aware -l 6 --no-summary async_app.py

Captured 2074 samples in 2.08 seconds
Sample rate: 999.01 samples/sec
Error rate: 0.10
Profile Stats:
       nsamples   sample%  tottime (ms)    cumul%  cumtime (ms)  filename:lineno(function)
        557/557      89.8       557.000      89.8       557.000  async_app.py:13(crunch)
          57/57       9.2        57.000       9.2        57.000  async_app.py:12(crunch)
            2/2       0.3         2.000       0.3         2.000  events.py:94(Handle._run)
            1/5       0.2         1.000       0.8         5.000  :0(Task-35)
            1/1       0.2         1.000       0.2         1.000  async_app.py:6(fetch)
            1/2       0.2         1.000       0.3         2.000  base_events.py:2066(BaseEventLoop._run_once)

select が消え、crunch が27.0%から89.8%へ。<task>:0(Task-35) という行は実在の関数ではなく、タスク境界を示す合成フレームです。公式ドキュメントの “Task markers and stack reconstruction” にある挙動で、await をまたいだ呼び出し関係を論理的な流れとして復元してくれます。

複数タスクが同じコルーチンを通るとき、どのタスク由来のサンプルかがこのマーカーで分かれる。TaskGroup で組んだコードのボトルネックを追うときは、これが無いと gather の内側が全部ひとかたまりに見えます。

併用できないオプションがある

--async-aware は --native / --no-gc / --all-threads / --mode=cpu / --mode=gil と同時に指定できません。asyncio アプリの CPU 時間だけを見たい、という要求はモードでは満たせない。対象プロセスがプロファイル開始前に asyncio を import 済みであることも条件です。

サンプリングレートと出力形式

-r でサンプリングレートを上げても、実行時間はほとんど動きません。素の実行1.55秒に対して、1kHz が1.62秒、10kHz が1.70秒、50kHz が1.69秒。50kHz は既定の50倍のサンプル数(81,324個)を取りながら、オーバーヘッドは+9%に収まっています。

頭打ちも実測で見えます。100kHz は指定どおり99,999サンプル/秒が出ましたが、500kHz を指定すると Sample rate: 173044.56 samples/sec までしか届かない。指定値の約35%で、これ以上は取得側の限界です。なお 1mhz というサフィックスは受け付けません。

error: argument -r/--sampling-rate: Invalid sampling rate format: 1mhz.
Expected: number followed by optional suffix (hz, khz, k) with no spaces (e.g., 10khz)

レートを上げてよいのは非ブロッキング時だけです。--blocking(サンプル取得中に対象スレッドを止める)には公式ドキュメントに警告があり、間隔1000マイクロ秒(=1kHz)以上を推奨、既定の100マイクロ秒では対象アプリの目に見える減速を招くとされています。

flamegraph と heatmap

python3.15-prof -m profiling.sampling run --flamegraph -o flame.html app.py
python3.15-prof -m profiling.sampling run --heatmap -o hm app.py

Flamegraph data: 1 root function, 1270 total samples, 179 unique strings
Flamegraph saved to: flame.html

Heatmap output written to hm/
  - Index: hm/index.html
  - 3 source files analyzed

flamegraph は依存ライブラリなしの単一 HTML(実測 638,955バイト)。ズーム・検索が入っているので、そのままチャットに貼って共有できます。heatmap のほうはソースファイルごとに行単位のサンプル数を色分けした HTML を吐きます。Go の pprof でいう line-level の粒度。

binary で撮って replay で変換する

本番で撮るときは --binary が扱いやすい。可視化を後回しにするぶんサンプリングが速く、ファイルも小さくなります。

python3.15-prof -m profiling.sampling run --binary -o prof.bin app.py
python3.15-prof -m profiling.sampling replay --flamegraph -o out.html prof.bin

Binary profile written to prof.bin (1302 samples)
    Bytes (pre-zstd): 19.7 KB

Replaying 1302 samples from prof.bin
  Sample interval: 1000 us
  Compression: none
Flamegraph saved to: out.html
Replayed 1302 samples

1302サンプルで 21KB。同じ .bin から pstats・flamegraph・heatmap・Gecko(Firefox Profiler 形式)を後から生成できます。”Record and replay workflow” として公式が推している流れで、本番で撮って手元で開く運用に向いています。

profile は3.17で削除、cProfile はエイリアスとして残る

PEP 799 による再編で、既存モジュールの扱いが変わりました。

python3.15 -W error::DeprecationWarning -c "import profile"

DeprecationWarning: The profile module is deprecated and will be removed in
Python 3.17. Use profiling.tracing (or cProfile) for tracing profilers instead.

cProfile は警告なし。”Legacy compatibility” のとおり profiling.tracing のエイリアスとして残るので、cProfile.Profile is profiling.tracing.Profile は True を返します。既存コードの書き換えが要るのは、純 Python 実装の profile を使っている場合だけです。

まとめ

• profiling.sampling のオーバーヘッドは実測で+5%(1kHz)、50kHz でも+9%。profiling.tracing は2.08倍
• macOS は codesign -s - --entitlements で com.apple.security.cs.debugger を付ければ sudo なしで動く。SIP を切る必要はない
• pre-release 同士では、プロファイラと対象が完全に同じバージョンでないと attach できない
• 待ち時間を含むワーカーは wall と --mode cpu の両方を撮る。今回は上位が wait_for_io 79.3% から normalize 24.9% に入れ替わった
• asyncio アプリは --async-aware 必須。付けないと KqueueSelector.select が69.5%を占めて自分のコードが埋もれる
• 正確な呼び出し回数が要るとき、1秒未満のスクリプト、1〜2%を争うマイクロベンチは profiling.tracing か timeit の担当
• profile モジュールは3.17で削除。cProfile は残る

3.15 は lazy import(PEP 810) のような言語仕様の変更が目立ちますが、運用側の変化はこのプロファイラのほうが大きい。動いているプロセスに後から挿せる計測手段が標準に入ったので、py-spy を別途入れる理由がひとつ減りました。