はじめに
処理が遅いプログラムをCythonで書き直したところ、あまり速度が速くならなかったためcProfileでプロファイリングしてみたところ
20925863 function calls (17411183 primitive calls) in 5.887 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
3251079/29289 2.895 0.000 5.794 0.000 copy.py:132(deepcopy)
2928900 0.195 0.000 0.195 0.000 copy.py:190(_deepcopy_atomic)
322179/29289 1.215 0.000 5.710 0.000 copy.py:210(_deepcopy_list)
322179 0.191 0.000 0.248 0.000 copy.py:252(_keep_alive)
28771 0.034 0.000 0.053 0.000 random.py:223(_randbelow)
28771 0.035 0.000 0.093 0.000 random.py:255(choice)
3924726 0.300 0.000 0.300 0.000 {built-in method builtins.id}
28771 0.005 0.000 0.005 0.000 {built-in method builtins.len}
3514680 0.309 0.000 0.309 0.000 {method 'append' of 'list' objects}
28771 0.005 0.000 0.005 0.000 {method 'bit_length' of 'int' objects}
6502158 0.689 0.000 0.689 0.000 {method 'get' of 'dict' objects}
44878 0.015 0.000 0.015 0.000 {method 'getrandbits' of '_random.Random' objects}
ということで処理にかかる時間の大半をcopy.deepcopyが占めていたということがわかりました。コピーしているオブジェクトは2次元のリストです。ncallsの列を見ると深いコピーが再帰的に処理されていることがわかります。
検証
調べたところcPickleモジュールを使って直列化できる場合は、dumpsとloadsを使用してコピーしたほうが速いらしい。
下のコードで時間を計測してみました
import copy
import _pickle as cPickle
import cProfile
def f1():
obj = [[k * j for k in range(10)] for j in range(10)]
for i in range(10000):
copy.deepcopy(obj)
def f2():
obj = [[k * j for k in range(10)] for j in range(10)]
for i in range(10000):
cPickle.loads(cPickle.dumps(obj, -1))
cProfile.run("f1()")
cProfile.run("f2()")
結果
7090005 function calls (5890005 primitive calls) in 1.662 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1.662 1.662 <string>:1(<module>)
1110000/10000 0.817 0.000 1.653 0.000 copy.py:132(deepcopy)
1000000 0.056 0.000 0.056 0.000 copy.py:190(_deepcopy_atomic)
110000/10000 0.343 0.000 1.634 0.000 copy.py:210(_deepcopy_list)
110000 0.048 0.000 0.065 0.000 copy.py:252(_keep_alive)
1 0.008 0.008 1.662 1.662 measurement.py:6(f1)
1 0.000 0.000 0.000 0.000 measurement.py:7(<listcomp>)
1 0.000 0.000 1.662 1.662 {built-in method builtins.exec}
1340000 0.090 0.000 0.090 0.000 {built-in method builtins.id}
1200000 0.087 0.000 0.087 0.000 {method 'append' of 'list' objects}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
2220000 0.211 0.000 0.211 0.000 {method 'get' of 'dict' objects}
20005 function calls in 0.068 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.068 0.068 <string>:1(<module>)
1 0.006 0.006 0.068 0.068 measurement.py:12(f2)
1 0.000 0.000 0.000 0.000 measurement.py:13(<listcomp>)
10000 0.033 0.000 0.033 0.000 {built-in method _pickle.dumps}
10000 0.029 0.000 0.029 0.000 {built-in method _pickle.loads}
1 0.000 0.000 0.068 0.068 {built-in method builtins.exec}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
cPickleを使ってコピーしたほうが圧倒的に速い結果となりました。
おわりに
今回学んだことなど
- copy.deepcopyは遅い
- cPickleを使うとcopy.deepcopyより高速にコピーできる
- cProfileは便利
- プロファイリングツールでボトルネックとなってる処理を特定してから対処しよう
Cythonで書き直したら速くはなったが、cPickleを使ってコピーするように変更したところ、上のはじめにで言及したプログラムは大幅に高速化したので闇雲に対処するよりボトルネックとなっている処理を特定してから対処していくことが大事だと感じました。
対処できなかった現象
最後に、Cythonで書き直したコードを.pyx内でプロファイリングしたところ一部の関数は呼び出されているのにプロファイリングされていない現象が起こったので書きます。
はじめにで言及したプログラムではCythonの.pyxファイル内のクラスのプロファイリングしたい関数の前後に下のコードのように
prf = cProfile.Profile()
prf.enable()
# プロファイリングしたい関数
prf.disable()
prf.print_stats()
処理を挟んでプロファイリングしたところ、同じクラス内のメンバ関数などの一部の関数は呼ばれているのにプロファイリングされていない現象が発生した。はじめにのプロファイリング結果だと5.887秒の処理になっているが、関数内で呼び出されているのにプロファイリングされていない処理があるため実際のプロファイリングしたい関数の処理時間はプロファイリング結果より長いです。また、上の検証結果では表示されている"{built-in method _pickle.dumps}"や"{built-in method _pickle.loads}"の行も.pyx内でのプロファイリングでは表示されなくなりました。Pure Pythonの同じコード、測定方法を試したところ、プロファイリングしたい関数が呼び出している他のメンバ関数もプロファイリングされていました。
原因や対処法が分かる人がいればコメント等で教えてくれると嬉しいです。