お題

前回、「Vegeta」を使ってローカル環境でMySQLに接続するWebAPIに対する負荷をかけてみた。
お次は、実際にアプリが動く環境として Google App Engine ＋ Cloud SQL を相手に負荷をかけてみるということになるのだけど、まずは、準備。

開発環境

# OS

$ cat /etc/os-release 
NAME="Ubuntu"
VERSION="18.04.2 LTS (Bionic Beaver)"

# Cloud SDK

$ gcloud version
Google Cloud SDK 245.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

実践

デプロイ対象のソース

アプリ本体のソース

大した内容ではないのと、前回も多少説明したので、細かいソースの説明は省略。
要するに、アプリ起動時にCloud SQLにコネクションを張り、「/users」にPOSTリクエストすると１リクエストにつき１レコードを「user」テーブルに登録する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))
}

func createDatasource(isLocal bool) string {
	if isLocal {
		return "testuser:testpass@tcp(localhost:3306)/testdb?charset=utf8&parseTime=True&loc=Local"
	}

	// GCP - CloudSQL への接続情報は環境変数から取得
	var (
		connectionName = os.Getenv("CLOUDSQL_CONNECTION_NAME")
		user           = os.Getenv("CLOUDSQL_USER")
		password       = os.Getenv("CLOUDSQL_PASSWORD")
		database       = os.Getenv("CLOUDSQL_DATABASE")
	)

	return fmt.Sprintf("%s:%s@unix(/cloudsql/%s)/%s?parseTime=True", user, password, connectionName, database)
}

type closeDB func(db *gorm.DB)

func closeDBFunc(db *gorm.DB) {
	if db == nil {
		return
	}
	_ = db.Close()
}

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(10000)

	return db, closeDBFunc, nil
}

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")
	})
}

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"
}

接続先テーブルのDDL

CREATE TABLE IF NOT EXISTS `user` (
  `id` varchar(64) NOT NULL,
  `name` varchar(256) NOT NULL,
  `mail` varchar(256) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE utf8_bin;

App Engineデプロイ定義ファイル

[app.yaml]

runtime: go111

includes:
  -  secret.yaml

[secret.yaml]

env_variables:
  # For Cloud SQL 2nd generation instances, this should be in the form of "project:region:instance".
  CLOUDSQL_CONNECTION_NAME: 【自分のプロジェクトID】:asia-northeast1:sample-001
  CLOUDSQL_USER: root
  CLOUDSQL_PASSWORD: 【rootユーザーのパスワード】
  CLOUDSQL_DATABASE: fs14db01

負荷のかけ先の情報

Clous SQL のセットアップ

インスタンス作成

最も低スペックな設定「db-f1-micro」でインスタンス作っておく。

そして、前回同様、最大同時接続数に余裕を持たせておくことにする。
現在の設定では「280」らしい。で、「1000」にあげようとすると、

MySQL [(none)]> show variables like "%max_connections%";
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| max_connections | 280   |
+-----------------+-------+
1 row in set (0.04 sec)

MySQL [(none)]> set global max_connections = 10000;
ERROR 1227 (42000): Access denied; you need (at least one of) the SUPER privilege(s) for this operation

あれ、変更できない。SUPER権限が必要？
なのだけど、FAQ見てみたら、「Cloud SQL は SUPER 権限をサポートしない」と書いてある。
https://cloud.google.com/sql/faq#grantall
そうなると、
こんなレベルの最大同時接続数では実務に使えないのでは・・・。
あ、「db-f1-micro」だからか。
一番、低スペックなインスタンスにしたせいかも。
https://cloud.google.com/sql/docs/quotas?hl=ja#fixed-limits
そのようだ。
「db-f1-micro」の最大同時接続数は「250」となってる。
「250」？　実測値は「280」のようだけど。
まあ、どちらにせよ、このインスタンスでは負荷をかける対象としては適さない。
「db-g1-small」インスタンスなら「1000」までいけるとのことなので、インスタンスを変更。

サイズアップにより、インスタンス再起動が必要になった。

「db-g1-small」インスタンスに変更完了。（メモリ搭載量の違いしかわからないけど・・・）

実際、最大同時接続数も増えた。（ドキュメント記載の数値より「30」余分なのはなぜだろう。。。）

データベース作成

アプリからは「fs14db01」という名前で接続を試みるので、その名前で作っておく。

MySQL [(none)]> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| fs14db01           |
| mysql              |
| performance_schema |
| sys                |
+--------------------+
5 rows in set (0.03 sec)

テーブル作成

アプリからは「user」という名前のテーブルにアクセスするので、その名前で作っておく。

MySQL [(none)]> use fs14db01;
Database changed
MySQL [fs14db01]>
MySQL [fs14db01]> CREATE TABLE IF NOT EXISTS `user` (
    ->   `id` varchar(64) NOT NULL,
    ->   `name` varchar(256) NOT NULL,
    ->   `mail` varchar(256) NOT NULL,
    ->   PRIMARY KEY (`id`)
    -> ) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE utf8_bin;
Query OK, 0 rows affected (0.05 sec)

MySQL [fs14db01]>
MySQL [fs14db01]> show tables;
+--------------------+
| Tables_in_fs14db01 |
+--------------------+
| user               |
+--------------------+
1 row in set (0.04 sec)

MySQL [fs14db01]>
MySQL [fs14db01]> 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.03 sec)

