mackerel plugin で瞬間的な負荷を捉える mackerel-plugin-maxcpu
とあるAPIに対するアクセスが、
回数 時間 1833 time:27/Oct/2020:21:32:25 1657 time:27/Oct/2020:21:32:26 1616 time:27/Oct/2020:21:32:27 2584 time:27/Oct/2020:21:32:28 14958 time:27/Oct/2020:21:32:29 6619 time:27/Oct/2020:21:32:30 1725 time:27/Oct/2020:21:32:31 1796 time:27/Oct/2020:21:32:32 1713 time:27/Oct/2020:21:32:33 1932 time:27/Oct/2020:21:32:34 1797 time:27/Oct/2020:21:32:35 1841 time:27/Oct/2020:21:32:36
という感じで、一瞬だけ急増し、1秒後にはほぼ戻るようなことがあり、この瞬間にCPUが尽きることで全体のレスポンスタイムに影響してしまうようなことがありました。
とりあえず台数を増やしてスケールアウトで対応してるわけですが、大元の原因の解決するまで、CPUの使用率が100%に近くなる瞬間がないか監視しておきたいということで、新しく mackerel plugin を作成しました。
CPU使用率の計算
Linuxの場合、よくあるツールではCPUの使用率を /proc/stat のファイルを読んで計測します。
$ cat /proc/stat |head cpu 4102976 0 548407 3258934935 6723 0 115819 0 0 0 cpu0 115620 0 14370 81452406 84 0 2527 0 0 0 cpu1 123341 0 12898 81453921 748 0 2527 0 0 0 cpu2 109211 0 16473 81465621 82 0 2505 0 0 0 cpu3 109706 0 14273 81467250 216 0 2513 0 0 0
cpuの行の数値は、user, nice, system, idle, iowait, irq, softirq.. と各モードに入っていた時間(USER_HZ)、CPU使用率を出すツールは一定周期でこのファイルを確認し、それぞれの数値の増分を使ってCPU使用率を計算しています。
通常のmackerel pluginの場合、1分周期でpluginが実行されるため、1分間の平均CPU使用率しか計算ができません。1分のあいだの最大値は取得できません。そこで、maxcpuでは初回plugin実行時に、1秒毎にCPU使用率を計測するbackgroundプロセスを作成し、次の起動タイミングからはbackgroundプロセスに前回取得タイミングからのCPU使用率の最大・最小・平均・パーセンタイル値を取得しています。
backgroudプロセスとの通信はgRPC over UNIXドメインソケットで行ってますが、gRPC(http含む)ではバイナリサイズが大きくなってしまうので変更するべきかもしれません。
maxcpuの使い方
gRPC over UNIXドメインソケットに使う --socket だけ指定します。
[plugin.metrics.maxcpu] command = "/usr/local/bin/mackerel-plugin-maxcpu --socket /var/run/maxcpu.sock"
maxcpuでは運用がしやすいように、バイナリが入れ替わった際にbackgroundプロセスは自動で再起動(新しいプロセスを作成し、自プロセスを停止)します。このためpluginのアップデート時に手動にて再起動する必要はありません。この機能を実現するため、SO_REUSEPORT を使っています。
また、一定時間gRPCの通信がないと停止して、余計なリソースを使い続けることはないようにしています。
作成されたグラフは以下のようになります。何回かCPUが跳ねているのがわかります。
ニッチなpluginですが、ニーズが合えばお使いください。
mkr hosts にコントリビュートした話
こちらでリリースの紹介があったmkrコマンドに一つコントリビュートしておりました。
リリースされたのは、mkr v0.41.0 です。
一つ前のバージョンまで mkr hosts は検索結果が一台もないと、null が返っていました。
$ mkr hosts --service all-working-service --status poweroff null
これだと、jq コマンドで何かしら処理するのが面倒。とあるスクリプトでは以下のようにしていました。
HOSTS=$(mkr hosts --service all-working-service --status poweroff)
if [ "${HOSTS}" == "null" ]; then
HOSTS="[]"
fi
for _ID in $(echo "$HOSTS"| jq -c -r '.[].id')
do
...
done
これだとやっぱり面倒ということで、Pullrequestを作って、マージしていただきました。
実質的なdiffはこれだけ
diff --git a/hosts/app.go b/hosts/app.go
index 4778db1..3c41be7 100644
--- a/hosts/app.go
+++ b/hosts/app.go
@@ -54,7 +54,7 @@ func (ha *hostApp) findHosts(param findHostsParam) error {
case param.verbose:
return format.PrettyPrintJSON(ha.outStream, hosts)
default:
- var hostsFormat []*format.Host
+ hostsFormat := make([]*format.Host, 0)
for _, host := range hosts {
hostsFormat = append(hostsFormat, &format.Host{
ID: host.ID,
sliceをvarではなくmakeで作成することで、nil sliceにならず、Marshal時に null ではなく意図通り [] として出力されました。
これで楽ができます。
ISUCON10 感想戦で 100,000 超えスコアを出した
感想戦優勝なんてものはない
— 紅葉坂乗り過ごして桜木町 (@kazeburo) 2020年10月12日
ISUCON10本選は悔しいところではありましたが、Fail(失格)で終わってしまいましたが、1週間もの長い間サーバとベンチマーカーが使えるようにして頂いていたので、感想戦にチャレンジし、24x7 ベンチマークを回し、最終的には100,000超え(本選時の弊チームベスト 32,312、優勝者スコア 49,545)のスコアを出すことに成功しましたので、その方法です。
レポジトリはこちらにあります。
この記事を読み進める前に当日のマニュアルを確認するとよいでしょう
最終スコア
101,249 がベストで最後のスコアです。
この際のTeamCapacityは100です
15:07:32.437656 ===> PREPARE 15:07:41.629186 ===> LOAD 15:08:51.629218 ===> VALIDATION 15:08:58.020129 ===> SCORE Count: admin-answer-clarification: 599 admin-get-clarification: 599 admin-get-clarifications: 63 audience-get-dashboard: 3378 create-team: 100 enqueue-benchmark: 4721 finish-benchmark: 4704 get-clarification: 672 get-dashboard: 448 join-member: 200 list-notifications: 48676 post-clarification: 672 push-notifications: 49167 resolve-clarification: 597 (53906 * 2.0) + 337 - 6900(err: 0, timeout: 6941) Pass: true / score: 101249 (108149 - 6900)
他のチームでは、FetchDecodeExecWriteが91,874、百万円ドリブンが88,331を記録しています。みんなすごい
百万円ドリブンの方のブログはこちら
サーバ構成
本選時の最終構成がこちら
サーバ101にWeb(主にweb画面用API)とAPI(ベンチマーカー用API)のプロセスがいる状態で、envoyを102、MySQLが103でした。ただし、~/env に設定されている BENCHMARK_SERVER_HOST が101のままだったので、仮想ベンチマーカーからのpollingリクエストは101に届いているという状況でした。このため101ではenvoyが動いたままでした。
大きな改善として、APIのプロセスにてHTTPサーバを起動して、ベンチマークのエンキューがあった際に、WebからAPIにHTTPリクエストを送るようにしていました。
API側
func pollBenchmarkJob(db sqlx.Queryer) (*xsuportal.BenchmarkJob, error) {
select {
case _ := <-benchmarkJobIdChannel:
var job xsuportal.BenchmarkJob
err := sqlx.Get(
db,
&job,
"SELECT * FROM `benchmark_jobs` WHERE `status` = ? ORDER BY `id` LIMIT 1",
resources.BenchmarkJob_PENDING,
)
return &job, nil
case <-time.After(200 * time.Millisecond):
return nil, nil
}
}
func enqueueBenchmarkJob(e echo.Context) error {
benchmarkJobIdChannel <- 42
return e.JSON(http.StatusOK, nil)
}
func main() {
...
benchmarkJobIdChannel = make(chan int, 300*4) // xsuportal.TeamCapacity
srv := echo.New()
srv.POST("/api/contestant/benchmark_jobs/:id", enqueueBenchmarkJob)
go func() {
srv.Start(":60051")
}()
....
}
Web側
url_target := fmt.Sprintf("http://10.162.47.101:60051/api/contestant/benchmark_jobs/%d", job.ID)
args := url.Values{}
res, err := http.PostForm(url_target, args)
if err != nil {
return fmt.Errorf("pass job id to benchmark: %w", err)
}
io.Copy(ioutil.Discard, res.Body)
res.Body.Close()
これにより、ジョブの起動速度の改善とMySQLの負荷削減が行われ、スコアも上昇してました。
また、WebPushやオーディエンスのleaderboard(Dashboard)のキャッシュなども実装してありました。
そして、スコア100,000を出したときの構成が下。
一週間の様々なトライがありましたが、最終的にはそれほど変わらない構成に落ち着いています。
変わったのは、静的コンテンツを出すためのnginxとleaderboardの処理を102に寄せたところです。
MySQLの追加設定
メモリが1GBと最近扱っているサーバの1/1000ぐらいなので、メモリ不足に陥らないような設定も必要となるでしょう。
disable-log-bin innodb_doublewrite = 0 innodb_flush_log_at_trx_commit = 0 innodb_flush_method = O_DIRECT innodb_adaptive_hash_index = 0 max_connections=1024 sort_buffer_size = 128K read_buffer_size = 128K
sort_buffer_size/read_buffer_sizeはもっと小さくてもいいのかもしれない。 本当に1024接続きたらメモリ不足で死にます。
延長戦での変更点
いろんなことを試していたので、覚えている限りで変更点です。
nginxでの静的コンテンツ配信 + gzip_static
102上にnginxをたてて、サイズの大きな静的コンテンツをnginxのgzip_staticを使って配信しました。
envoyに以下を追加
routes:
- match:
prefix: "/packs"
route:
cluster: xsuportal_web_static
- match:
prefix: "/favicon.ico"
route:
cluster: xsuportal_web_static
nginxは設定ファイルのbackupを忘れましたが、gzip_staticを有効にして、大きなjsは事前に圧縮しています。 これによりチーム作成と参加時の負荷を抑えられました。
leaderboardのbackground生成
リクエスト来た時にcacheを作るのではなく、backgroundのgoroutineでcacheを更新しました
func backgroundLeaderboardPB() {
ticker := time.NewTicker(500 * time.Millisecond)
defer ticker.Stop()
for {
select {
case <-ticker.C:
leaderboard, err := makeLeaderboardPB(0)
audienceDashboardCacheLock.Lock()
audienceDashboardCache = res
audienceDashboardCacheTime = n.UnixNano() + 800000000
audienceDashboardCacheLock.UnLock()
}
}
}
func (*AudienceService) Dashboard(e echo.Context) error {
audienceDashboardCacheLock.RLock()
if audienceDashboardCache != nil && audienceDashboardCacheTime > time.Now().UnixNano() {
defer audienceDashboardCacheLock.RUnlock()
return e.Blob(http.StatusOK, "application/vnd.google.protobuf", audienceDashboardCache)
}
audienceDashboardCacheLock.RUnlock()
log.Printf("cache miss audience dashboard")
// 通常の処理
cacheの有効期限は700msecから900msecぐらいで様々調整しましたが、時間内にcache生成ができないケースも多く発生したので、リクエストがきた際に有効期限が切れていた場合にDBにアクセスするようになってました。
後述するクエリの最適化をした後は、cacheの有効期限はいくら伸ばしても大丈夫になってました。
polling処理の改善
fujiwara組のblogを参考に、polling処理に RAND() を使うようにしました。
func pollBenchmarkJob(db sqlx.Queryer) (*xsuportal.BenchmarkJob, error) {
select {
case _ := <-benchmarkJobIdChannel:
var job xsuportal.BenchmarkJob
err := sqlx.Get(
db,
&job,
"SELECT * FROM `benchmark_jobs` WHERE `status` = ? ORDER BY RAND() LIMIT 1",
resources.BenchmarkJob_PENDING,
)
これで、ベンチマーカーが同じjob IDを取り合って無駄に動くことが減ったので、ベンチマークの処理回数がかなり伸び、スコアは 60,000 になりました。
これで成仏できる.. pic.twitter.com/rH4Jfhgcr4
— 中目黒乗り過ごさない (@kazeburo) 2020年10月7日
これで成仏した思っていたら、FetchDecodeチームがスコア 80,000を超えてきたので三途の川の前で引き返し、もうちょいトライすることに
ただし、しばらくはあまりスコアが上がっていかない、だいぶ茨の道でした。
push_subscriptions のcache
ListNotifications で空っぽを返すのは push_subscriptions があるユーザだけ（っぽい？）ので、アクセスのたびにpushが有効化確認するため、push_subscriptionsテーブルへのアクセスしていましたが、ListNotifications アクセスが多いのでインメモリでキャッシュしました。
contest_config のcache
コンテストの開始・終了、グラフのフリーズ時間を持っているテーブルですが、様々なエンドポイントでデータベースにアクセスするのでcacheしました。単純にcacheするだけではなく現在時間をみてキャッシュの中身を一部変更する必要がありました。
エンキュー時にjob IDを渡すように
本選時にうまくいかなかったのですが、WebからAPIに対してjob idを渡すように再度変更。RAND() がなくなりjobの競合がなくなるので多少高速化。
single flightの導入
オーディエンスのLeaderboardはキャッシュの有効期限が切れていた際に、その場で作成し直すようになってましたが、これをsingle flightにすることで、負荷を減らすようにしてみた。
こちらもfujiwara組のblogと以下の記事を参考にしました。
var sfGroup singleflight.Group
func (*AudienceService) Dashboard(e echo.Context) error {
.. cache の処理 ..
res, err, _ := sfGroup.Do("dashboard", func() (interface{}, error) {
leaderboard, err := makeLeaderboardPB(0)
if err != nil {
return nil, fmt.Errorf("make leaderboard: %w", err)
}
r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
return proto.Marshal(r)
})
if err != nil {
return err
}
return e.Blob(http.StatusOK, "application/vnd.google.protobuf", res.([]byte))
}
ベンチマークの後半はprotobufへの変換もCPUを使うようになるので、Marshalまでをsingle flightで包んでいます。
single flightはここだけではなく仮想選手のLeaderboardアクセス、ListBenchmarkJobsなどでも使いました。便利
Leaderboardのgzip
これは最後まで有効にしたり、外したりを繰り返しました。最終的には圧縮が有効になっています。 オーディエンスのLeaderboardのcaccheはbackgroundで作成しているのでそこでついでに圧縮しています。
leaderboard, err := makeLeaderboardPB(0)
r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
res, _ := proto.Marshal(r)
var buffer bytes.Buffer
ww, _ := gzip.NewWriterLevel(&buffer, gzip.BestCompression)
ww.Write(res)
ww.Close()
res = buffer.Bytes()
audienceDashboardCache = res
Accept-Encodingはみていませんmm
Leaderboardを作成するmakeLeaderboardPBでは、最終的には数千行のベンチマークのログを返すことになるのでレスポンスのサイズが大きくなります。最後には仮想選手のLeaderboardもgzip圧縮しています。
学生チームフラグをteamsテーブルに
cacheだけではそろそろスコアが上がらないので、makeLeaderboardPB内の大きなクエリの改善に着手しました。
query := "SELECT\n" +
" `teams`.`id` AS `id`,\n" +
" `teams`.`name` AS `name`,\n" +
" `teams`.`leader_id` AS `leader_id`,\n" +
" `teams`.`withdrawn` AS `withdrawn`,\n" +
" `team_student_flags`.`student` AS `student`,\n" +
" (`best_score_jobs`.`score_raw` - `best_score_jobs`.`score_deduction`) AS `best_score`,\n" +
" `best_score_jobs`.`started_at` AS `best_score_started_at`,\n" +
" `best_score_jobs`.`finished_at` AS `best_score_marked_at`,\n" +
" (`latest_score_jobs`.`score_raw` - `latest_score_jobs`.`score_deduction`) AS `latest_score`,\n" +
" `latest_score_jobs`.`started_at` AS `latest_score_started_at`,\n" +
" `latest_score_jobs`.`finished_at` AS `latest_score_marked_at`,\n" +
" `latest_score_job_ids`.`finish_count` AS `finish_count`\n" +
"FROM\n" +
" `teams`\n" +
" -- latest scores\n" +
" LEFT JOIN (\n" +
" SELECT\n" +
" MAX(`id`) AS `id`,\n" +
" `team_id`,\n" +
" COUNT(*) AS `finish_count`\n" +
" FROM\n" +
" `benchmark_jobs`\n" +
" WHERE\n" +
" `finished_at` IS NOT NULL\n" +
" -- score freeze\n" +
" AND (`team_id` = ? OR (`team_id` != ? AND (? = TRUE OR `finished_at` < ?)))\n" +
" GROUP BY\n" +
" `team_id`\n" +
" ) `latest_score_job_ids` ON `latest_score_job_ids`.`team_id` = `teams`.`id`\n" +
" LEFT JOIN `benchmark_jobs` `latest_score_jobs` ON `latest_score_job_ids`.`id` = `latest_score_jobs`.`id`\n" +
" -- best scores\n" +
" LEFT JOIN (\n" +
" SELECT\n" +
" MAX(`j`.`id`) AS `id`,\n" +
" `j`.`team_id` AS `team_id`\n" +
" FROM\n" +
" (\n" +
" SELECT\n" +
" `team_id`,\n" +
" MAX(`score_raw` - `score_deduction`) AS `score`\n" +
" FROM\n" +
" `benchmark_jobs`\n" +
" WHERE\n" +
" `finished_at` IS NOT NULL\n" +
" -- score freeze\n" +
" AND (`team_id` = ? OR (`team_id` != ? AND (? = TRUE OR `finished_at` < ?)))\n" +
" GROUP BY\n" +
" `team_id`\n" +
" ) `best_scores`\n" +
" LEFT JOIN `benchmark_jobs` `j` ON (`j`.`score_raw` - `j`.`score_deduction`) = `best_scores`.`score`\n" +
" AND `j`.`team_id` = `best_scores`.`team_id`\n" +
" GROUP BY\n" +
" `j`.`team_id`\n" +
" ) `best_score_job_ids` ON `best_score_job_ids`.`team_id` = `teams`.`id`\n" +
" LEFT JOIN `benchmark_jobs` `best_score_jobs` ON `best_score_jobs`.`id` = `best_score_job_ids`.`id`\n" +
" -- check student teams\n" +
" LEFT JOIN (\n" +
" SELECT\n" +
" `team_id`,\n" +
" (SUM(`student`) = COUNT(*)) AS `student`\n" +
" FROM\n" +
" `contestants`\n" +
" GROUP BY\n" +
" `contestants`.`team_id`\n" +
" ) `team_student_flags` ON `team_student_flags`.`team_id` = `teams`.`id`\n" +
"ORDER BY\n" +
" `latest_score` DESC,\n" +
" `latest_score_marked_at` ASC,\n" +
" `teams`.`id` ASC\n"
このクエリ、各チームの最新のスコア、ベストスコア、ベンチマーク試行回数、学生チームかどうかなどを出してきます。
この中から、まず学生チームのフラグをteamsテーブルに持ってくることにしました。
大雑把にteamsテーブル/contestantsテーブルを更新するタイミングで
UPDATE teams LEFT JOIN (SELECT team_id,(SUM(`student`) = COUNT(*)) AS `student` FROM `contestants` GROUP BY `contestants`.`team_id`) `team_student_flags` ON `teams`.`id` = `team_student_flags`.`team_id` SET `teams`.`student` = `team_student_flags`.`student`
としたらdead lockしたので、あとから where team_id = X を入れて、上記のでかいクエリから contestants テーブルのJOINを外しました。
ただ、これだけではあまりスコアに変化が感じられませんでした。
スコアサマリーテーブルの作成
学生フラグだけでは変わりがないので、narusejunのコードを参考にさせてもらって、サマリーテーブルを作りました。
最初はスコアだけでしたが、leaderboardで一切のjoinをしないようにするため、チーム名や学生フラグなどもいれた。
CREATE TABLE `team_scores` ( `team_id` BIGINT NOT NULL PRIMARY KEY, `name` VARCHAR(255) NOT NULL, `leader_id` VARCHAR(255), `withdrawn` TINYINT(1) DEFAULT FALSE, `student_flag` tinyint NOT NULL DEFAULT '0', `best_score` INT, `best_started_at` DATETIME(6), `best_finished_at` DATETIME(6), `latest_score` INT, `latest_started_at` DATETIME(6), `latest_finished_at` DATETIME(6), `finish_count` INT, `fz_best_score` INT, `fz_best_started_at` DATETIME(6), `fz_best_finished_at` DATETIME(6), `fz_latest_score` INT, `fz_latest_started_at` DATETIME(6), `fz_latest_finished_at` DATETIME(6), `fz_finish_count` INT ) ENGINE=InnoDB DEFAULT CHARACTER SET utf8mb4;
スコアは、チームの最新のものと、グラフが更新されなくなる(freeze)直前までのスコアが必要になります。 また、スコアの更新時は次のようにUPDATEクエリを作ることで、余計な参照なく1回のクエリでテーブルの更新をしています。
q := "UPDATE `team_scores`" +
"SET " +
"`best_score` = IF(? >= IFNULL(`best_score`,0),?,`best_score`), " +
"`best_started_at` = IF(? >= IFNULL(`best_score`,0),?,`best_started_at`), " +
"`best_finished_at` = IF(? >= IFNULL(`best_score`,0),?,`best_finished_at`), " +
"`latest_score` = ?, " +
"`latest_started_at` = ?, " +
"`latest_finished_at` = ?, " +
"`finish_count` = IFNULL(`finish_count`,0) + 1 "
args := []interface{}{full, full, full, job.StartedAt, full, markedAt, full, job.StartedAt,markedAt}
if フリーズの時間「前」だったら {
q = q +
", `fz_best_score` = IF(? >= IFNULL(`fz_best_score`,0),?,`fz_best_score`), " +
"`fz_best_started_at` = IF(? >= IFNULL(`fz_best_score`,0),?,`fz_best_started_at`), " +
"`fz_best_finished_at` = IF(? >= IFNULL(`fz_best_score`,0),?,`fz_best_finished_at`), " +
"`fz_latest_score` = ?, " +
"`fz_latest_started_at` = ?, " +
"`fz_latest_finished_at` = ?, " +
"`fz_finish_count` = IFNULL(`fz_finish_count`,0) + 1 "
args = append(args, full, full, full, job.StartedAt, full, markedAt, full, job.StartedAt, markedAt)
}
q = q + "WHERE `team_id` = ?"
args = append(args, job.TeamID)
_, err = db.Exec(q, args...)
と、ここまでくると大きなクエリはもう必要がなくなり、
query := "SELECT " +
"`ts`.`team_id` AS `id`, " +
"`ts`.`name` AS `name`, " +
"`ts`.`leader_id` AS `leader_id`, " +
"`ts`.`withdrawn` AS `withdrawn`, " +
"`ts`.`student_flag` AS `student`, " +
"IF(`ts`.`team_id` = ?,`ts`.`best_score`,`ts`.`fz_best_score`) AS `best_score`, " +
"IF(`ts`.`team_id` = ?,`ts`.`best_started_at`,`ts`.`fz_best_started_at`) AS `best_score_started_at`, " +
"IF(`ts`.`team_id` = ?,`ts`.`best_finished_at`,`ts`.`fz_best_finished_at`) AS `best_score_marked_at`, " +
"IF(`ts`.`team_id` = ?,`ts`.`latest_score`,`ts`.`fz_latest_score`) AS `latest_score`, " +
"IF(`ts`.`team_id` = ?,`ts`.`latest_started_at`,`ts`.`fz_latest_started_at`) AS `latest_score_started_at`, " +
"IF(`ts`.`team_id` = ?,`ts`.`latest_finished_at`,`ts`.`fz_latest_finished_at`) AS `latest_score_marked_at`, " +
"IF(`ts`.`team_id` = ?,`ts`.`finish_count`, `ts`.`fz_finish_count`) AS `finish_count` " +
"FROM `team_scores` `ts` " +
"ORDER BY `latest_score` DESC, `latest_score_marked_at` ASC, `ts`.`team_id` ASC"
err = tx.Select(&leaderboard, query, teamID, teamID, teamID, teamID, teamID, teamID, teamID)
これだけとなりました。このクエリはfile sortとなってしまいますが、チーム数は100ちょいなので無視。
こんなにIFを多用したクエリを書くの初めて...
90,000と100,000のあいだで
ここまでの対策でデータベースの負荷が減り、4coreマシンの半分も使わなくなっていたので、4coreでenvoyとwebを動かすようなサーバ構成を行ったりしたが、あまり好ましい結果がでずに、最終的には戻すことに。
leaderboardの改善を進めてきたもののベンチマーク中になぜか2秒で返せてないtimeoutが1000-3000以上あり、これが全く解消できなかったが、スコア100,000を目指すためには、dashboardより質問への回答やベンチマークの実行完了を優先したほうが良さそうと考えることにしあまり気にしないことに。
また、ベンチマーク中のenvoyの負荷も高くなるので、仮想ベンチマーカーのpollingを行うBENCHMARK_SERVER_HOSTと実ベンチマークのターゲットとなるURLを別にするのも、本選時は意図してませんでしたが、効果があったようです。
ここまでで、だいたい安定的に80,000から90,000ぐらいのスコアがでるようになりました。
最後の調整はいくつかABテストのように試して、効果があったのが仮想参加者のDashboardでsingleflightを使うかどうかでした。
contestFreezesAt := contestStatus.ContestFreezesAt
if contestFreezesAt.Add(-10 * time.Second).Before(time.Now()) {
res, err, _ := sfGroup.Do(fmt.Sprintf("dashboard%d", team.ID), func() (interface{}, error) {
leaderboard, err := makeLeaderboardPB(team.ID)
r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
res, _ := proto.Marshal(r)
var buffer bytes.Buffer
ww := gzip.NewWriter(&buffer)
ww.Write(res)
ww.Close()
res = buffer.Bytes()
return res, nil
})
e.Response().Header().Set("Content-Encoding", "gzip")
return e.Blob(http.StatusOK, "application/vnd.google.protobuf", res.([]byte))
} else {
leaderboard, err := makeLeaderboardPB(team.ID)
r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
res, _ := proto.Marshal(r)
buf := globalPool.Get().(*bytes.Buffer)
defer func() {
buf.Reset()
globalPool.Put(buf)
}()
ww := gzip.NewWriter(buf)
ww.Write(res)
ww.Close()
res = buf.Bytes()
e.Response().Header().Set("Content-Encoding", "gzip")
return e.Blob(http.StatusOK, "application/vnd.google.protobuf", res)
}
何回かの試行の結果、どうもsingle flightを使わない方がスコアは高くなるが、最後のスコアボード検証ができずFailし、single flightを使わないと100,000は届かない、ということで、グラフフリーズの数秒前からsingle flightをやめるようにしてみた。5秒、15秒などを試し、100,000に届いたのが、10秒前でした。
祈る
最後はfailしないことを祈るとか、祈るとか、祈るしかない
祈りながらベンチマーク動かしてる #isucon pic.twitter.com/Sbl2mAewbI
— 紅葉坂乗り過ごして桜木町 (@kazeburo) 2020年10月11日
さいごに
いやぁ、本当に1週間楽しめました。楽しかったです（語彙)
白金動物園さん、すごい問題ありがとう。whywaitaをはじめサイバーエージェントの方々も1週間もサーバ使わせて頂いて、本当に感謝です
ISUCON 10 本選に「チーム中目黒乗り過ごし」で参加して、結果はFailでした
結果はこちら
予選に引き続き、hanabokuro氏、mtokioka氏と参加して、結果はFailで失格となりました。スコア的には8位といったところでしょうか。
白金動物園による問題はISUCONのベンチマーカーで、これまで「スケールアップ」「スケールアウト」しておきましょうで済ませていたものが辛い（楽しい）課題になっておりました。 運営のみなさま、スポンサーのみなさま本当にありがとうございます。
クヤシカー
— 中目黒乗り過ごしたい (@kazeburo) 2020年10月5日
準備
チーム紹介のスライドつくりました
100万円は残りませんでした。
また今回用に、モバイルディスプレイを書いました。
USB 1本で使えるので楽です。
当日
今日は電車乗らないので、中目黒で乗り過ごす心配ナシ
— 中目黒乗り過ごしたい (@kazeburo) 2020年10月2日
予選は六本木のオフィスでやったので、中目黒で乗り過ごしてしまう可能性がありましたが、本選は横浜駅近くの貸し会議室をかりました。電車にのらないので乗り過ごす心配なし。チーム名とは。。
構成と最終スコア
言語は引き続き、Goでやりました。 3台のサーバのスペックがすべて違うのは途中から気付きました。
| id | spec (cpu/mem) | role |
|---|---|---|
| 1 | 2core/1GB | web/benchmarker |
| 2 | 2core/2GB | envoy |
| 2 | 4core/1GB | MySQL |
成功した中で最も高かったスコアは、32,312 でした。
Failしまくっているのがわかるグラフ
序盤
ぱっと見でどこから取り組めばいいのかわからない感じの中、MySQLの負荷が高かったようだったので、pt-query-diest で調べたのが最初。 長大なクエリは気になったけど、interpolateParams の有効化が最初の変更
interporateParams · kazeburo/isucon10-final@48804ed · GitHub
このあと、取り組むところをわかりやすくするために、もう少し負荷をかけてみようということで、TeamCapacityを10=>50=>100と増やしたりしていた。
benchmarkerのpollingのクエリが多いこと、ベンチマークが早く動き出せば、スコアも高くなりそうということで、benchmarkerにhttpサーバを追加し、appから命令をおくってやるようにしたのが12:30過ぎ
use channel to pass pending job by hanabokuro · Pull Request #12 · kazeburo/isucon10-final · GitHub
スコアは 2万弱まで上がる。
中盤
取り除けそうなトランザクションとして ListNotifications のトランザクションを外したのは13時過ぎ
list-noti by kazeburo · Pull Request #18 · kazeburo/isucon10-final · GitHub
これが大きな間違いだったわけだが。
小さい改善とリバートを繰り返し、TeamCapacityを変更しながら、フェイルをいっぱいしすつ、16時過ぎにスコアは3万程度に。
後半
web-pushの実装をいれるも、この時間帯になると
「リーダーボード上の最終 ID 検証に失敗しました」「あるべき通知を受信していないことが検知されました」でずっとFail。
他のチームからの質問の回答をヒントに、makeLeaderboardPB の長いクエリに order by id asc をつけて「リーダーボード上の最終 ID 検証に失敗しました」は出にくくなったところで、再起動試験をして、TeamCapacityを100にして、終了
まとめ
18時前のベンチマークでは通っていましたが、検証では「あるべき通知を受信していないことが検知されました」が連続して発生し、結果はFail。悔しいところとなりました。
感想戦環境で確認していると、どうやら、ListNotificationsのトランザクションを外してしまったがいけなかったようで、トランザクションを戻すと、エラーが出にくくなり（負荷をあげるとでる）、4万点から5万点ぐらいのスコアがでるようになりました。
ベンチマーカーの整合性チェックが厳しい~と思いつつ、みんな条件は同じなので、上位のチームは本当に素晴らしい！！すごい！！！
今回の上位がすべて学生チームとなりましたが、まだまだシニア枠として頑張る所存です。
予選に続いて、生中継がありましたので、奥さん、息子と娘が家で応援してくれておりました。ありがとう〜 チーム名がちょこちょこ画面にでていたはずなので、よかった（？）かな
ISUCON10予選に「チーム中目黒乗り過ごし」で参加し本選出場決まりました
ISUCON10の予選に尊敬するエンジニアであるhanabokuro氏、mtokioka氏と参加して、9位で本戦出場できることになりました。うれしい！ ISUCON8は予選落ち、去年は出題をやらせていただいたので、本選出場は3年ぶりになります
今年の問題も、よく練られた問題で開始から終了まで楽しむことができました。運営のみなさま朝早くから遅くまで本当にありがとうございます。
準備
GoはMackerelプラグインやミドルウェアでよく書いておりますが、、いわゆるWebアプリケーションはあまり書いてないので、手を動かすために去年のISUCON9予選の問題を手元で動かして取り組んでみてました。
ローカル環境で動かすのは以下の記事が役立ちます。
また、Cloud TraceやProfilerを試すために、takonomura氏の記事やgithub repositoryをすごくすごく参考にしました。ありがとうございます！
当日
六本木のオフィスで集まってやることに決めていたので、自宅から移動。
チーム名は中目黒乗り過ごしですが、今日は乗り過ごししないように。。 #isucon
— 中目黒乗り過ごしたい (@kazeburo) 2020年9月11日
これを言いたいが為だけにこのチーム名になっていることは秘密。
半年ぶりに六本木向かっているわけだけど、まずちゃんとした服を着て外に出るのが難しい。
— 中目黒乗り過ごしたい (@kazeburo) 2020年9月11日
開始が12時すぎになったので、半年ぶりにいったオフィスで賞味期限がきれたお菓子などを片付けたりして準備してました。
構成と最終スコア
最終的には3台を使う構成になりました。
作業の順序的にベンチマーカーは103に向けて、NginxとGoがそこで動きます。DBを2つに分割し、chair用とestate用それぞれ専用にしました。 この構成でCPU使用率はGoが40%程度、MySQLの負荷は99%以上になるような状況でしたので、まだまだ改善はできたのではないか、やれることはあったはずと思っています。
最終スコアは 3016 でした。
予選でつかったrepositoryはこちらになります
序盤
開始されてからしばらくベンチマークを動かすことができなかったので、当日マニュアルやソースコードを読む時間にあてました。明らかに不足しているインデックスを追加したり、featureやnazotte検索あたりが重そうだなというと手を付ける箇所を検討していました。空いた時間でbotを避けるnginxの設定もいれました。
今回の予選のサーバは3台すべて1coreのサーバで、ベンチマークを動かしたところMySQLが多くのCPUを使っていることがわかったので、profilerやtraceは一旦おいておいて良さそうと判断し、まずpt-query-digestを使い、DBの解析行いました。
初めの段階でCPU時間を使っているクエリは
SELECT * FROM chair WHERE stock > 0 ORDER BY price ASC, id ASC LIMIT 20
と
SELECT * FROM estate WHERE rent >= 50000 AND rent < 100000 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 0
と
SELECT * FROM estate WHERE (door_width >= 191 AND door_height >= 183) OR (door_width >= 191 AND door_height >= 173) OR (door_width >= 183 AND door_height >= 191) OR (door_width >= 183 AND door_height >= 173) OR (door_width >= 173 AND door_height >= 191) OR (door_width >= 173 AND door_height >= 183) ORDER BY popularity DESC, id ASC LIMIT 20
最初のクエリは単純にindexで済み、3つ目はクエリをもっと単純にできそうでしたが、問題は昇順と降順が混ざる ORDER BY popularity DESC, id ASC でこれを解決するために、MySQL8のアップデートを試すことにしました。
中盤
MySQL8アップデートの作業は他のチューニングとぶつからないように、103のサーバで行いました。MySQL8のアップデートは初めてでしたので、google様に聞いて以下のサイトを参考にしました。画像までありわかりやすかったです。ありがとうございます！
インストール中に、認証方式を新しい認証方式にするか、5.7と互換性にあるモードにするか聞いてくるらしい、というのがわかったのがとくに嬉しいところでした。実際にやってみたところ、最後にmy.cnfの設定を、今の設定を残すか、新しい設定で上書きするか聞いてくれたのも便利でした。設定のdiffもみれ、何が起きるのかも明確でした。別のところで悩みなくなかったのでここは5.7互換モードを選び、新しい設定で上書きしました。
apt-get install のあとmysqlコンソールでデータが読めるか確認したところ、何事もなく読めたので、ベンチマーカの向き先を 103 にして実行。スコアは半分程度にさがりましたが無事にベンチマークが成功しているので、クエリとindexのチューニングで改善すると考え、MySQL8で続行しました。
create index idx_pop on isuumo.chair(popularity desc); create index idx_pop on isuumo.estate(popularity desc);
ORDER BYに関してはこの2つで多くは解消しました。
mysql> explain SELECT * FROM chair WHERE price >= 3000 AND price < 6000 AND height >= 80 AND height < 110 AND width >= 80 AND width < 110 AND depth >= 150 AND stock > 0 ORDER BY popularity DESC, id ASC LIMIT 25 OFFSET 25\G
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: chair
partitions: NULL
type: index
possible_keys: idx_price,idx_depth,idx_height,idx_width,stock
key: idx_pop
key_len: 4
ref: NULL
rows: 286
filtered: 0.16
Extra: Using where
1 row in set, 1 warning (0.00 sec)
idx_popが選ばれて、rowsが小さくなってます。MySQL8賢い。信じてた。
MySQL8のアップデート後一旦さがったスコアは、indexの整理、ドアの大きさのクエリの改善、nazotte検索のN+1の解消、SELECT COUNT(*) を goroutineで取得などをいれることで良くなり、1000を超えるスコアになってきていました。
nazotte検索のN+1は
SELECT id,latitude,longitude FROM estate WHERE latitude <= ? AND latitude >= ? AND longitude <= ? AND longitude >= ?
のクエリのあと
SELECT * FROM estate WHERE
(id = ? AND ST_Contains(ST_PolygonFromText(%s), ST_GeomFromText('POINT(%f %f)')))
OR (id = ? AND ST_Contains(ST_PolygonFromText(%s), ST_GeomFromText('POINT(%f %f)')))
OR (id = ? AND ST_Contains(ST_PolygonFromText(%s), ST_GeomFromText('POINT(%f %f)')))
..
と2回のクエリで取得するようにしています。ベンチマーカーからのリクエストではHitするのが多くても数百件でしたのでこれで十分な性能がでると判断しました。
ここまで1台でやってきてましたが、MySQLの負荷を低減させるのが難しく複数台構成への変更を行いました。chairとestateテーブルはJOINを行わなず、複雑なトランザクションなどもないので、テーブルごとにDBを分割する方法をとりました。自分はレプリケーション案を出していましたが、分割案ではレプリケーション遅延などを考える必要もなくシンプルに負荷分散ができるこちらで行くことに決め、101、102のサーバのMySQLのアップグレード作業を行いました。
分割後、スコアは2000程度まで上昇。これがだいたい18:30ぐらいでした。
終盤
ここから、細かく次のようなチューニングを行い、
- estateとchairのbuk insert
- buyChair時のクエリを削減
- getLowest のcache
- chair と estateの検索をcache
- nazotte検索の最初のクエリをcovering indexになるように調整
20時をまわったところで一旦再起動試験、ufwやapparmorを無効にして再起動して問題がないことを確認。 20時半に3000点を超えたところで、作業を終了にしました。
よかったところと反省点
初手から複数台構成やキャッシュ戦略を取らず、pt-query-digestやkataribeを使い、ログを解析しながら手を動かして行った点、複数台構成を最初に行わなかったことで大きな変更の検証や、MySQL8へのアップグレードを使ってないサーバを使って試せたのはよかった。逆に、MySQLの負荷が最後まで下がらず、負荷を大幅に押さえるような手段が取れなかったのは、まだまだ精進しなければならないところ。本選に行くチャンスを得たので、反省含め頑張っていきたい。
今回、生中継があったので奥さん、息子、娘も家でちょこちょこ見て応援してくれていたようです！ありがとう！！！
Nginxのupstreamコンテキストでの名前解決に nginx-dynamic-upstream-resolve-servers を使う
Nginxでproxyする際に、名前解決を動的に行ってからupstreamへ接続をするというのは、S3だったりConsulで管理されたサーバ群に対するproxyを行いたい場合に使いたくなる機能のひとつ。
ただ、upstreamコンテキスト内の resolve オプションは有償の Nginx Plusにしかない機能なので、set変数を使ってやるというのがこれまでの方式
resolver 127.0.0.1 valid=30s ipv6=off;
server {
set $backend_host "backend-apps.service.dc.consul:8080";
location / {
proxy_pass http://$backend_host;
}
}
この方式は問題なく動くのですが、
- upstream keepaliveが有効にならない
- 名前解決した結果に複数のIPがあっても、接続が失敗した際のretryが行われない
といった問題、課題がありました。
そこで、nginxにchoconを同居させ
upstream chocon {
server 127.0.0.1:8080 max_fails=5 fail_timeout=3s;
server 127.0.0.2:8080 max_fails=5 fail_timeout=3s backup;
keepalive 16;
keepalive_requests 1000;
}
server {
proxy_http_version 1.1;
proxy_set_header Connection "";
proxy_set_header Host "backend-apps.service.dc.consul.ccnproxy";
location / {
proxy_pass http://chocon;
}
}
などという方法をとっていましたが、ミドルウェアを減らしよりシンプルにしたいなとずっと考えていました。
3rd party moduleの利用
流れ星に resolve オプションがOSSにきますようにと願いながら、3rd party moduleでresolve相当の機能がある
を試しました。
こちらのnginxモジュールを使うと、
resolver 127.0.0.1 valid=30s ipv6=off;
upstream backend_apps {
server backend-apps.service.dc.consul:8080 resolve max_fails=10 fail_timeout=3s;
keepalive 16;
keepalive_requests 1000;
}
server {
proxy_http_version 1.1;
proxy_set_header Connection "";
location / {
proxy_pass http://backend_apps;
}
}
と、resolveオプションが使えるようになります。何これ最高！
、、、だったのですが、検証の結果、一見問題ないのですが、サーバの増減時にNginxのworkerがsegmentation faultで落ちるということがわかりました。
モジュール自体、最終更新から5年たっており、修正される気配もなさそうです。
そこで次に見つけたのが nginx-upstream-dynamic-servers のissueで紹介されていた zhaofeng0019 さんの nginx-dynamic-upstream-resolve-servers
このモジュールは nginx-upstream-dynamic-servers のsegvなどのissueを修正し、いくつか変更を加えています。もっとも大きな違いは、Nginx本体へのpatchが必要なことです。コードを追いかけていけば本体へのpatchは納得する範囲です。
使い方は nginx-upstream-dynamic-servers とまったく同じで。use_lastというオプションが追加されています。
ビルド方法
cubicdaiyaことbokkoのnginx-buildを使ってbuildしていきます。nginx-1.18.0で確認済みです
configure.sh
#!/bin/sh
./configure \
--prefix=/path/to/nginx-1.18 \
--with-http_ssl_module \
--with-http_realip_module \
--with-http_stub_status_module \
--with-http_v2_module \
--with-pcre-jit \
modules3rd.ini
[nginx-upstream-dynamic-resolve-servers] form=git url=https://github.com/zhaofeng0019/nginx-upstream-dynamic-resolve-servers.git rev=9ad9322e99fa9f07fb3dc1cbdef355d1ae81f376
ビルド
Nginxへのpatchはこちら
$ curl -O https://gist.githubusercontent.com/kazeburo/01d1901eece9341aaaa92194ce1b4251/raw/03a126359746b8a41ed03124aa952120ae83815d/nginx-upstream-dynamic-resolve-servers.patch
$ nginx-build \
-clear \
-d work \
-v 1.18.0 \
-patch nginx-upstream-dynamic-resolve-servers.patch \
-patch-opt "-p1" \
-c configure.sh \
-m modules3rd.ini \
-zlib \
-zlibversion=1.2.11 \
-verbose \
-pcre \
-pcreversion=8.44 \
-openssl \
-opensslversion=1.1.1g \
これでビルドできると思われます。Mac上で確認しています。
実は nginx-upstream-dynamic-resolve-servers にもsegvする問題があったのですが、PRを出したところ解決していただきました。
早速productionでもconsulで構成するserver群に対して nginx-upstream-dynamic-resolve-servers でproxyして問題なく動いてます。consul maintを行って数秒後にはリクエストが正しく止まること、keepaliveされることなどは確認、検証しています。便利！！
2019年 作った・喋ってきたまとめ
振り返り的なやつです。
去年の振り返りはこちらです。
ISUCON9 予選出題した
bokko, catatsuy, sota1235 とともにISUCON9の予選出題をやらせていただいた。7月から9月にかけて圧倒的に手を動かした。
解説と講評のほか、ローカル環境で予選問題を動かす方法についての記事を書かせてもらった。
参加していただいた方、出題メンバー、各言語への移植をやっていただいた皆様、さくらインターネットの皆様、アリババクラウドの皆様、そして941さんをはじめLINEの皆様、改めて感謝です。
作った
percentile
説明はないが、簡単にpercentileを求められるようにするコマンドです。
$ grep status:499 access.log|lltsv -K -k ptime|percentile count: 353 avg: 0.0088 95pt: 0.0440 90pt: 0.0400 75pt: 0.0030
grep、jqやlltsvと組みあわせると便利
mackerel-plugin-axslog
mackerel-plugin-accesslogで少し足りない機能があったので作った。一度つくった上で、より速いやつが書けそうだと思って書き直したら速くなった。
blogも書いている
「秒間2万req、1分間で120万行のログが記録される、よくある環境」はほんの少し盛っている
ppdp
某DBサーバへの通信のログを取りたいということで作った。アクセス元も必要なのでproxy protocol対応を行なった。
どこか => [tcp] => nginx stream => [proxy proto] => ppdp => [tcp] => mysql
のように使う。
名前はペンパイナッポーアッポーペンからきている
deteco
公開鍵で暗号化したJWTをnginxのauth_requestで認証するための、簡単な認証サーバ
TCP over websocket と組み合わせて使うことを考えていた。
mackerel-plugin-log-incr-rate
2つのログの増える行数の比率を出すmackerel plugin。アプリケーションのログが爆発したときに書いた。
Go言語の初期状態のbufio.Scannerは1行の長さが65kを越えると、すぎゃんをやめてしまう仕様なのだが、その中で1MBを越えるログが発見された思ひでも
mackerel-plugin-postfix-log
メール送信をインストール型のソフトウェアからクラウド型のサービスに切り替えたので、中継サーバとしてのpostfixの監視重要性が高まったので書いた。
メトリクスはいくつか増えるが、役に立っているかどうか聞かれると、そんな役に立ってない。まだ。
consul-service-has-ip
指定したconsulのサービスに、任意のIPアドレスが含まれるかどうか確認するのを簡単にするAPIサーバ。
Slaveサーバの分散・切り離しに必要になって作ったが、もっと良い別の方法を発見し、3日ぐらいでお蔵入り。書いたからってそこにしがみつかないことも大事。
mackerel-plugin-pinging
データセンター間の通信を普段からモニタリングしていくために作った。
Mackerel アドベントカレンダーの記事として紹介している
成功失敗だけではなく、RTTのパーセンタイルもでるので、便利。
myps
MySQLのprocesslistをgrepしたり、思いの強いクエリKILLするのに便利なコマンド。便利ツールはいざと言う時に思い出さず、やくに立たないので、作ったことを自分で忘れないようにblogも書いた。
grepとlltsvで別の監視に使うことも考えている。
喋ってきた
なんと2回しか喋ってない
第22回 Lucene/Solr勉強会 10/28
検索まわりのこれまでストーリーを短めに紹介させてもらった。
タイトル・構成はYAPC::Asia 2007 の際の Brad Fitzpatrickの発表「LiveJournal: Behind The Scenes」のインスパイアです
Mackerel day #2 12/23
ここ1年で作ってきたプラグインやDB周りの監視について課題を交えながら紹介した。見事に時間オーバーした。
--
先日、10年ぶりぐらいにデータセンターにて、1Uサーバのハードウェアを増設する作業を行なった。以前は作業していると手がいつのまにか赤くそまっているようなことがあったが、サーバもサーバをマウントするレールもラックも非常に精度が高く作られており、スムーズにきっちりと動くことに非常に感動した。こういった機器を設計、製造する方々のおかげで我々の業務が成り立っているとの思いを新たにした。
家族、チームのメンバーに感謝するとともにお客様に信頼性や価値を届けるため、面白かっこいいぜ！な仕組みの構築運用に取り組んで行きたい
