お題
前回は「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サーバを起動。
[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に永続化。
[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")
})
}
[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」というO/Rマッパーを使ってMySQLのデータベースよりコネクションを取得しているが、明示的にプール数を指定していない。
[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
}
この場合のデフォルト値がどうなるかを調べる。
gormがラップしているsql.DBの設定メソッドの中で、コネクションプールに関係していそうなのは下記。
[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/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に設定してみる。
[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サーバに対して負荷をかけてみようか。