結局、Go言語をやめる理由はなかった件

　この記事は Go 2 Advent Calendar 14日目の穴埋め記事です。

はじめに

　@okdyy75 さんによる Go 5 Advent Calendar 14日目の の記事「だから僕はGo言語を辞めた」 が「ベンチマークっていうのはこうやるんだよ」というのを説明するために反面教師的な意味で良い教材だと思ったので、反証記事を書きたいと思います。
　ベンチマークを取りながらコードを改善して、最終的にGoは遅くないからやめる必要はないということ、そして、なぜ遅いという結論になってしまったのかを掘り下げていきたいと思います。

下準備

　幸いなことに、ベンチマークのソースコードがGitHubにある ので、こちらを実行しながら問題点を改善していきましょう。
　ちゃんとコードが上がっているのは素晴らしいですね！

　一方で、元記事には測定環境が明記されていませんでしたので、同じ環境で測定することはできませんでした。
　今回は誰でも追試できるように、AWS EC2 の m5d.large インスタンスを使うことにしました。m5d.large インスタンスのスペックは次のようになっています：

• vCPU: 2
  • Intel(R) Xeon(R) Platinum 8175M CPU @ 2.50GHz (最大3.1GHz)
• メモリ: 8 GiB
• ストレージ: 1 x 75 GiB NVMe SSD
• OS: Amazon Linux 2

　今回、m5d.large インスタンスを採用したのは次の理由からです:

• 汎用ワークロード向けインスタンスである
• Docker Composeを使うため、メモリに余裕をもたせて8GB用意する
• MySQLでストレージがボトルネックになることを少しでも抑えるため、NVMe SSD を使う

　注意点として、同じ汎用ワークロード向けでもバースト可能なT系インスタンスはベンチマークを取る際には避けたほうが良いです。バースト可能インスタンスはCPUクレジットが切れるとパフォーマンスが著しく制限されるため、性能が安定しないからです。（バーストリミットを外すという手もありますが、そうすると課金が青天井になります。富豪じゃないので、怖くてとてもリミットは外せません(^q^)）

　それではリポジトリをクローンして始めていきましょう：

$ git clone https://github.com/okdyy75/bench-docker.git
$ cd bench-docker

docker-compose.yml があるので、docker-composeで起動します：

$ docker-compose up -d

とりあえず測ってみる

　とりあえず、Go実装のベンチマークプログラムを実行させてみましょう：

$ sudo docker-compose run --rm golang sh -c 'cd go; go build . && ./go'
Creating bench-docker_golang_run ... done
Go go1.15.6
  .
  .
  .
(snip)
  .
  .
  .
平均秒数：9.78155623 (0x0,0x0)

　元記事よりもずいぶん速いですね。まぁ、実行環境が違うので仕方ありませんね。

　次に比較対象として、元記事で最速だった Python実装の時間を計測してみましょう：

$ sudo docker-compose run --rm python sh -c 'cd python; pip install -r ./requirements.txt && python bench.py'
Creating bench-docker_python_run ... done
  .
  .
  .
(snip)
  .
  .
  .
Python 3.9.1 (default, Dec 11 2020, 14:29:41) 
  .
  .
  .
(snip)
  .
  .
  .
平均秒数：9.155766, 標準偏差: 0.6

　なるほど、元記事ほどの差はありませんが、たしかにPythonのほうが良い結果が出ていますね。

測定結果の "ブレ" はどれくらい？

　ここでGoの実行結果をよく見ると、各試行の実行時間にだいぶブレがあることに気づきます：

$ sudo docker-compose run --rm golang sh -c 'cd go; go build . && ./go'
Creating bench-docker_golang_run ... done
Go go1.15.6
...(snip)...
9.5253088 (0x0,0x0)
...(snip)...
9.8432198 (0x0,0x0)
...(snip)...
10.5489359 (0x0,0x0)
...(snip)...
10.4082789 (0x0,0x0)
...(snip)...
10.4875889 (0x0,0x0)
...(snip)...
9.4180508 (0x0,0x0)
...(snip)...
9.1494458 (0x0,0x0)
...(snip)...
9.1779438 (0x0,0x0)
...(snip)...
9.5848948 (0x0,0x0)
...(snip)...
9.6719018 (0x0,0x0)
平均秒数：9.78155623 (0x0,0x0)

