プログラムのある箇所が実行された時間や回数を計測するためのプロファイラについて、Python には標準で cProfile と profile があります。どちらも同じインタフェースを提供しており、通常は C の拡張でありオーバーヘッドの小さい cProfile を利用します。profile はプロファイラを拡張したいときに利用する C に依存していない実装です。

• The Python Profilers

cProfile

結果の読み方

#!/usr/bin/python
# -*- coding: utf-8 -*-

from cProfile import Profile
from time import sleep

def Main():
    pr = Profile()
    pr.runcall(sleep, 1)
    pr.print_stats()

if __name__ == '__main__':
    Main()

実行例

$ python sample.py 
         2 function calls in 1.004 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    1.004    1.004    1.004    1.004 {time.sleep}

• 関数が実行された回数は 2 回で 1.004 秒を要した
• 関数名の順に表示
• ncalls 各関数の実行回数
• tottime 各関数の実行に要した時間 (内部でサブ関数の実行に要した時間を除く)
• percall tottime / ncalls
• cumtime 各関数の実行に要した時間 (内部でサブ関数の実行に要した時間を含む)
• percall cumtime / ncalls

結果のファイルへの書き出しおよび利用

書き出し

#!/usr/bin/python
# -*- coding: utf-8 -*-

from cProfile import Profile
from time import sleep

def Main():
    pr = Profile()
    pr.runcall(sleep, 1)
    pr.dump_stats('sample.profile')

if __name__ == '__main__':
    Main()

読み込み

#!/usr/bin/python
# -*- coding: utf-8 -*-

from pstats import Stats

def Main():
    stats = Stats('./sample.profile')
    stats.sort_stats('cumtime') # 指定した情報でソートできます。
    stats.print_stats(10) # トップ10
    print stats.total_tt # tottime の合計

if __name__ == '__main__':
    Main()

RunSnakeRun

cProfile の出力結果を可視化するためのツールとしては RunSnakeRun が利用できます。

インストール

sudo apt install runsnakerun

可視化

runsnake sample.profile

今回は time.sleep がすべての実行時間を占めていますが、より複雑な状況では可視化できると便利です。