App Engine デプロイ

ローカル環境のコンソールにて、デプロイ先プロジェクトの設定確認。

$ gcloud config list
[compute]
region = asia-northeast1
zone = asia-northeast1-c
[core]
account = 【自分のアカウント】@gmail.com
disable_usage_reporting = False
project = 【自分のプロジェクトID】

Your active configuration is: [default]

デプロイ。

$ gcloud app deploy
Services to deploy:

descriptor:      [/home/sky0621/work/src/go111/src/github.com/sky0621/try-gae-go111/t03_vegeta_gae/app.yaml]
source:          [/home/sky0621/work/src/go111/src/github.com/sky0621/try-gae-go111/t03_vegeta_gae]
target project:  [【自分のプロジェクトID】]
target service:  [default]
target version:  [20190514t083802]
target url:      [https://【自分のプロジェクトID】.appspot.com]


Do you want to continue (Y/n)?  y

Beginning deployment of service [default]...
╔════════════════════════════════════════════════════════════╗
╠═ Uploading 0 files to Google Cloud Storage                ═╣
╚════════════════════════════════════════════════════════════╝
File upload done.
Updating service [default]...done.                                                                                                                                                                           
Setting traffic split for service [default]...done.                                                                                                                                                          
Deployed service [default] to [https://【自分のプロジェクトID】.appspot.com]

You can stream logs from the command line by running:
  $ gcloud app logs tail -s default

To view your application in the web browser run:
  $ gcloud app browse

負荷をかける

１リクエスト

$ cat vegeta/gae_post_user.txt 
POST https://【自分のプロジェクトID】.appspot.com/users

$ vegeta attack -targets=vegeta/gae_post_user.txt -output=/tmp/vegeta_result.bin -rate=1 -duration=1s

結果。
レイテンシー高いな・・・。ローカルから叩いてるせいかな。
ちょっとあとで、プログラム内にログ仕込んで、１リクエストのINとOUT、及びDBアクセス前後の処理時間を計測してみよう。

$ vegeta report /tmp/vegeta_result.bin
Requests      [total, rate]            1, 1.00
Duration      [total, attack, wait]    923.851771ms, 0s, 923.851771ms
Latencies     [mean, 50, 95, 99, max]  923.851771ms, 923.851771ms, 923.851771ms, 923.851771ms, 923.851771ms
Bytes In      [total, mean]            5, 5.00
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:1  
Error Set:

ちゃんとDBにも入ってる。

MySQL [fs14db01]> select count(*) from user;
+----------+
| count(*) |
+----------+
|        1 |
+----------+
1 row in set (0.03 sec)

MySQL [fs14db01]> select * from user;
+--------------------------------------+--------------------------------------------------+-------------------------------------------------------+
| id                                   | name                                             | mail                                                  |
+--------------------------------------+--------------------------------------------------+-------------------------------------------------------+
| bf6874da-7c0d-41ff-a2ca-4aae8c64c1dd | ユーザーbf6874da-7c0d-41ff-a2ca-4aae8c64c1dd     | mail-bf6874da-7c0d-41ff-a2ca-4aae8c64c1dd@example.com |
+--------------------------------------+--------------------------------------------------+-------------------------------------------------------+
1 row in set (0.03 sec)

１リクエスト（処理時間計測版）

ソースに処理時間計測用のログを仕込む

[main.go(抜粋)]

        e.POST("/users", func(c echo.Context) error {
+               start := time.Now()
+               fmt.Printf("[START] %v\n", start)
+
                id := uuid.New().String()
                u := &User{
                        ID:   id,
                        Name: fmt.Sprintf("ユーザー%s", id),
                        Mail: fmt.Sprintf("mail-%s@example.com", id),
                }
+
+               dbSave := time.Now()
+               fmt.Printf("[from start to db.Save] %v\n", dbSave.Sub(start))
                if err := db.Save(u).Error; err != nil {
                        return c.JSON(http.StatusInternalServerError, http.StatusText(http.StatusInternalServerError))
                }
+
+               fmt.Printf("[from db.Save to end] %v\n", time.Now().Sub(dbSave))
+               fmt.Printf("[from start to end] %v\n", time.Now().Sub(start))
+
+               fmt.Printf("[ END ] %v\n", time.Now())
                return c.JSON(http.StatusOK, "OK")
        })

再度、１リクエスト送ってみる。

$ cat vegeta/gae_post_user.txt 
POST https://【自分のプロジェクトID】.appspot.com/users

$ vegeta attack -targets=vegeta/gae_post_user.txt -output=/tmp/vegeta_result.bin -rate=1 -duration=1s

結果。

$ vegeta report /tmp/vegeta_result.bin
Requests      [total, rate]            1, 1.00
Duration      [total, attack, wait]    937.806167ms, 0s, 937.806167ms
Latencies     [mean, 50, 95, 99, max]  937.806167ms, 937.806167ms, 937.806167ms, 937.806167ms, 937.806167ms
Bytes In      [total, mean]            5, 5.00
Bytes Out     [total, mean]            0, 0.00
Success       [ratio]                  100.00%
Status Codes  [code:count]             200:1  
Error Set:

StackdriverLoggingで仕込んだログを確認。

レイテンシーの「937ms」に対して、１リクエスト内の処理時間としては「22ms」。
ほとんどがプログラムの処理時間外でかかった時間。

検証

試みとしては、ちゃんとした負荷試験では到底なく、お試しでやってるだけではあるものの、負荷をかけることを考えると、ローカル環境からではなく、Vegetaコマンド自体の発行をApp Engineの別サービスを立ててやる、ないし、別でGCEインスタンス立ててやるといったことも考えた方がいいかも。

Vegetaはライブラリとして使ってGoのアプリでラップもできるようなので、HTTPリクエストで負荷度合いのパラメータをもらったら、対象のApp Engineインスタンスにパラメータに応じた負荷をかけるGoアプリを別途作って、複数のGCEインスタンスに配置して一斉に負荷をかけるとかも考えられる。

[2019-05-15]追加検証

レイテンシーが「937ms」かかったのは、ウォームアップのためだった様子。
下記によると、デプロイしたばかりのApp Engineインスタンスには、アプリのコードを読み込むためのリクエストが走ることがあり、その分、別リクエストのレイテンシーが大きくなる可能性があるとのこと。
https://cloud.google.com/appengine/docs/standard/go111/configuring-warmup-requests?hl=ja

実際、５回リクエストを発行したところ、以下の通りとなった。

回	レイテンシー
1	937.806167ms
2	814.035009ms
3	162.590719ms
4	129.247249ms
5	175.187796ms

まとめ

準備編。ひとまずは、ここまで。