　ちなみに、今回のベンチマークでは、対象処理を10回試行して、その平均秒数を表示するようになっています。
　Go と Python の実行時間の差はこのブレ、つまり誤差の中に収まってしまうのではないか？というわけで、標準偏差も計算して表示するようにプログラムを次のように書き換えました:

$ git diff
diff --git a/www/go/bench.go b/www/go/bench.go
index 5c56714..878b95a 100644
--- a/www/go/bench.go
+++ b/www/go/bench.go
@@ -5,6 +5,7 @@ import (
        "encoding/csv"
        "fmt"
        "io"
+       "math"
        "os"
        "runtime"
        "time"
@@ -281,6 +282,12 @@ func main() {
                sum += s
        }
        avg := float64(sum / float64(len(times)))
-       println(fmt.Printf("平均秒数：%f", avg))
+       // 標準偏差を計算
+       sdev := 0.0
+       for _, t := range times {
+               sdev += math.Pow(avg-t, 2)
+       }
+       sdev = math.Sqrt(sdev / float64(len(times)))
+       println(fmt.Printf("平均秒数：%f, 標準偏差: %.1f", avg, sdev))

 }
diff --git a/www/python/bench.py b/www/python/bench.py
index 2639925..8050297 100644
--- a/www/python/bench.py
+++ b/www/python/bench.py
@@ -1,4 +1,5 @@
 import csv
+import math
 import os
 import sys
 from itertools import zip_longest
@@ -179,7 +180,12 @@ def main():
         times.append(s)

     svg = sum(times) / len(times)
-    print('平均秒数：%f' % svg)
+    # 標準偏差を計算
+    sdev = 0.0
+    for t in times:
+        sdev += (t - svg) ** 2
+    sdev = math.sqrt(sdev / len(times))
+    print('平均秒数：%f, 標準偏差: %.1f' % (svg, sdev))


 if __name__ == '__main__':

　ちなみに、Pythonの標準的なテスト／ベンチマークツールである pytest を使うと、この標準偏差や最小値、最大値といった数値をまとめて表示してくれるので便利です。
　よく使われているベンチマークツール／フレームワークを利用すれば先人の知恵の恩恵にあやかることができるので、可能な場合は是非利用しましょう。

　書き換えたプログラムの実行結果は次のようになります：

Go実装:

$ sudo docker-compose run --rm golang sh -c 'cd go; go build . && ./go'
...(snip)..
平均秒数：9.945593, 標準偏差: 0.342 (0x0,0x0)

Python実装：

$ sudo docker-compose run --rm python sh -c 'cd python; pip install -r ./requirements.txt && python bench.py'
...(snip)...
平均秒数：8.899219, 標準偏差: 0.1

　たしかに Go実装のほうが標準偏差が大きいですが、しかし両者の差が誤差の範囲とは言えませんね。
　では、いったい何にそんなに時間がかかっているのでしょうか？

どんな処理に時間がかかっているのかざっくり知る

　プログラムの実行時間は次のような時間の合計です：

1. ユーザー空間で実行されてる時間（user time)
2. カーネル空間で実行されている時間（system time）
3. ファイルやネットワークなどの入出力結果を待っている時間（idle time）

　1 は自分や自分が利用しているライブラリのコードが実行されている時間です。普通はチューニングや高速化といったらまずはここを改善します。
　2 はOS（カーネル）のコードが実行されている時間です。カーネルの中に手を入れてチューニングするということは普通はしないので、2の時間を縮めるためにはカーネル機能（システムコール）を呼び出す回数を減らすことを考えます。特に、システムコールを呼んだときは、プロセスの実行が通常の権限で動くユーザー空間から特権で動くカーネル空間へと切り替わりますが、この切り替え処理はかなり重い処理です。そのため、一度のシステムコールでなるべく多くの仕事をするようにしてシステムコールを呼ぶ回数を減らすことが、プログラムの効率化につながります。（I/Oのバッファリングはこの典型的な手法ですね）
　最後に 3 は、ソフトウェアではどうにもできないことが多いです。2 のチューニングでシステムコールを呼ぶ回数を減らしたあとは、もうハードウェアのスペックを上げたり、ネットワーク遅延を下げたりすることで改善することになります。（基本的には札束で殴るのが効果的な世界）

