Notebook の %%time で FireDucks の時間計測をするときの落とし穴

FireDucks 開発チームの大道です．今回の開発者ブログでは時間計測のちょっとした落とし穴についてご紹介したいと思います．

まずは結論

IPython Notebook で提供されている %%time マジックコマンドで FireDucks の時間計測をするときも，必ず _evaluate() メソッドを呼んで確実に評価が行われるようにしましょう！

%%time
df = pd.read_csv("input.csv")
df._evaluate()

Notebook における時間計測

Jupyter などの IPython Notebook では，コードを書いたセルの実行時間を測定するために %%time というマジックコマンドが提供されています．ちなみにパーセント記号ひとつの %time だとその行だけの実行時間の計測で，パーセント記号ふたつの %%time だとセルの実行時間の計測です．FireDucks は pandas と同じ API で pandas よりも高速に処理できることが特徴ですので，処理時間を計測してみた方や計測してみたいと思った方もいらっしゃるでしょう．

しかし…，おや？ 以下の処理時間計測は正しいのでしょうか？

import fireducks.pandas as pd

%%time
df = pd.read_csv("sample-dataset-tips.csv")
df.head()

CPU times: user 3.37 ms, sys: 4.06 ms, total: 7.43 ms
Wall time: 6.87 ms

	total_bill	tip	sex	smoker	day	time	size
0	16.99	1.01	Female	No	Sun	Dinner	2
1	10.34	1.66	Male	No	Sun	Dinner	3
2	21.01	3.50	Male	No	Sun	Dinner	3
3	23.68	3.31	Male	No	Sun	Dinner	2
4	24.59	3.61	Female	No	Sun	Dinner	4

FireDucks の時間計測

実行モデルの解説ページに記載している通り，FireDucks は遅延実行モデルを採用しています．簡単に言うと FireDucks のデータフレームは，例えば print() や display() で画面に表示させたり，データフレームの _evaluate() メソッドを明示的に呼んだりするまでは，実際の処理が始まらずに溜め込まれた状態のままになるのです．FireDucks は溜め込んでいた処理を実行する前に最適化を行うことでより高速に処理できるようになっており，溜め込んでいた処理を実際に実行することを「評価」と呼びます．

ところで，IPython Notebook ではセルの最後に代入文ではなく値が置かれていると，Python インタープリターの REPL と同様に，値が自動で画面に出力されます．つまり IPython 的に言うと自動的に display() が呼ばれているということであるため，FireDucks のデータフレームはセルの最後に置いておけば自動で評価もされるということになります．

df = pd.read_csv("sample-dataset-tips.csv")
df = df.sort_values(by="tip")
df  # ← これ

しかし，マジックコマンド %%time で処理時間を計測したい場合にはちょっとした落とし穴がありました．FireDucks データフレームをセルの最後に置いておけば自動で評価されるということと，それで正しい時間が計測できているかということは別の問題だったのです．

誤った時間計測の例

10GB 弱の csv ファイルを用意して実験してみました．以下のようなセルを実行すると奇妙なことが起こります．

%%time
df = pd.read_csv("sample-dataset-tips10gb.csv")
df = df.sort_values(by="tip")
df

CPU times: user 18.2 ms, sys: 4.31 ms, total: 22.5 ms
Wall time: 15.2 ms

	total_bill	tip	sex	smoker	day	time	size
67	3.07	1.0	Female	Yes	Sat	Dinner	1
92	5.75	1.0	Female	Yes	Fri	Dinner	2
…	…	…	…	…	…	…	…
319815362	50.81	10.0	Male	Yes	Sat	Dinner	3
319815606	50.81	10.0	Male	Yes	Sat	Dinner	3

319815680 rows x 7 columns

Wall time と書かれているところを見ましょう．3億行もあるデータを読み込んでソートするのに 15 ミリ秒しかかかっていないのだとしたらすごいことですね．実際にはそんなことはなく，このセルの実行を開始してから結果が表示されるまでに10秒ぐらい待たされました．結果が画面に出力されているのだから，きちんと評価されているはずでは…？ と思いましたが，それは半分正しく，半分間違っていました．

実はこの書き方の場合，%%time のタイマーが止まった後でデータフレームの評価が始まってしまっているのです．つまり，タイマー停止 → 評価 → 表示 の順序になってしまっているため，データフレームの実際の処理が %%time の測定範囲外にあるということなのです．

正しい時間計測の例

というわけで，処理時間を計測したい場合は IPython Notebook でも明示的にデータフレームの _evaluate() メソッドを呼び出し，きちんと評価しましょう．以下のように書くと，評価 → タイマー停止 → 表示 の順序で実行されるため，データフレームの実際の処理が %%time の測定範囲に入ります．

%%time
df = pd.read_csv("sample-dataset-tips10gb.csv")
df = df.sort_values(by="tip")
df._evaluate()

CPU times: user 3min 58s, sys: 1min 2s, total: 5min
Wall time: 11.1 s

	total_bill	tip	sex	smoker	day	time	size
67	3.07	1.0	Female	Yes	Sat	Dinner	1
92	5.75	1.0	Female	Yes	Fri	Dinner	2
…	…	…	…	…	…	…	…
319815362	50.81	10.0	Male	Yes	Sat	Dinner	3
319815606	50.81	10.0	Male	Yes	Sat	Dinner	3

319815680 rows x 7 columns

別解？

ちなみに以下のように書くと，評価 → 表示 → タイマー停止 の順序になります．この場合，データフレームを画面に表示するための処理も時間計測の範囲内に含まれることになるため，僅かではありますが時間計測の意味が変わってきます．データフレームの出力と計測結果の出力の順序も入れ替わっていますね．

%%time
df = pd.read_csv("sample-dataset-tips10gb.csv")
df = df.sort_values(by="tip")
display(df)

	total_bill	tip	sex	smoker	day	time	size
67	3.07	1.0	Female	Yes	Sat	Dinner	1
92	5.75	1.0	Female	Yes	Fri	Dinner	2
…	…	…	…	…	…	…	…
319815362	50.81	10.0	Male	Yes	Sat	Dinner	3
319815606	50.81	10.0	Male	Yes	Sat	Dinner	3

319815680 rows x 7 columns

CPU times: user 3min 58s, sys: 55.4 s, total: 4min 53s
Wall time: 10.6 s

まとめにかえて

FireDucks は pandas と同じ API を維持しながら遅延評価の仕組みを取り入れているため，処理時間の計測においてはこのようなちょっとしたことにも気をつける必要があります．しかし pandas とほとんど同じコードのまま処理を高速化できる FireDucks は，データサイエンスの強い味方になってくれるでしょう．

最近は多くの方が FireDucks に興味を示してくださり，速くなったという声やバグレポートなども増えつつあります．私たち開発チームとしても，FireDucks を広く，末永く使っていただけるよう頑張っています！ 今後のアップデートにも是非ご注目ください．

May the Acceleration be with you, FireDucks 開発チーム

• ←前へ
• 次へ→