paiza開発日誌

IT/Webエンジニア向け総合求人・学習サービス「paiza」(https://paiza.jp ギノ株式会社)の開発者が開発の事、プログラミングネタ、ITエンジニアの転職などについて書いています。

Pythonの処理が遅いときにプロファイラを使って原因を調べる方法

f:id:paiza:20180907185100j:plain
Photo by William Warby
秋山です。Pythonエンジニアです。

Pythonは動作がすっごく速い言語というわけではないので、大きめのデータを処理したりしようとすると「なんか遅いよな」と感じることがあると思います。

Pythonの処理を「もうちょっと速くしたい…」というときは、どうすればいいと思いますか?

処理を単純化したり、for文をリスト内包表記にしたり、アルゴリズムを変えたり、単純にPCをスペックを高いものに変えるとか……まぁいろいろ対処法はあるわけですが、そもそも処理が遅いなら、「どこがどう遅いのか」を特定したほうがいいですよね。プログラミングをしていると、意外な処理に結構な時間がかかっていることに全然気付いてなかった…ということもありますから。

というわけで今回は、Pythonで処理が遅い部分を特定する方法についてやっていきたいと思います。

■Pythonプロファイラを使ってみる

◆再帰

とりあえず、わかりやすくフィボナッチ数を求めるプログラムで試してみましょう。

特に処理速度などは考えず、単純に再帰で組んでみるとこんな感じのコードになります。

paiza.ioで動かしてみると、と fib(37) で37番目のフィボナッチ数を求めるのが限界ですね…。

再帰なので、何回ぐらい計算してるんだろう?といったことはすぐにはわからないですね。ここはPythonプロファイラの cProfile を使って見てみましょう。

cProfile.run()で呼び出すだけで、プロファイル結果が出てきます。説明のためにfib(30)を2回呼び出してみています。

         5385078 function calls (6 primitive calls) in 3.795 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    3.795    3.795 <string>:1(<module>)
5385074/2    3.795    0.000    3.795    1.898 Main.py:3(fib)
        1    0.000    0.000    3.795    3.795 Main.py:9(main)
        1    0.000    0.000    3.795    3.795 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

一番上に、何回関数呼び出しをしたということと、秒数が出てきます。 5385078 回呼び出しているようですね。

下には、呼び出した関数別の結果が出ています。

左から順に
ncalls は回数、/で分割された左側がfib自体が呼ばれた総回数、右側がfib(30)などで1回とカウントしたもの(プリミティブな呼び出し回数)
tottime は関数の実行時間(別の関数呼び出しは除外してます)
percall は tottime / ncalls
cuttime はその関数と別の関数呼び出しを含めた累積時間
percall …またpercallが出てきましたが、これはcuttimeをプリミティブな呼び出し回数で割ったもの
という感じです。

◆メモ化再帰

では、せっかくなのでフィボナッチ数列の最適化をしながら、このプロファイル結果がどう変化していくのかを見ていきましょう。

このコードでは、メモ化再帰を雑にしてみました。

結果は以下のとおりです。

         2692600 function calls (6 primitive calls) in 1.908 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.907    1.907 <string>:1(<module>)
     59/1    0.000    0.000    0.000    0.000 Main.py:10(fib_memo)
        1    0.000    0.000    1.907    1.907 Main.py:19(main)
2692537/1    1.907    0.000    1.907    1.907 Main.py:3(fib)
        1    0.000    0.000    1.908    1.908 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

もとのfib()は2692537回も呼び出されていますね。一方で、 fib_memo() はたった59回となっています。

このような感じで処理が入り乱れている場合は、「どの関数の呼び出し回数が多いのだろう?」(≒時間がかかっているのだろう?)といった感じで見ることができます。

ちなみに percall を見ると、当然ですがフィボナッチ数の足し算引き算程度は大した時間がかからないので0となっています。

◆sleep追加

次に、sleepとか入れてみました。

       59    5.911    0.100    5.911    0.100 {built-in method time.sleep}

と、実際に0.1 秒sleepさせた場合はちゃんと0.1と出て、今回はわざと59回呼ばれる fib_memo で呼び出したので、合計で 5.911 秒かかっていることがわかりますね。

◆Numpy使用時

今度は、Numpyを使った場合にどんな計測結果になるかを見てみましょう。

これもフィボナッチ数を求めています。一般項をそのまま式にしても意味がないので、行列表現の方をNumpyで試してみました。(フィボナッチ数 - Wikipedia


         55 function calls in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap>:996(_handle_fromlist)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 Main.py:4(fib_mat)
        1    0.000    0.000    0.000    0.000 defmatrix.py:100(matrix_power)
        1    0.000    0.000    0.000    0.000 defmatrix.py:246(__new__)
        8    0.000    0.000    0.000    0.000 defmatrix.py:292(__array_finalize__)
        1    0.000    0.000    0.000    0.000 defmatrix.py:314(__getitem__)
        1    0.000    0.000    0.000    0.000 defmatrix.py:355(__pow__)
        1    0.000    0.000    0.000    0.000 numeric.py:2118(binary_repr)
        1    0.000    0.000    0.000    0.000 numeric.py:2188(<listcomp>)
        1    0.000    0.000    0.000    0.000 numeric.py:484(asanyarray)
        1    0.000    0.000    0.000    0.000 numerictypes.py:660(issubclass_)
        1    0.000    0.000    0.000    0.000 numerictypes.py:728(issubdtype)
        1    0.000    0.000    0.000    0.000 {built-in method __new__ of type object at 0xa3ee00}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        2    0.000    0.000    0.000    0.000 {built-in method builtins.hasattr}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.hex}
       12    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
        2    0.000    0.000    0.000    0.000 {built-in method builtins.issubclass}
        3    0.000    0.000    0.000    0.000 {built-in method builtins.len}
        2    0.000    0.000    0.000    0.000 {built-in method numpy.core.multiarray.array}
        7    0.000    0.000    0.000    0.000 {built-in method numpy.core.multiarray.dot}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'lstrip' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'mro' of 'type' objects}