　では、今回のケースではどこに時間が使われているのでしょう？

　これをざっくり知るためのもっとも簡単な方法は time コマンドです。
　測定したいコマンドの前に time を置くだけで、上記1、2、3を表示してくれます：

Go実装：

$ sudo /usr/local/bin/docker-compose run --rm golang sh -c 'cd go; go build . && time ./go'
...(snip)...
平均秒数：9.182259, 標準偏差: 0.142 (0x0,0x0)
real    1m 31.83s
user    0m 6.06s
sys     0m 8.80s

Python実装：

$ sudo /usr/local/bin/docker-compose run --rm python sh -c 'cd python; pip install -r ./requirements.txt && time python bench.py'
...(snip)...
平均秒数：9.029642, 標準偏差: 0.6
real    1m 30.32s
user    0m 8.65s
sys     0m 2.45s

　real が実際にプログラムを頭から終わりまで実行するのにかかった実際の時間です。（しばしばCPU時間と区別するために wall-clock timeも呼ばれます）
　user が上記1のuser time、sys が 上記2のsystem timeです。したがって、real から user と sys を引いた時間が上記3のidle timeになります。

　見ておわかりの通り、どちらのプログラムも real は 90秒程度なのに対し、user + sys は 10～15秒くらいしかありません。つまり、実行時間のうち85％くらいの時間は、ただI/Oの結果を待っているだけの ヒマしている時間 なのです。

　さらによく見てみると、Python実装の user time が8.65秒、system time が 2.45秒なのに対し、Go実装の user time が 6.06秒、system time が 8.80秒と、それぞれの実行時間が逆転しています。
　Goの場合は user time ≒ Goで実装されたコードの実行時間ですから、Goで書かれたコードが実行されている時間のほうがPythonで書かれたコードが実行されている時間よりも短いと言えます。
　ではなぜ、system time（OSカーネルが動いている時間）が8.80秒もかかっているのでしょうか？

　経験豊富な方はもうこのあたりでピンと来ていると思いますが、もう少し詳しく調べてみましょう。

プロファイリングしてみる

　Go実装のどこに時間がかかっているのか、プロファイリングしてみることにします。

　ありがたいことに、Goには標準でプロファイリングのためのツールが付いてきます。
　プロファイリングを行うには、pprof パッケージを使います。
　詳しい使い方は Go Blogの記事 を参照していただくこととして、次のように main 関数に追加します：

