前回までのお話
「並行コンピューティング技法」という書籍を読み進める中で「並行和」という並行処理にてデータの要素の合計値を求めるアルゴリズムをElixirを用いて実装してみた。何とか動くところまで作れたものの、実行速度がどれだけ逐次処理と異なるかは実行してみないと分からない。そこでベンチマーク測定をするためのログを出力すると決めて1週間が経過していた。
前回のお話はこちらから
ベンチマーク測定の実装
以前、Yamazakiさんよりご紹介頂いた「Benchfella」を使用しました。ご紹介頂きまして有難うございます。めちゃくちゃ手軽で使いやすかった。
パフォーマンス測定には Benchfella という超便利ツールがあります。活用してみてください。 https://t.co/mtv9BM9Hf9
— Susumu Yamazaki (ZACKY) (@zacky1972) 2019年8月3日
githubのREADME.mdに従い、実装を進めていく。
github.com
プロジェクトディレクトリの直下にbenchという名前のディレクトリを作成。合わせて、このディレクトリの直下にベンチマーク用のファイルを用意する。ベンチマーク測定に使用するモジュールを記述するファイルには_bench.exsを必ず付ける。golangの_test.goと同じで対象ファイルを探索するために使用していると思われる。
以下のファイルを作成してベンチマークを行う準備をする。
./parallel_sum/bench/sum_bench.exs
defmodule ParallelSum.Bench do @moduledoc """ 実行時間などを外部モジュール'benchfella'を用いて計測を行うためのモジュール """ use Benchfella @recursive "recursive" @enum "enum" @dataset_100 ParallelSum.DataCreater.create_N_size_list(100) # data size 100 ------------------------------------------- ## recursive bench "parallel: recursive 100" do ParallelSum.bench_parallel_exec(@dataset_100, @recursive) end bench "serial: recursive 100" do ParallelSum.bench_serial_exec(@dataset_100, @recursive) end ## enum bench "parallel: enum 100" do ParallelSum.bench_parallel_exec(@dataset_100, @enum) end bench "serial: enum 100" do ParallelSum.bench_serial_exec(@dataset_100, @enum) end end
一部を抜粋。ベンチマーク測定に使用する処理の最終値は毎回同じである必要があり、要は検証データは使い回しする必要がある。前回の記事を参照してもらえれば分かるが、今の並行和の実装はpipeline関数内部でランダム値を使用したデータを生成しているため、このままではベンチマーク測定が出来ない。そのため、ベンチマーク用に並行和、逐次和、それぞれに専用の関数を実装した。
./parallel_sum/lib/parallel_sum.ex
defmodule ParallelSum do @moduledoc """ メインモジュール。他モジュールにて抽象化した関数群をpipeline化する """ @doc """ benchfella用の実行関数(算出結果が異なるとerrorになるため) """ def bench_parallel_exec(_, ""), do: :error def bench_parallel_exec([], _), do: :error def bench_parallel_exec(dataset, mode) do # 立ち上げるプロセス数を算出 process_num = ParallelSum.Scheduler.calc_total_process(length(dataset)) # プロセスを立ち上げて並行和を算出 parallel_sum = ParallelSum.Scheduler.start_task( mode, ParallelSum.Scheduler.list_spliter(dataset), process_num ) Enum.sum(parallel_sum) end @doc """ benchfella用の実行関数(算出結果が異なるとerrorになるため) """ def bench_serial_exec(_, ""), do: :error def bench_serial_exec([], _), do: :error def bench_serial_exec(dataset, mode) do _serial_exec(mode).(dataset) end end
これで準備は完了。あとはドキュメントに従ってベンチマークを実行するのみ。
ベンチマークの実行方法について
プロジェクトディレクトリの直下に移動して、以下コマンドを実行。その前に、ファイル変更がある場合はmix compileをお忘れなく。
$ mix bench
Settings: duration: 1.0 s ## ParallelSum.Bench [20:37:04] 1/4: parallel: enum 100 [20:37:07] 2/4: parallel: recursive 100 [20:37:11] 3/4: serial: enum 100 [20:37:13] 4/4: serial: recursive 100 Finished in 10.74 seconds ## ParallelSum.Bench benchmark name iterations average time serial: recursive 100 1000000 1.49 µs/op serial: enum 100 1000000 1.60 µs/op parallel: recursive 100 50000 57.99 µs/op parallel: enum 100 50000 60.18 µs/op
終了後の全体ログを出力しているが、実行中には現在の進行度合いがリアルタイムに出力されるため非常に便利。ログの内容もシンプルで分かりやすい。
# ベンチマーク実行までにかかった時間 Settings: duration: 1.0 s
# 経過ログ ## ParallelSum.Bench [20:37:04] 1/4: parallel: enum 100 [20:37:07] 2/4: parallel: recursive 100 [20:37:11] 3/4: serial: enum 100 [20:37:13] 4/4: serial: recursive 100
# ベンチマーク終了後に出力される結果 ## ParallelSum.Bench benchmark name iterations average time serial: recursive 100 1000000 1.49 µs/op serial: enum 100 1000000 1.60 µs/op parallel: recursive 100 50000 57.99 µs/op parallel: enum 100 50000 60.18 µs/op
合わせて、ベンチマークの結果をbench直下のsnapshotsというディレクトリに自動で保存してくれる。ファイル形式が.snapshopという独自形式だが、ただのテキスト(binary)のようなのでVSCodeでも問題なく閲覧出来た。
./parallel_sum/bench/snapshots/_.snapshots
duration:1.0;mem stats:false;sys mem stats:false module;test;tags;iterations;elapsed ParallelSum.Bench parallel: enum 100 50000 3009104 ParallelSum.Bench parallel: recursive 100 50000 2899529 ParallelSum.Bench serial: enum 100 1000000 1596746 ParallelSum.Bench serial: recursive 100 1000000 1491282
他にもベンチマーク実行前、実行後に行いたい処理を指定したり、複数のベンチマークを比較させたりと対応範囲が広いなぁという印象。詳しくはREADNE.mdを見てください。個人的にアツいと思ったのは.snapshotファイルからグラフを描画できる点。
$ mix bench.graph
Wrote bench/graphs/index.html
(別のベンチマークの結果。ファイルを誤って削除してしまった)
$ open bench/graphs/index.htmlとコマンドを実行してブラウザから生成されたグラフを閲覧することが出来る。凄い。さて、ベンチマークの実行方法も分かったのでベンチマークをデモのものから書き換える。
いざベンチマーク: 逐次処理vs並行処理
少し行数が多くなったのでリンクを貼っておきますが、内容は対したものではなく、ただデータ数と集計方法を変えてベンチマークを実行しているだけ。一般化する良い方法が思いつかなかったので、別にケース分けるならということでヨシ！とした。また、最大要素数は100,000としているが特に理由はなく、何となくそれ以上の要素数にするとベンチマークが終わらないのではないかと思ったからだ。
github.com
いざ、ベンチマークを実行!!!
$ mix bench
Settings: duration: 1.0 s ## ParallelSum.Bench [14:03:33] 1/20: parallel: enum 100 [14:03:35] 2/20: parallel: enum 1000 [14:03:39] 3/20: parallel: enum 10000 [14:03:41] 4/20: parallel: enum 100000 [14:03:45] 5/20: parallel: enum 1000000 [14:09:00] 6/20: parallel: recursive 100 [14:09:02] 7/20: parallel: recursive 1000 [14:09:04] 8/20: parallel: recursive 10000 [14:09:06] 9/20: parallel: recursive 100000 [14:09:07] 10/20: parallel: recursive 1000000 [14:13:30] 11/20: serial: enum 100 [14:13:38] 12/20: serial: enum 1000 [14:13:42] 13/20: serial: enum 10000 [14:13:46] 14/20: serial: enum 100000 [14:13:50] 15/20: serial: enum 1000000 [14:13:54] 16/20: serial: recursive 100 [14:14:03] 17/20: serial: recursive 1000 [14:14:07] 18/20: serial: recursive 10000 [14:14:11] 19/20: serial: recursive 100000 [14:14:15] 20/20: serial: recursive 1000000 Finished in 646.13 seconds ## ParallelSum.Bench benchmark name iterations average time serial: enum 100 10000000 0.76 µs/op serial: recursive 100 10000000 0.80 µs/op serial: recursive 1000 500000 6.49 µs/op serial: enum 1000 500000 6.60 µs/op parallel: recursive 100 50000 22.68 µs/op parallel: enum 100 50000 33.83 µs/op serial: recursive 10000 50000 64.08 µs/op serial: enum 10000 50000 65.76 µs/op parallel: recursive 1000 10000 243.17 µs/op parallel: enum 1000 10000 349.81 µs/op serial: recursive 100000 5000 641.54 µs/op serial: enum 100000 5000 647.33 µs/op serial: recursive 1000000 500 6415.18 µs/op serial: enum 1000000 500 6530.90 µs/op parallel: recursive 10000 100 10893.83 µs/op parallel: enum 10000 100 17106.37 µs/op parallel: recursive 100000 1 1575123.00 µs/op parallel: enum 100000 1 4650929.00 µs/op parallel: recursive 1000000 1 262729181.00 µs/op parallel: enum 1000000 1 314724083.00 µs/op
めっちゃ時間かかった。このままだと非直感的で分かりにくいのでjupyter notebookとPython使ってグラフ化。
並行処理(parallel)
逐次処理(serial)
「ん？全然差がないやん？」と思うかもしれないが実はそうではなく、実際は数値からも見て分かる通りかなり平均処理時間に大きな差がある。単純にPythonのmatplotlib.pyplot力がなくてy軸の最大値を統一していないのが悪い、というか比較するグラフで単位(10n)が異なるのどうなのかと思うが、並行処理(parallel)の方が10^8であり、逐次処理(serial)の方が10^3になっており、天と地ほどの差がある。2つのグラフを並べて表示させてみたが、数値に差がありすぎて逐次処理の実行時間の値が表示されないという悲しすぎる問題に直面した。
なぜ並行処理の方がこんなにも遅いのか
まずは結果を重く受け止める。正直、データ量がどのあたりで並行処理が逐次処理を上回るかなとワクワクしていたが幻想をぶち壊されてしまった。何がこうも処理を遅くさせているのか。「並行コンピューティング技法」の書籍から得た知識から推測するに「オーバーヘッド」部分がかなりの負担となっていると考えられる。ここでいうオーバーヘッドにあたる処理は以下の3つ。
- データを要素N個ずつのチャンクに分割
- プロセスの立ち上げとチャンク割り当て & 合計処理の実行と終了確認 -> プロセスの停止
- 各プロセスが算出した値をメインプロセスにて合計
チャンク分割が上手く出来ていないのだろうか。
Enum.chunk_every()使ってるだけで記述の雑みの問題はないかと思うが、単純な疑問として100,0000もの要素を持つ配列を分割するのにどれだけの時間が掛かるのだろう。index=0から順に要素を見ていき、index=10になったところで配列を分割。このような再帰処理を行うとすればO(N)の計算量がかかるはず。プロセスの起動と終了に関してもElixirのTaskを使っているだけで、改善を見込めそうにない。
現状の手札だけでは打つ手がない。
改善方法について
もっと細かくベンチマークを行い、どこのオーバーヘッドがボトルネックになりうるのかを洗い出すところから始めてみる。今回の成果物としてはベンチマークを実行する方法を身につけた事と、並行処理と逐次処理を比べるという人生初体験が出来たということで、次にその改善をするチャンスを得られたということにしておく。必ず、特定条件以下では並行処理で逐次処理を倒してやる。
