Go製の負荷ツール「Vegeta」でRDBアクセスのあるWebAPIをいじめてみる。

# お題
[前回](https://qiita.com/sky0621/items/5b65aff97765455dd31d)は「[Vegeta](https://github.com/tsenart/vegeta)」のコマンドオプションを軽くさらってみた。
今回は、やや実践というか、単にリクエストを受け付けて”OK"を返すだけでなく、RDBのテーブルに１リクエストあたり１レコード投入するWebAPIに対して負荷をかけてみることにする。

# 開発環境
### # OS
```
$ cat /etc/os-release 
NAME="Ubuntu"
VERSION="18.04.2 LTS (Bionic Beaver)"
```

### # Cloud SDK
```
$ gcloud version
Google Cloud SDK 241.0.0
```

### # Golang
```
$ go version
go version go1.11.4 linux/amd64
```

### # Vegeta

```
$ vegeta -version
Version: cli/v12.2.0
Commit: 65db074680f5a0860d495e5fd037074296a4c425
Runtime: go1.11.4 linux/amd64
Date: 2019-01-20T15:07:37Z+0000
```

# 実践

## 負荷のかけ先の情報

手元のローカルLinux(Ubuntu)マシン上で試してみる。
他のソフトも動いている状況なので、厳密な負荷の計測はできない。

### Spec

CPUはコア４つ。メモリは１６GB。（半分くらい他のソフト関連で使用済みだけど。）

#### CPU

```
$ cat /proc/cpuinfo 
processor	: 0
　〜〜　省略　〜〜
model name	: Intel(R) Core(TM) i5-6200U CPU @ 2.30GHz
　〜〜　省略　〜〜
cpu MHz		: 600.006
cache size	: 3072 KB
　〜〜　省略　〜〜

processor	: 1
　〜〜　省略　〜〜
model name	: Intel(R) Core(TM) i5-6200U CPU @ 2.30GHz
　〜〜　省略　〜〜
cpu MHz		: 600.008
cache size	: 3072 KB
　〜〜　省略　〜〜

processor	: 2
　〜〜　省略　〜〜
model name	: Intel(R) Core(TM) i5-6200U CPU @ 2.30GHz
　〜〜　省略　〜〜
cpu MHz		: 600.008
cache size	: 3072 KB
　〜〜　省略　〜〜

processor	: 3
　〜〜　省略　〜〜
model name	: Intel(R) Core(TM) i5-6200U CPU @ 2.30GHz
　〜〜　省略　〜〜
cpu MHz		: 600.016
cache size	: 3072 KB
　〜〜　省略　〜〜
```

#### Memory

```
$ cat /proc/meminfo 
MemTotal:       16341516 kB
MemFree:          565220 kB
MemAvailable:    7626996 kB
Buffers:          852652 kB
Cached:          6772228 kB
SwapCached:            0 kB
　〜〜　省略　〜〜
```

```
$ free -h
              total        used        free      shared  buff/cache   available
Mem:            15G        7.1G        604M        794M        7.8G        7.3G
Swap:          975M          0B        975M
```

## WebAPIソース

ローカル環境では下記の通り「`IS_LOCAL`」環境変数をセットしておく。
これは、ローカル環境で動かす場合と例えばGoogle Cloudのようなクラウド環境で動かす場合とでデータソースの取得フォーマットを変えるため。
今回は、ローカル環境でDockerコンテナ起動するMySQLに接続するケースのみ試すが、継続してクラウド環境等で負荷ツールを試す時用に仕込んでおく。

```
$ env | grep IS_LOCAL
IS_LOCAL=yes
```

RDBへのコネクションを取得し、ルーティングを定義した後、WebAPIサーバを起動。

```go:[main.go]
package main

import (
	"fmt"
	"net/http"
	"os"

	"github.com/jinzhu/gorm"

	"github.com/google/uuid"

	_ "github.com/go-sql-driver/mysql"
	"github.com/labstack/echo"
)

func main() {
	// ローカル環境での実行時は、環境変数にセットしておく。例：「export IS_LOCAL='yes'」
	isLocal := os.Getenv("IS_LOCAL") != ""

	// Cloud SQL (ローカルでは MySQL) への接続
	db, closeDBFunc, err := connectDB(isLocal)
	if err != nil {
		os.Exit(-1)
	}
	defer closeDBFunc(db)

	// WebAPIサーバ起動
	e := echo.New()
	routing(e, db)

	port := fmt.Sprintf(":%s", os.Getenv("PORT"))
	fmt.Printf("[GWFGS] PORT: %s\n", port)
	if isLocal {
		port = ":8080"
	}
	e.Logger.Fatal(e.Start(port))
}
```

ルーティングの中身は以下の通り。
通常のAPIであれば、POSTで受け付ける場合はリクエストBodyに永続化したい内容を詰めるけど、
今回は負荷ツールの検証したいだけなので単純にUUIDを使ってランダムに内容が変わる情報を作成してRDBに永続化。

```go:[main.go]
func routing(e *echo.Echo, db *gorm.DB) {
	// ユーザー登録
	e.POST("/users", func(c echo.Context) error {
		id := uuid.New().String()
		u := &User{
			ID:   id,
			Name: fmt.Sprintf("ユーザー%s", id),
			Mail: fmt.Sprintf("mail-%s@example.com", id),
		}
		if err := db.Save(u).Error; err != nil {
			return c.JSON(http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError))
		}
		return c.JSON(http.StatusOK, "OK")
	})
}
```

```go:[main.go]
type User struct {
	ID   string `gorm:"column:id"`
	Name string `gorm:"column:name"`
	Mail string `gorm:"column:mail"`
}

func (u *User) TableName() string {
	return "user"
}
```

ソースの全量は下記参照。
https://github.com/sky0621/try-gae-go111/blob/24f18c0f3472a49bac8825b5cf87f09798e7e9c2/t03_vegeta_gae/main.go

## 負荷別の検証

### MySQL起動

docker-composeで起動。

```
$ ls -l docker-compose.yml 
-rw-r--r-- 1 sky0621 sky0621 362 May 11 23:23 docker-compose.yml
$
$ sudo docker-compose up
　〜〜　省略　〜〜
```

上記ファイルの中身や起動時のテーブル作成に関しては下記参照
https://github.com/sky0621/try-gae-go111/tree/24f18c0f3472a49bac8825b5cf87f09798e7e9c2/t03_vegeta_gae
・「docker-compose.yml」
・「local/init/1_create.sql」

で、現時点でテーブルの中身が空っぽであることを確認。

```
$ sudo docker ps
[sudo] password for sky0621: 
CONTAINER ID        IMAGE               COMMAND                  CREATED              STATUS              PORTS                               NAMES
6819a5588c73        mysql:5.7.24        "docker-entrypoint.s…"   About a minute ago   Up About a minute   0.0.0.0:3306->3306/tcp, 33060/tcp   t03_vegeta_gae_db_1_1abb6e86579d
$
$ sudo docker exec -it 6819a5588c73 /bin/sh
# mysql -u testuser -p 
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.7.24 MySQL Community Server (GPL)
　〜〜　省略　〜〜
mysql> use testdb
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> show tables;
+------------------+
| Tables_in_testdb |
+------------------+
| user             |
+------------------+
1 row in set (0.00 sec)

mysql> desc user;
+-------+--------------+------+-----+---------+-------+
| Field | Type         | Null | Key | Default | Extra |
+-------+--------------+------+-----+---------+-------+
| id    | varchar(64)  | NO   | PRI | NULL    |       |
| name  | varchar(256) | NO   |     | NULL    |       |
| mail  | varchar(256) | NO   |     | NULL    |       |
+-------+--------------+------+-----+---------+-------+
3 rows in set (0.00 sec)

mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)
```

### WebAPIサーバ起動

```
$ go run main.go 
[GWFGS] PORT: :8080

   ____    __
  / __/___/ /  ___
 / _// __/ _ \/ _ \
/___/\__/_//_/\___/ v3.3.10-dev
High performance, minimalist Go web framework
https://echo.labstack.com
____________________________________O/_______
                                    O\
⇨ http server started on [::]:8080
```

### ■１リクエストのみ実行

そもそも実装した内容が正しく動くか試していないので、まずは１リクエストだけ発行。
curlでもいいけど、負荷ツールを使う記事なので`vegeta`コマンドを使用。

```
$ cat vegeta/post_user.txt 
POST http://localhost:8080/users
$
$ vegeta attack -targets=vegeta/post_user.txt -output=/tmp/vegeta_result.bin -rate=1 -duration=1s
```

当然ながら、成功。

```
mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
|        1 |
+----------+
1 row in set (0.00 sec)

mysql> select * from user;
+--------------------------------------+---------------------------------------------+-------------------------------------------------------+
| id                                   | name                                        | mail                                                  |
+--------------------------------------+---------------------------------------------+-------------------------------------------------------+
| 3b4b350a-d26d-4bf0-afa5-55cd1d395357 | ユーザー3b4b350a-d26d-4bf0-afa5-55cd1d395357 | mail-3b4b350a-d26d-4bf0-afa5-55cd1d395357@example.com |
+--------------------------------------+---------------------------------------------+-------------------------------------------------------+
1 row in set (0.01 sec)
```

### ■秒間 10 リクエストを 10秒継続にトライ

```
$ vegeta attack -targets=vegeta/post_user.txt -output=/tmp/vegeta_result.bin -rate=10 -duration=10s
```

負荷ツールによるレポート結果は、すべて成功。

```
$ vegeta report /tmp/vegeta_result.bin 
Requests      [total, rate]            100, 10.10
Duration      [total, attack, wait]    9.911591453s, 9.90002121s, 11.570243ms
Latencies     [mean, 50, 95, 99, max]  10.552032ms, 10.485257ms, 14.909923ms, 18.981639ms, 19.382076ms
Bytes In      [total, mean]            500, 5.00
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:100  
Error Set:
```

実際、RDBに登録されたレコード数は、お試しで入れておいた１件＋１０件×１０秒で１０１件。合ってる。

```
mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
|      101 |
+----------+
1 row in set (0.00 sec)
```

### ■秒間 100 リクエストを 10秒継続にトライ

いったん、テーブルを空にする。

```
mysql> truncate table user;
Query OK, 0 rows affected (0.05 sec)

mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)
```

実行。

```
$ vegeta attack -targets=vegeta/post_user.txt -output=/tmp/vegeta_result.bin -rate=100 -duration=10s
```

結果。全リクエスト成功だけど、レイテンシーは上がってきた。

```
$ vegeta report /tmp/vegeta_result.bin 
Requests      [total, rate]            1000, 100.10
Duration      [total, attack, wait]    9.995852132s, 9.990115336s, 5.736796ms
Latencies     [mean, 50, 95, 99, max]  9.446727ms, 8.986903ms, 14.687037ms, 18.344098ms, 29.561299ms
Bytes In      [total, mean]            5000, 5.00
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:1000  
Error Set:
```

１００件×１０秒の１０００件すべて入ってる。

```
mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
|     1000 |
+----------+
1 row in set (0.01 sec)
```

### ■秒間 1000 リクエストを 10秒継続にトライ

#### ＜試行＞

いったん、テーブルを空にする。

```
mysql> truncate table user;
Query OK, 0 rows affected (0.04 sec)

mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)
```

実行。

```
$ vegeta attack -targets=vegeta/post_user.txt -output=/tmp/vegeta_result.bin -rate=1000 -duration=10s
```

結果。成功は全リクエストの３割程度になった。
レイテンシー１秒オーバーが発生しているし、それでなくても数100ミリ秒かかっているものが大多数なので、明らかに処理遅延している。

```
$ vegeta report /tmp/vegeta_result.bin 
Requests      [total, rate]            10000, 999.89
Duration      [total, attack, wait]    10.214505392s, 10.001083836s, 213.421556ms
Latencies     [mean, 50, 95, 99, max]  356.803162ms, 359.136175ms, 696.536954ms, 1.116018894s, 1.814554114s
Bytes In      [total, mean]            182050, 18.20
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  30.50%
Status Codes  [code:count]             200:3050  500:6950  
Error Set:
500 Internal Server Error
```

RDBに入ったレコード数も上記でステータスコード 200 OK が返った 3050 件と同じ。

```
mysql> select count(*) from user;
+----------+
| count(*) |
+----------+
|     3050 |
+----------+
1 row in set (0.00 sec)
```

#### ＜原因調査＞

まあ、RDBのコネクションプールについては明示的に指定していないので、そのへんのデフォルト値がどうなっているかと、
WebAPIサーバとしても、１リクエストのタイムアウト値が、やはり明示的に指定なしなのでデフォルト値をチェックしよう。

あ、その前にWebAPIサーバが吐いているログがないか見ないと。

##### WebAPIサーバのログ確認

多数のINSERT文のログに紛れて、以下のようなエラーログが大量に吐かれていた。

```
　〜〜　省略　〜〜

(/home/sky0621/work/src/go111/src/github.com/sky0621/try-gae-go111/t03_vegeta_gae/main.go:87) 
[2019-05-12 22:49:49]  Error 1040: Too many connections 

(/home/sky0621/work/src/go111/src/github.com/sky0621/try-gae-go111/t03_vegeta_gae/main.go:87) 
[2019-05-12 22:49:49]  Error 1040: Too many connections 

(/home/sky0621/work/src/go111/src/github.com/sky0621/try-gae-go111/t03_vegeta_gae/main.go:87) 
[2019-05-12 22:49:49]  Error 1040: Too many connections 

(/home/sky0621/work/src/go111/src/github.com/sky0621/try-gae-go111/t03_vegeta_gae/main.go:87) 
[2019-05-12 22:49:49]  Error 1040: Too many connections 

　〜〜　省略　〜〜
```

##### DBコネクションプール数の確認

以下のコードで「[gorm](https://github.com/jinzhu/gorm)」というO/Rマッパーを使ってMySQLのデータベースよりコネクションを取得しているが、明示的にプール数を指定していない。

```go:[main.go]
func connectDB(isLocal bool) (*gorm.DB, closeDB, error) {
	db, err := gorm.Open("mysql", createDatasource(isLocal))
	if err != nil {
		return nil, nil, err
	}

	db.LogMode(true)
	if err := db.DB().Ping(); err != nil {
		return nil, nil, err
	}

	return db, closeDBFunc, nil
}
```
https://github.com/sky0621/try-gae-go111/blob/24f18c0f3472a49bac8825b5cf87f09798e7e9c2/t03_vegeta_gae/main.go#L64

この場合のデフォルト値がどうなるかを調べる。
`gorm`がラップしている`sql.DB`の設定メソッドの中で、コネクションプールに関係していそうなのは下記。

```go:[go/src/database/sql/sql.go]
// SetMaxOpenConns sets the maximum number of open connections to the database.
//
// If MaxIdleConns is greater than 0 and the new MaxOpenConns is less than
// MaxIdleConns, then MaxIdleConns will be reduced to match the new
// MaxOpenConns limit.
//
// If n <= 0, then there is no limit on the number of open connections.
// The default is 0 (unlimited).
func (db *DB) SetMaxOpenConns(n int) {
　〜〜　省略　〜〜
```

上記は、最大でどれだけコネクションを張れるかの設定である様子。
デフォルトは「`0`」とのことなので、今回の負荷でエラーになった原因ではなさそう。

```go:[go/src/database/sql/sql.go]
// SetMaxIdleConns sets the maximum number of connections in the idle
// connection pool.
//
// If MaxOpenConns is greater than 0 but less than the new MaxIdleConns,
// then the new MaxIdleConns will be reduced to match the MaxOpenConns limit.
//
// If n <= 0, no idle connections are retained.
//
// The default max idle connections is currently 2. This may change in
// a future release.
func (db *DB) SetMaxIdleConns(n int) {
　〜〜　省略　〜〜
```

上記は、アイドリング状態にできるコネクションプールの最大数。
デフォルトは「`2`」とのこと。関係あるとしたら、ここか。

#### ＜修正確認＞
ということで、ここの数値を、負荷をかける秒間1000リクエストに合わせ、`1000`に設定してみる。

```go:[main.go]
func connectDB(isLocal bool) (*gorm.DB, closeDB, error) {
	db, err := gorm.Open("mysql", createDatasource(isLocal))
	if err != nil {
		return nil, nil, err
	}

	db.LogMode(true)
	if err := db.DB().Ping(); err != nil {
		return nil, nil, err
	}

+	db.DB().SetMaxIdleConns(1000)

	return db, closeDBFunc, nil
}
```

WebAPIサーバを再起動し、先ほどエラーが発生したのと同じ負荷をかける。

```
$ vegeta attack -targets=vegeta/post_user.txt -output=/tmp/vegeta_result.bin -rate=1000 -duration=10s
```

結果は、だいぶエラー率が下がった。改善と言えそう。ただ、あと一息。

```
$ vegeta report /tmp/vegeta_result.bin 
Requests      [total, rate]            10000, 1000.01
Duration      [total, attack, wait]    10.018436121s, 9.999932539s, 18.503582ms
Latencies     [mean, 50, 95, 99, max]  51.855648ms, 33.936805ms, 153.788245ms, 204.374335ms, 281.17987ms
Bytes In      [total, mean]            51064, 5.11
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  99.44%
Status Codes  [code:count]             200:9944  500:56  
Error Set:
500 Internal Server Error
```

#### ＜修正確認(２回目)＞

今度は、`SetMaxIdleConns`の設定値を`10000`に上げてみる。
WebAPIサーバを再起動し、先ほどエラーが発生したのと同じ負荷をかける。

```
$ vegeta attack -targets=vegeta/post_user.txt -output=/tmp/vegeta_result.bin -rate=1000 -duration=10s
```

前回のように改善されず。こうなってくると、アプリ側の問題というより、ミドルウェア（MySQL）の方の問題か。

```
$ vegeta report /tmp/vegeta_result.bin 
Requests      [total, rate]            10000, 1000.06
Duration      [total, attack, wait]    10.359391169s, 9.999360893s, 360.030276ms
Latencies     [mean, 50, 95, 99, max]  129.267505ms, 56.912163ms, 551.853224ms, 769.190913ms, 881.883548ms
Bytes In      [total, mean]            65447, 6.54
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  91.87%
Status Codes  [code:count]             200:9187  500:813  
Error Set:
500 Internal Server Error
```

#### ＜修正確認(３回目)＞

よく考えたら、dockerコンテナ起動させているMySQLの設定も確認しておく必要があった。

```
mysql> show variables like "%max_connections%";
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| max_connections | 151   |
+-----------------+-------+
1 row in set (0.01 sec)
```

うん、足りてない。
秒間の負荷に耐えられるだけ上げてみる。

```
mysql> set global max_connections = 1000;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like "%max_connections%";
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| max_connections | 1000  |
+-----------------+-------+
1 row in set (0.00 sec)
```

再実行。

```
$ vegeta attack -targets=vegeta/post_user.txt -output=/tmp/vegeta_result.bin -rate=1000 -duration=10s
```

結果。余裕で全てのリクエストが 200 OK になった。
あ〜、完全にミドルウェアの問題だった・・・。
まあ、あまりコネクション増やしすぎるとメモリ食うのだろうけど、少なくともRDBがボトルネックになっていた事象は解消。

```
$ vegeta report /tmp/vegeta_result.bin 
Requests      [total, rate]            10000, 1000.06
Duration      [total, attack, wait]    10.017606023s, 9.99939783s, 18.208193ms
Latencies     [mean, 50, 95, 99, max]  30.286596ms, 25.360282ms, 56.566478ms, 137.478086ms, 213.348836ms
Bytes In      [total, mean]            50000, 5.00
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:10000  
Error Set:
```

#### ＜対比＞

ちなみに、単純にミドルウェアのみがボトルネックだったのかどうかの確認のため、Goのソース上で`SetMaxIdleConns`を外してみて確認したところ、エラーが再発した。
なので、これはこれで必要な設定だったということか。

# まとめ
どうもあまりお題に即していない内容になった気がする。
次回は、Google App EngineにデプロイしたWebAPIサーバに対して負荷をかけてみようか。