Numpyでの呼び出しなどが見えますね。Numpyなどのライブラリを使っていろいろ計算している人だと、「なんか遅いけど何が遅いんだ?」と思うことも結構あるかと思いますが、こんなふうにプロファイラを使って見てみるといいですよ。

適当にNumpyの関数を並べたりループしたりしてみましょう。

np.linalg.inv(m) にすごい時間かかっているのが一目瞭然ですね。

      100    0.001    0.000    0.001    0.000 linalg.py:198(_assertRankAtLeast2)
      100    0.001    0.000    0.001    0.000 linalg.py:209(_assertNdSquareness)
      100   12.351    0.124   12.356    0.124 linalg.py:458(inv)
      100    0.000    0.000    0.000    0.000 numeric.py:414(asarray)
      200    0.000    0.000    0.001    0.000 numeric.py:484(asanyarray)

行列計算やNumpyになじみがある人にとっては、逆行列を算出するのは時間がかかる!というのは暗黙の了解みたいなところもあるかもしれませんが、初心者の人とかだとこうやって可視化することで気付けることもあると思います。

■まとめ

こんな感じで、「なんか処理が遅いなぁ」と思ったら、プロファイラをちょっと試してみると発見があるかもしれません。

ちなみにソースコード自体をプロファイルしたいときは

    python -m cProfile program.py

とコマンドを打つだけでも使えるので、自分で作ったプログラムのボトルネックをざっくり探すには十分かと思います。(標準機能でちょっと貧弱なところもありますけど)

プロファイラにはほかにもいろいろな使い方があるので、気になる方はPython公式ドキュメントをあたってみてください。

27.4. Python プロファイラ — Python 3.6.5 ドキュメント

あと、これまでもPythonに関する記事や機械学習に関する記事をいろいろ書いているので、気になった人はぜひ見てみてください。
paiza.hatenablog.com
paiza.hatenablog.com


「Pythonを使えるようになりたい!」という方は、プログラミングが動画で学べる「paizaラーニング」の「Python入門編」(今年から全編無料になりました)から始めてみてください。先日新しく「Python入門編9: さらにクラスを理解しよう」が追加されました。

paizaラーニング





paizaラーニング」では、未経験者でもブラウザさえあれば、今すぐプログラミングの基礎が動画で学べるレッスンを多数公開しております。

詳しくはこちら

paizaラーニング

そしてpaizaでは、Webサービス開発企業などで求められるコーディング力や、テストケースを想定する力などが問われるプログラミングスキルチェック問題も提供しています。

スキルチェックに挑戦した人は、その結果によってS・A・B・C・D・Eの6段階のランクを取得できます。必要なスキルランクを取得すれば、書類選考なしで企業の求人に応募することも可能です。「自分のプログラミングスキルを客観的に知りたい」「スキルを使って転職したい」という方は、ぜひチャレンジしてみてください。

詳しくはこちら

paizaのスキルチェック