田舎で並行処理の夢を見る

試したこと、需要がないかもしれないけど細々とアウトプットしてます

【並行処理vs逐次処理】Elixirで実装した並行和と逐次和をベンチマーク測定をして比較した結果【完全敗北】

前回までのお話

「並行コンピューティング技法」という書籍を読み進める中で「並行和」という並行処理にてデータの要素の合計値を求めるアルゴリズムElixirを用いて実装してみた。何とか動くところまで作れたものの、実行速度がどれだけ逐次処理と異なるかは実行してみないと分からない。そこでベンチマーク測定をするためのログを出力すると決めて1週間が経過していた。

前回のお話はこちらから
www.okb-shelf.work

ベンチマーク測定の実装

以前、Yamazakiさんよりご紹介頂いた「Benchfella」を使用しました。ご紹介頂きまして有難うございます。めちゃくちゃ手軽で使いやすかった。

githubREADME.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

f:id:takamizawa46:20200223211558p:plain:w450
(別のベンチマークの結果。ファイルを誤って削除してしまった)

$ 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 notebookPython使ってグラフ化。

並行処理(parallel) f:id:takamizawa46:20200223211206p:plain
f:id:takamizawa46:20200223211212p:plain

逐次処理(serial) f:id:takamizawa46:20200223211216p:plain
f:id:takamizawa46:20200223211221p:plain

「ん?全然差がないやん?」と思うかもしれないが実はそうではなく、実際は数値からも見て分かる通りかなり平均処理時間に大きな差がある。単純にPythonmatplotlib.pyplot力がなくてy軸最大値を統一していないのが悪い、というか比較するグラフで単位(10n)が異なるのどうなのかと思うが、並行処理(parallel)の方が10^8であり、逐次処理(serial)の方が10^3になっており、天と地ほどの差がある。2つのグラフを並べて表示させてみたが、数値に差がありすぎて逐次処理の実行時間の値が表示されないという悲しすぎる問題に直面した。

なぜ並行処理の方がこんなにも遅いのか

まずは結果を重く受け止める。正直、データ量がどのあたりで並行処理が逐次処理を上回るかなとワクワクしていたが幻想をぶち壊されてしまった。何がこうも処理を遅くさせているのか。「並行コンピューティング技法」の書籍から得た知識から推測するに「オーバーヘッド」部分がかなりの負担となっていると考えられる。ここでいうオーバーヘッドにあたる処理は以下の3つ。

  • データを要素N個ずつのチャンクに分割
  • プロセスの立ち上げとチャンク割り当て & 合計処理の実行と終了確認 -> プロセスの停止
  • 各プロセスが算出した値をメインプロセスにて合計

チャンク分割が上手く出来ていないのだろうか。
Enum.chunk_every()使ってるだけで記述の雑みの問題はないかと思うが、単純な疑問として100,0000もの要素を持つ配列を分割するのにどれだけの時間が掛かるのだろう。index=0から順に要素を見ていき、index=10になったところで配列を分割。このような再帰処理を行うとすればO(N)の計算量がかかるはず。プロセスの起動と終了に関してもElixirTaskを使っているだけで、改善を見込めそうにない。
現状の手札だけでは打つ手がない。

改善方法について

もっと細かくベンチマークを行い、どこのオーバーヘッドがボトルネックになりうるのかを洗い出すところから始めてみる。今回の成果物としてはベンチマークを実行する方法を身につけた事と、並行処理と逐次処理を比べるという人生初体験が出来たということで、次にその改善をするチャンスを得られたということにしておく。必ず、特定条件以下では並行処理で逐次処理を倒してやる。

参考文献