【忙しい人向け】cProfileの便利な使い方【ボトルネック探しにめちゃくちゃ便利】

  • 2022年7月6日
  • 2022年7月7日
  • python
  • 170view

pythonの標準プロファイラであるcProfileの使い方を簡単に説明します

cProfileを使用することでプログラムのボトルネックを簡単に特定することができます

ボトルネック:プログラムの中の処理能力が一番低い箇所

この記事を読むとわかること・・

  • cProfileの使い方
  • snakevizの使い方
  • cProfileとProfileの違い
おへんじ
具体例を使って説明するよ

cProfileの使い方

さっそくcProfileの使い方を説明していきます

まず、cProfileの主な使い方は以下の2つです

  1. プログラムファイル(.py)のコードの中にcProfileを書き込む方法
  2. ターミナル(コマンドプロンプト)でプログラムを実行するときにcProfileを使用する方法
おへんじ
今回はターミナルでcProfileを使用する方法を紹介するよ

プログラム全体の処理時間を計測したい場合は、ターミナルでcProfileを使用する方法が適しています

1.cProfileの使い方手順

まず、以下のようなsample.pyファイルがあったとします

# coding: UTF-8

import time


def main():

    print(1)
    time.sleep(1)  # 1秒待機
    print("----------")

    print(2)
    time.sleep(2)  # 2秒待機
    print("----------")

    print(3)
    time.sleep(3)  # 3秒待機
    print("----------")


if __name__ == '__main__':
    main()

これをターミナルで普通に実行するとき

$ python sample.py
(実行結果)
1
----------
2
----------
3
----------

cProfileを使用して実行するときは

$ python -m cProfile sample.py
(実行結果)
1
----------
2
----------
3
----------
         13 function calls in 6.009 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    6.009    6.009 sample.py:3(<module>)
        1    0.000    0.000    6.009    6.009 sample.py:6(main)
        1    0.000    0.000    6.009    6.009 {built-in method builtins.exec}
        6    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        3    6.009    2.003    6.009    2.003 {built-in method time.sleep}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

このようにファイルを実行するコードを少し変えるだけでcProfileを使用することができます

一度普通にプログラムが実行されて、その後処理にかかった時間などが表示されます

cProfileを使用してプログラムを実行すると

  1. プログラム実行時間
  2. 関数呼び出し回数・関数ごとの処理時間

を簡単に把握することができます

それぞれの項目の意味は

  • ncalls : 呼び出された回数
  • tottime : 関数処理にかかった合計時間(subfunctionの呼び出しにかかった時間は除く)
  • percall : tottime ➗ ncalls
  • cumtime : 関数処理と全てのsubfunctionに消費された累積時間
  • percall : cumtimeを呼び出し回数で割った値
  • filename : 関数のファイル名、行番号、関数名

となっています

2.cProfileのオプションについて

cProfileは実行する際にオプションを設定することができます

$ python -m cProfile [-o output_file] [-s sort_order] myscript.py
  • -o : cProfile結果をファイルに書き出すときに使用する(cProfile結果がターミナルに標準出力されない)
  • -s : 出力をソートする値を指定できる(-o を使用していない場合に有効)

各オプションを使用するときの例をみてみましょう

-o オプションを使用する場合(例)

# coding: UTF-8

import time


def main():

    print(1)
    time.sleep(1)  # 1秒待機
    print("----------")

    print(2)
    time.sleep(2)  # 2秒待機
    print("----------")

    print(3)
    time.sleep(3)  # 3秒待機
    print("----------")


if __name__ == '__main__':
    main()
$ python -m cProfile -o sample.profile sample.py
sample.profile : cProfileの出力結果が書き出されるファイル(任意のファイル名でOK 。拡張子も任意でOK)

おへんじ
拡張子はcProfileの出力結果だってことがわかるように『.prof』や『.stats』がおすすめだよ
(実行結果)
1
----------
2
----------
3
----------
-oオプションを使用する場合は、cProfileの結果はターミナル上には出力されません

出力結果が格納されているsample.profileはsample.pyが格納されているディレクトリに書き出されます

-s オプションを使用する場合 (例)

$ python -m cProfile -s tottime sample.py
tottime : ここで選択した項目で出力結果がソートされる
(実行結果)
1
----------
2
----------
3
----------
  13 function calls in 6.013 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        3    6.013    2.004    6.013    2.004 {built-in method time.sleep}
        6    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    6.013    6.013 sample.py:6(main)
        1    0.000    0.000    6.013    6.013 sample.py:3(<module>)
        1    0.000    0.000    6.013    6.013 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

tottimeを指定しているからtottimeの値が大きい順に並べられている

ソートできる項目は以下のとおり(公式の表より)

snakevizの使い方

snakevizはcProfileの出力結果を図で表示することができます

  • cProfileの出力結果が書き出されたファイルが必要(-o オプションにより書き出しておく必要がある)
  • インストールが必要

標準ライブラリではないため別途インストールする

$ pip install snakeviz

先ほど上で書き出したsample.profileをsnakevizで表示してみる

$ snakeviz sample.profile
sample.profile : cProfileの出力結果が書き出されたファイル

(実行結果)

実行すると上記のページが表示される
  • カーソルを図の上に移動すると、それぞれの関数の処理時間などが表示される
  • ページしたのnacallsやtottimeはクリックすることで、昇順・降順に並べ替えることができる

sample.pyは単純なプログラムのため、より複雑なプログラムの出力結果は

みればわかる複雑なやつやーん笑 って感じになります。(失礼しました)

おへんじ
プログラムが複雑になるほどsnakevizが便利だと感じるよ

cProfileとProfileの違いについて

ボトルネックを特定する方法としてよくProfilecProfileが挙げられます

どちらもpythonの標準プロファイリングツールであり

プログラムの処理時間等を計測するためのツールです

これらの違いを超ざっくりまとめると

10ファイル程度両方を使用して試してみましたが

全てのファイルにおいてcProfileの方が処理が早く終わりました

内部的な仕組み等は詳しくはわかりませんが 、cProfileを使用しておけば、問題なさそうです


まとめ

cProfileとは

  • プログラムのボトルネックを特定できる便利なツール

snakevizを使うと

  • cProfileの出力結果を可視化できる

cProfileとProfileの違い

  • cProfile(c言語)・Profile(python)

  • 基本的にcProfileが処理速度が速い

  • cProfileを使用しておけば問題ない

cProfileについて理解できたでしょうか?

今回は紹介しませんでしたが、行ごとに処理時間を計測できるline_profiler

リアルタイムで計測結果を確認できるpy_spyなどのプロファイラもありますので

そちらも使って自分に合うプロファイラを使用することをオススメします

ohenziblogはプログラミングを独学で始めるための徹底ガイドを目指しています

最新情報をチェックしよう!