$ git diff
diff --git a/www/go/bench.go b/www/go/bench.go
index 878b95a..e2f7731 100644
--- a/www/go/bench.go
+++ b/www/go/bench.go
@@ -8,6 +8,7 @@ import (
        "math"
        "os"
        "runtime"
+       "runtime/pprof"
        "time"

        _ "github.com/go-sql-driver/mysql"
@@ -250,6 +251,17 @@ func printTime(message string) {

 // メイン処理
 func main() {
+       f, err := os.Create("cpuprofile")
+       if err != nil {
+               fmt.Fprintln(os.Stderr, "could not create file: ", err)
+               os.Exit(1)
+       }
+       defer f.Close()
+       if err := pprof.StartCPUProfile(f); err != nil {
+               fmt.Fprintln(os.Stderr, "could not start CPU profile: ", err)
+               os.Exit(1)
+       }
+       defer pprof.StopCPUProfile()

        println("Go " + runtime.Version())

　こうしてプログラムを実行すると、実行時に情報が集められてその結果が cpuprofile という名前のファイルに保存されます：

$ sudo docker-compose run --rm golang sh -c 'cd go; go build . && ./go'
...(snip)...
平均秒数：9.895000, 標準偏差: 0.442 (0x0,0x0)
real    1m 39.11s
user    0m 6.03s
sys     0m 9.34s
$ ls www/go 
bench.go  cpuprofile  export_users.csv  go  README.md

　プロファイリングの処理が追加されるので、当然ながら実行速度は少し遅くなります。

　プロファイリング結果を見る方法も、標準のGoコマンドについてきます。見た目きれいに見えるので、次のコマンドでWebブラウザで見る方法がおすすめです：

$ go tool pprof -http=localhost:9090 cpuprofile

　ブラウザが開いて、次のような図が表示されるはずです：

　これはどの関数がどの関数を呼び出したのかを示すコールグラフという図です。さらに、それぞれにどれくらいの時間がかかっているのかが表示されています。
　ただし、実行時のサンプリングによって得られた結果ですので、実際には実行されているはずの関数が表示されていなかったり、厳密に計測した実行時間とはズレがあります。それでも、どこの処理に時間がかかっているのかを知るには十分です。

　赤く色がついているパスが一番実行時間がかかっているクリティカルパスなので、基本的にはここを改善することになります：

　SQLデータベースにアクセスする部分に時間がかかっているようですね。
　これを下にどんどんたどっていくと……ひときわ大きな赤い四角がありました：

　この syscall.Syscall というのが、GoがOSのシステムコールを呼ぶときに必ず通る部分です。
　この処理に6.82秒かかっているということで、上で time コマンドを使って測った system time とほぼ同じになっていますね。
　コールグラフをたどってわかったように、SQLドライバの処理が何度もシステムコールを呼んでいるため、system time が長くなっているようです。

　それにしても、どうしてこんなにシステムコールを呼んでいるのでしょう？
　というわけでソースコードを見てみると、どうやら原因は bench.go の147行目からの処理のようです：

rows, err = db.Query("select * from users order by id")
  .
  .
  .
（中略）
  .
  .
  .
var user User
for rows.Next() {
    err = rows.Scan(
        &user.ID,
        &user.Name,
        &user.Email,
        &user.EmailVerifiedAt,
        &user.Password,
        &user.RememberToken,
        &user.CreatedAt,
        &user.UpdatedAt,
    )
  .
  .
  .
（略）

　この処理では、MySQLデータベースから1行ずつ結果を取ってくるようになっています。

　一方でPython実装では、これに相当する処理は fetchall を使って一括で取得しています：

    cur = db.cursor()
    cur.execute('select * from users order by id')
    users = cur.fetchall()

　fetchall なら、ネットワークからの入力を（可能ならば）1度のシステムコールで読み込むことができますが、1行ずつ読み込む場合は必要な分だけをネットワークデバイスに読み込みにいくことになるため、何度もシステムコールを呼ぶことになります。
　上で述べたように、システムコール呼び出しはそれ自体が重い処理なので、一度に全部読み込めるなら一度で済ませてしまったほうが、CPUとしては効率的なプログラムになります。

　ところが、Goの標準ライブラリである database/sql には fetchall のような一度に全部の結果を読み込むためのAPIがありません。したがって、Goでは一度にすべてを読み込むことは（標準の方法では）不可能なのです。
　実はこれは既知のissueでして、Go2で実装してほしいことのリクエストにも上がっている問題だったりします。

議論すべきポイント

　さて、少なくとも現状のGoではシステムコール呼び出しを減らす方法はなさそうだ、という話になりました。
　しかしここで考えたいのは、果たして fetchall を使った実装が "お行儀のいい" 実装なのか、ということです。

　たしかに、システムコール呼び出しの回数が少なくなるのはCPUの観点からは高速ですし、少ない文字数で簡潔に書けるという点からも便利な方法なのは間違いないでしょう。
　しかし、もしデータベースに大量のデータがあったらどうなるでしょうか？
　当然、一度にすべてのデータを読み込むと大量のメモリを必要としますし、最悪の場合はOut of Memoryで死にます。
　ここで、今回のワークロード（CSVファイルから情報を読み込んでデータベースに保存し、データベースから行を読み込んでCSVファイルに書き出す）において実行速度が重要になる状況というのは、当然ながら読み書きする行が大量になったときです。 行が少ないならば、そもそも実行時間なんて気にする必要はなく、人間にとって一番効率の良い方法で実装するべきです。 それこそ、シェルスクリプトのほうが速く書けるのではないでしょうか？
　つまり、そもそもが大量の行を扱うという前提があるわけですから、すべての行をデータベースから一度に読み込むという実装を書くべきではありません。

　これは個人的な推測ですが、Goが標準のAPIで fetchall のようなものを用意していないのは、こういう思想があるからだと思います。
　つまり、Goはメモリ安全で効率的なプログラムを、誰でも比較的容易に書けるようにすることを目指しているのだから、メモリ溢れを助長するような書き方はそもそもできないようにしているのではないかと思っています。
　私はこの思想に肯定的ですが、一方で、メモリが溢れないとわかっているときには効率的に書ける方法を用意しておいてくれてもいいじゃないか、という意見もわかります。¹
　Goの場合でも、どうしてもやりたければCgoを使ったり自分でショートカットをゴリゴリ実装すればできないことはないです。推奨されないやり方を敢えて実行するためのハードルをすごく高くしているという感じですね。

　いずれにしても、もし今回の fetchall を使った方法を本番環境で使っていたら、早晩メモリ不足でサーバーがダウンしていたことでしょうから、比較としてフェアではないと思います。
　ちなみに、他の言語のベンチマークプログラムも、みんな fetchall に類するものを使っていましたので、今回はGoだけがハンデを背負っていました。

たとえハンデがあったとしても

　というわけで、今回のベンチマークはGoにとって完全にハンデ戦なわけですが、それでもまだ改善できる部分があります。

　上のコールグラフでは syscall.Syscall で 6.82秒かかっていたわけですが、sql.exec 全体では 8.81秒かかっていることが見て取れます。残りの約2秒は何に時間がかかっているのでしょうか？

　答えは、Go実装でデータベースにインサートしている部分を見てください：

for {
    lines, err = reader.Read()
    if err != nil {
        break
    }

    // lines[0]はidのため1から
    _, err = db.Exec(`
        INSERT INTO users (
            name,
            email,
            email_verified_at,
            password,
            remember_token,
            created_at,
            updated_at
        ) values (
            ?, ?, ?, ?, ?, ?, ?
        );
    `, lines[1], lines[2], lines[3], lines[4], lines[5], lines[6], lines[7])
    if err != nil {
        panic(err)
    }
}

　なんと、for文の中で繰り返し db.Exec にSQL文を文字列で渡しています。
　知らないと驚かれるかもしれませんが、Go の database/sql（正確にいうと go-sql-driver/mysql）では Exec のSQL文のパース結果をキャッシュしません。そのため、毎回SQL文のパース処理が行われます。

　Python や PHP など他の言語の標準ライブラリではライブラリ内部でキャッシュすることが多いです。
　これも賛否が分かれるところですが、Goではキャッシュのために勝手にメモリを使うことを是としていないのだと思います。特に、PythonのようにGlobalキャッシュを使っていると、ユーザーがMySQLとの接続を追えたあともメモリ上に残り続けてしまって、メモリをムダに消費し続けます。
　Goの場合は、何度も同じSQL文を実行するなら明示的に Prepare を使うべきです。というわけで、次のように書き換えました：

$ git diff
diff --git a/www/go/bench.go b/www/go/bench.go
index e2f7731..f15f0ea 100644
--- a/www/go/bench.go
+++ b/www/go/bench.go
@@ -115,6 +115,23 @@ func work(db *sql.DB) {
        }
        defer file.Close()

+       stmt, err := db.Prepare(`
+               INSERT INTO users (
+                       name,
+                       email,
+                       email_verified_at,
+                       password,
+                       remember_token,
+                       created_at,
+                       updated_at
+               ) values (
+                       ?, ?, ?, ?, ?, ?, ?
+               );
+       `)
+       if err != nil {
+               panic(err)
+       }
+
        reader = csv.NewReader(file)
        _, err = reader.Read() // ヘッダースキップ
        for {
@@ -124,19 +141,7 @@ func work(db *sql.DB) {
                }

                // lines[0]はidのため1から
-               _, err = db.Exec(`
-                       INSERT INTO users (
-                               name,
-                               email,
-                               email_verified_at,
-                               password,
-                               remember_token,
-                               created_at,
-                               updated_at
-                       ) values (
-                               ?, ?, ?, ?, ?, ?, ?
-                       );
-               `, lines[1], lines[2], lines[3], lines[4], lines[5], lines[6], lines[7])
+               _, err = stmt.Exec(lines[1], lines[2], lines[3], lines[4], lines[5], lines[6], lines[7])
                if err != nil {
                        panic(err)
                }

　実のところ、この書き換えもフェアとは言えません。
　Pythonの場合は、ベンチマークの10回の試行の内、最初に1回だけパース処理をして、あとの9回はキャッシュした結果が使い回せますが、Goの場合は10回の試行の毎回パース処理が走ります。
　とはいえ、1回だけにするために Prepare を初期化処理の中でやってしまうと、パースにかかった時間が計測されなくなってしまってそれはそれでフェアじゃないかなぁ、と思ったので、毎回やることにしました。
　つまり、まだPythonに対してハンデをつけてあげています。

※追記： この辺りは自分の勘違いでした。詳しくは下の @methane さんのコメントをご覧ください。

　実行結果は次のとおり（※速度が重要なので、プロファイリングは外してあります）：

$ sudo /usr/local/bin/docker-compose run --rm golang sh -c 'cd go; go build . && time ./go'
...(snip)...
平均秒数：8.116856, 標準偏差: 0.342 (0x0,0x0)

　はい、上のPythonの実行結果を逆転しました！
　元記事ではPythonが最速だったので、Goが最速の座を奪い取りましたね。しかも これだけのハンデを負っていても勝っています。フェアな条件を設定してまともなプログラムを書いて比較したら、もっと差がつけられそうですね。

結論

　Goが最速だったので、やっぱりGo言語を辞める必要はありませんでした。

本日の教訓

• ベンチマークをする時には制約条件を明確にしましょう
  • 想定するデータの制約
  • 利用可能なメモリの制約
  • 利用していい手段の制約（たとえばCgoとかCFFIを使ってCでゴリゴリにチューニングするのはアリか？）
• ベンチマークをするときには、何を測定しているのかを明確にしましょう
  • ネットワーク遅延も含めたワークロード全体？
  • CPUが仕事をしている時間？
  • ユーザー空間でCPUを使っている時間？
  • 自分が書いた部分のコードがCPUを使っている時間？
• ベンチマークをするときは、結果を再現可能するための情報を可能な限り記録しましょう
  • 実行環境（マシンの種類、CPU、RAM等）
  • 実行したコード
  • 実行したコマンドの履歴
• ベンチマークをするときは、標準的なツールを使いましょう
  • Goなら go test -bench、Pythonなら pytest
  • ただし、異なる言語間での比較をしたい場合はツールを揃えるのは難しい
  • でも、time コマンドはほぼすべてのUNIX-like環境で使える

ちなみに、、、

　元記事の計測結果では、Go実装がCSVの書き込みにすごい時間がかかっていた（約4.7秒）のですが、自分の環境では再現することができませんでした。

　元記事の実行環境が明記されていないので推測でしかありませんが、もしかすると Docker Desktop on Windows を使って計測していたのかな、と思っています。
　今回の計測では各言語の実装コードやベンチマークファイルはホスト上のディレクトリにあり、dockerコンテナからはそのホストのディレクトリをマウントして実行するようになっています。実行結果（CSVファイル）もマウントしたディレクトリに書き出されます。

　Docker Windowsでは、ホスト（Windows）のディレクトリへのアクセスはものすごく遅く、しかもGoの実装では Write I/O がバッファリングされていなかったので、ここがボトルネックになっていたのではないかと推測しています。（コメント欄で @makiuchi-d さんが指摘されている通り）
　ですが、Linuxホスト上ではここはボトルネックになっていませんでした。

※追記：ご本人から回答をいただきました
　元記事ではDocker Desktop for Macを使って測定していたとのことです。
　詳しくは下のコメント欄をご覧ください。

※追記：結局、言語の差なんてなかった件

　@kazeburo さんによる記事 「Re: 結局、Go言語をやめる理由はなかった件」 で、秘伝のタレによって10倍近い爆速 になっていました。

これくらいなら正直どの言語でやってもいいのではないかと思います。仲良くしましょう

　これぞ真理。

---

1. ちなみに、Python の MySQLdb 実装は、fetchone で一行ずつ読み込んだとしても、メモリ上には一度にすべて読み込んでしまうか、もしくはソケットのコネクションをブロックしてMySQLサーバ側にムダに負担をかける実装になっていると批判されていました。今もそうなっているのかは知りませんが、こういう事情なので今回はPython実装を一行ずつ読み込むように変更して比較することはしませんでした。 ↩