0
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

Python 3.15のTachyonで短い関数を見落とす理由

0
Posted at

Python 3.15のTachyonで短い関数を見落とす理由

Python 3.15のTachyonでプロファイルを取っても、短い関数がほとんど表示されないことがあります。
これは処理が軽い証拠とは限りません。samplingは一定間隔でスタックを観測するため、すべての呼び出しを記録するわけではないからです。
ホットスポット探索にはsampling、呼び出し回数の確認にはtracing、短い処理の速度比較にはtimeitを使い分けます。
同じPythonコードを3通りで測り、計測方法を切り替える境界を確認します。

Tachyonで短い関数を測ってみる

Python 3.15では、統計的プロファイラのTachyonがprofiling.samplingとして標準ライブラリに追加されました。

2026年10月2日に3.15.0rc3が公開され、10月9日には3.15.0正式版が公開されています。

Tachyonは対象プロセスの外側からスタックを読み取り、実行時間の分布を推定します。関数呼び出しごとに計測処理を挟まない点が特徴です。

ただし、短い関数の実行時間を正確に測れるかは別の問題です。

次のworkload.pyを用意します。

実行環境はCPython 3.15.0、追加パッケージなしです。

# workload.py
import sys

def short_task():
    total = 0
    for i in range(300):
        total += i * i
    return total

def long_task():
    total = 0
    for i in range(2_000_000):
        total += i * i
    return total

def run(short_calls=100):
    result = 0
    for _ in range(short_calls):
        result += short_task()
    result += long_task()
    return result

if __name__ == "__main__":
    count = int(sys.argv[1]) if len(sys.argv) > 1 else 100
    print(run(count))

short_task()は小さなループ、long_task()は大きなループです。

short_task()が数十マイクロ秒程度で終わることを想定していますが、実行時間はCPUやPythonのビルドによって変わります。

まずsamplingを実行します。

python --version
python -m profiling.sampling run --mode=cpu workload.py 100

デフォルトのサンプリングレートは1kHzで、約1ミリ秒間隔の観測を試みます。

ここで確認したいのは、short_task()とlong_task()がどの程度の割合で現れるかです。

long_task()は長く実行されるため、多数のサンプルに含まれる可能性があります。一方、short_task()は観測時点に実行されていなければ記録されません。

短い関数の呼び出しを増やして比較します。

python -m profiling.sampling run --mode=cpu workload.py 1000
python -m profiling.sampling run --mode=cpu workload.py 10000

呼び出し回数を増やすと、short_task()の合計CPU時間も増えます。十分なサンプルが集まれば、短い関数でもホットスポットとして現れます。

つまり、短い関数が必ず見えないわけではありません。

重要なのは、1回の実行時間と、観測期間全体で消費した時間を区別することです。

サンプリング間隔より短い関数はどう見えるか

Python 3.15のTachyonで短い関数を見落とす理由

samplingが記録するのは関数の呼び出し履歴ではなく、一定の時点で取得したスタックのスナップショットです。

例えば、1ミリ秒ごとに観測している間に、ある関数が50マイクロ秒で終了したとします。

その関数の実行区間が観測時点と重ならなければ、サンプルには登場しません。

ただし、同じ関数を何万回も呼び出せば、観測時点に実行されている確率が高くなります。

単純化すると、関数が全CPU実行時間の割合pを占め、独立したサンプルをN個取得できる場合、期待されるヒット数は次のようになります。

期待ヒット数 = N × p

独立な観測を仮定すると、1回も観測されない確率は次のように近似できます。

未観測確率 = (1 - p) ** N

実際のサンプリングは完全に独立とは限りません。周期的な処理と観測タイミングが重なる偏りもあります。

また、Tachyonの時間表示は各関数をストップウォッチで測った値ではありません。サンプル数と観測間隔から推定した時間です。

そのため、表示された値を関数1回あたりの厳密な実行時間として扱うのは誤りです。

サンプリングレートを変更して比較することもできます。

python -m profiling.sampling run -r 1khz --mode=cpu workload.py 10000
python -m profiling.sampling run -r 20khz --mode=cpu workload.py 10000

レートを上げれば観測機会は増えますが、収集側のCPU負荷も増えます。指定したレートで実際にサンプルを取得できるとは限りません。

--realtime-statsを付ければ収集状況も確認できます。

なお、Tachyonのデフォルトはwall-clockモードです。今回はCPU計算を比較するため、待機時間を除外する--mode=cpuを明示しています。

tracingで呼び出し回数を確定する

samplingでshort_task()が見えなくても、呼び出されていないとは判断できません。

そこでprofiling.tracingを使います。

これは関数の呼び出しや復帰を記録する決定的プロファイラです。Python 3.15では、従来のcProfileに相当する機能を新しい名前でも利用できます。

同じスクリプトを実行します。

python -m profiling.tracing -s cumulative workload.py 100
python -m profiling.tracing -s cumulative workload.py 1000

出力のncallsに注目します。

short_task()の呼び出し回数は、引数を100にすれば100回、1000にすれば1000回です。long_task()はどちらも1回です。

tracingは関数呼び出しのイベントを記録するため、短時間で終了する関数でも回数を確認できます。

一方、計測処理自体が実行時間に加わる点には注意が必要です。

特に短い関数を大量に呼ぶプログラムでは、追跡のオーバーヘッドが無視できなくなります。

出力される主な項目は次のとおりです。

項目 意味
ncalls 呼び出し回数
tottime 子関数の時間を除いた実行時間
cumtime 子関数の時間を含む累積時間

tracingは呼び出し関係の調査に向いていますが、関数本来の実行速度を測るには別の方法が必要です。

timeitで短い処理の差を測る

短い関数の速度を比較したい場合は、timeitに切り替えます。

先ほどのworkload.pyを使い、別ファイルbench.pyを作ります。

# bench.py
from statistics import median
from timeit import repeat
from workload import short_task

def measure(calls, repeats=7):
    samples = repeat(
        stmt="short_task()",
        globals={"short_task": short_task},
        number=calls,
        repeat=repeats,
    )
    per_call_us = [t / calls * 1_000_000 for t in samples]
    return min(per_call_us), median(per_call_us)

for calls in (100, 1000, 10000):
    best, middle = measure(calls)
    print(
        f"calls={calls:5d} "
        f"best={best:.3f}us "
        f"median={middle:.3f}us"
    )

実行します。

python bench.py

指定した回数だけ関数を繰り返し実行し、合計時間を呼び出し回数で割ります。

bestは7回の測定の最小値、medianは中央値です。単位はマイクロ秒です。

timeitには関数呼び出しやループ制御のコストも含まれます。関数本体だけの純粋な実行時間ではありません。

また、numberを増やしても関数自体が高速化するわけではありません。まとめて測ることで、タイマーの分解能や一時的な変動の影響を相対的に小さくします。

例えば、short_task()のループを別の実装に置き換えた場合、変更前後で同じ入力と実行環境を使い、timeitで比較します。

samplingで微小な差を読み取るより、比較対象を限定した方が判断しやすくなります。

ただし、1〜2%程度の差では測定ノイズが支配的になる場合があります。実行順序を入れ替える、測定を繰り返す、CPU負荷を抑えるといった条件管理も必要です。

計測方法を切り替える判断基準

3つの方法は、同じ性能計測でも答えられる問いが異なります。

知りたいこと 選ぶ方法
実行時間を多く消費する箇所 profiling.sampling
関数の正確な呼び出し回数 profiling.tracing
短い関数の速度比較 timeit
呼び出し関係の調査 profiling.tracing
稼働中プロセスのホットスポット profiling.sampling

業務システムの性能を調べる場合も、最初からすべての関数を個別に計測する必要はないと考えています。

まずsamplingで全体の時間配分を調べます。負荷の大きい処理を特定したら、必要に応じてtracingで呼び出し関係を確認します。

改善候補が数十マイクロ秒程度の関数なら、最後にtimeitで実装同士を比較します。

ただし、timeitの結果が良くても、アプリケーション全体が速くなるとは限りません。

関数1回の処理が速くなっても、呼び出し回数が少なければ効果は限定的です。逆に短い関数でも、何百万回も実行されれば合計時間は無視できません。

また、CPU使用状況とI/O待機を含む応答時間では、samplingのcpuとwallの選択も変わります。

プロファイラが見せているのは、選択した観測方法で得られた実行の一面です。

Tachyonで関数が見えないことを、最適化不要という判断につなげない方がよいでしょう。

今回の例は単一スレッドのCPU処理です。I/O待機、複数スレッド、C拡張を含む処理では観測結果の意味が変わります。特に複数スレッドでは、Tachyonのデフォルトがメインスレッドのみの観測である点にも注意が必要です。実際の処理に適用するなら、まずsamplingの収集状況とCPU時間の分布を確認し、改善対象を絞ってからtimeitで比較するのがよいと考えています。

参考

0
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
0
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?