2021-02-21

ロシア版ISUCONであるところのHighLoad Cup 2021(Gold Rush)のベータテストがはじまりました

ついにきたぞ！

ロシア版ISUCONともいうべき高負荷環境をチューニングするプログラミングコンテストHighLoad Cup 2021(Gold rush)がついに始まりました。2017年、2018年と2回開催されて以降更新がなかったのですが、All Cupsの一部として装いも新たについに降臨です。いやぁ待った甲斐があったね。

cups.mail.ru

開催日程

現時点での開催日程は以下の通りです。

2021/02/19 - 2021/03/05 Beta-testing

2021/03/05 - 2021/03/26 Battle-round (予選)

2021/03/26 - 2021/04/02 Final round (本選)

Beta-testingの期間もテスト走行は可能ですが、ランキングとしては記録されません。Battle-roundが本番となる見込みです。

Beta-testingの間は仕様が変更になる可能性がありますが、おおよそプログラムの実装を進めておき、Battle-roundの期間で本格的に実装すればokでしょう。期間の間ずっと張り付いている必要はなく、その期間内の任意のタイミングで実装すればokです。

Battle-roundで上位20位になるとFinal roundへ進めるようです。

賞金

賞金は一応用意されています。

1位 200,000ルーブル

2位 150,000ルーブル

3位 125,000ルーブル

4～6位 35,000ルーブル

日本在住者が賞金を貰えるのかはちゃんと確認してません。

はじめかた

ざっくりとはじめかたを紹介します。

アカウント登録

まずはアカウント登録をしましょう。アカウント登録は画面右上のAUTHORIZATIONからRegister Nowを選択すれば可能です。

概要

問題の概要は以下のページにあります。ロシア語だけでなく英語も用意されてますので安心です。

cups.mail.ru

サンプル実装

現時点でPythonによるサンプル実装が用意されています。

github.com

また、swagger.yamlがあるのでこれを参考に実装するのがいいでしょう。

Dockerコンテナイメージ上で稼働できるのであれば実装言語何でもokです。

実装の提出

実装の提出はDockerコンテナを作成して主催者が用意するDockerレジストリにpushして提出することになります。そのため手元にDocker実行環境を用意してください。提出方法の詳細はアカウントでログイン後の MY WORKSPACEをご確認ください。

まずは上記サンプル実装を提出してみてテスト走行してみるのがいいでしょう。

質問など

ちょっとした質問であればTelegramで質問するのがいいでしょう。ロシア語が飛び交ってますが、英語で質問したら丁寧に教えてくれました。

t.me

もしくは私が回答できることならTwitterでいつでもどうぞ。

2020-10-04

ISUCON10本選に出場し17:00時点ではベストスコア1位だったもののfailフィニッシュになりました

TL;DR

ISUCON10本選に出場し、17:00時点でベストスコア1位につけるも最終的にはfailフィニッシュとなった（と思われる）matsuuです、こんにちは。

体制（予選から再掲）

チーム名ウー馬場ーイーツ

あいこん	なまえ	やくわり
	matsuu	バリバリ実装する前衛
	netmarkjp	司令塔
	ishikawa84g	~~SELinux~~AppArmorとレギュレーションやコードやDiscordを見るセキュリティ＆情報官

本選も同じくそれぞれの場所からリモート体制です。

方針

基本的に予選を踏襲してsshrc+tmux+vim(or nvim)です。 gitについてはファイルシステムのルートで git init を実行し、.gitignoreで /home と /etc を記録するようにしました。このあたりはまだ改善余地があったので来年に向けて改善を続けます。

解析ツール

予選と同じのため省略

最終構成

最終構成は以下の通りです。

サーバ	スペック	構成要素	備考
isu1	1コア1GB	envoy+varnish	varnishを追加インストール
isu2	2コア2GB	mysql	バージョン変更なし
isu3	4コア1GB	xsuportal/benchmark_server	golang

当初は1台目のみを使い、ある程度負荷傾向が定まってきてから最適なスペックに配分していきました。

ベンチマーク結果

f:id:tmatsuu:20201004154854p:plain — ベストスコア遷移

あくまでベストスコアであって実際には上下してます。

f:id:tmatsuu:20201004194846p:plain — 全スコア一覧

初動

開始後、自分はkataribeやpt-query-digestなどを設定できるよう調整。言語もrubyからgolangに変更しています。 envoyを自分で触るのはほぼ初めてだったものの、envoyの公式ドキュメントを確認したところデフォルトのログ形式でも %DURATION% として応答時間が記録されることを確認。そのままkataribeに食わせることに。kataribeの設定はこんな感じ。

# kataribe.toml
scale = -3
effective_digit = 3
log_format = '^\[([^\]]+)\] "((?:\\"|[^"])*)" (\d+) (\d+|-) (\d+) (\d+) (\d+) (\d+) .*$'
request_index = 2
status_index = 3
bytes_index = 6
duration_index = 7

今回MySQLのバージョンが最初から8.0.21だったので、予選から本選の間に調べたREDOログの無効化を速攻で実施してます。

ALTER INSTANCE DISABLE INNODB REDO_LOG;

atsuizo.hatenadiary.jp

本番環境で実行しちゃダメだぞ！

マニュアルを読む

私が初動のenvoy調整をしている間に @netmarkjp と @ishikawa84g でマニュアルを通読してもらいました。気になるところは @ishikawa84g がスライドにまとめ上げていて後で参照しやすくとても助かりました。わいわい。

docs.google.com

初回ベンチ実行

初回ベンチ実行でダッシュボード表示(/api/audience/dashboard)が遅いことを確認してます。 kataribe実行結果より

Top 50 Sort By Total
Count     Total    Mean  Stddev    Min  P99.9    Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
11606  1821.391  0.1569  0.1799  0.002  1.560  1.990  11606     0    0    0   249308292          2      21480      25122  GET /api/audience/dashboard HTTP/2
 1596   581.121  0.3641  0.1905  0.001  0.665  0.666   1596     0    0    0       34450          5         21         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
 2978   572.663  0.1923  0.2492  0.001  1.941  2.525   2978     0    0    0       34173          0         11         73  get /api/contestant/notifications?.*

アプリ実装とSQLを確認したもののすぐの改修が難しく、いくつかインデックスの追加しても速度改善が見込めない状況でした。

キャッシュ戦略

ただ、マニュアルをしっかり読んでいたため1秒間はキャッシュできることを確認したのでenvoyとxsuportalの間にVarnishを挟んでキャッシュする戦略としました。初期化対策のため /initialize にアクセスがあった場合はキャッシュを削除するよう設定しています。

# /etc/varnish/default.vcl
vcl 4.0;

backend default {
    .host = "127.0.0.1";
    .port = "9292";
}

sub vcl_recv {
    if (req.url ~ "^/initialize") {
       ban("obj.http.url ~ ^/api/audience/dashboard");
    }
}

sub vcl_backend_response {
    if (beresp.http.content-type ~ "text") {
      set beresp.do_gzip = true;
    }
    if (beresp.http.content-type ~ "javascript") {
      set beresp.do_gzip = true;
    }
    if (bereq.url ~ "^/packs/") {
      set beresp.ttl = 60s;
      set beresp.http.cache-control = "public, max-age=60";
    }
    if (bereq.url ~ "^/api/audience/dashboard") {
      set beresp.ttl = 1s;
      set beresp.http.cache-control = "public, max-age=1";
    }
}

この１秒キャッシュはその後負荷が増えると応答遅延などの影響でエラーとなる場合あり、キャッシュ時間は 1s → 0.8s → 0.7s と徐々に短くしてます。上記の結果もありkataribeの結果はダッシュボード表示が2番に下がったことを確認してます。

Top 50 Sort By Total
Count    Total    Mean  Stddev    Min  P99.9    Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 1822  510.656  0.2803  0.2199  0.007  0.637  0.671   1822     0    0    0       70231          5         38         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
21365  205.622  0.0096  0.0265  0.000  0.382  0.416  21354     0    0   11   790986026          2      37022      55120  GET /api/audience/dashboard HTTP/2
 4392  129.572  0.0295  0.0282  0.002  0.332  0.400   4392     0    0    0       77408          0         17         74  get /api/contestant/notifications?.*

ReceiveBenchmarkJob対策

次に多い ReceiveBenchmarkJobのソースコードを見て「ウッ、gRPCなんも分からん」となったものの、SELECT FOR UPDATEからUPDATEを実行している実装があって一応「あっこれ予選で見たやつだ」となって念の為修正しています。

負荷が増えないところからTeamCapacityの気づき

CPUやメモリに負荷がなくボトルネックになっている様子がないことから何らかのリミットを考えてトラフィック量を削減するためにVarnishでgzip応答を返してみるものの改善せず、何だろうなとマニュアルとソースとにらめっこしていたところ、アプリ側でTeamCapacityで上限が制約されていることを確認。これだーと気づいてTeamCapacityを増やしていきました。 10→20→60→120→180→60。このあたりの調整に時間をかけていたのですが、最終的には120でフィニッシュしています。

open files limit対策

TeamCapacityを増やしていくとenvoyやアプリでopen files limitに引っかかったようなメッセージが表示されることを確認したのでインフラにめっぽう強い我々は速攻で対処しています。

# systemctl edit envoy.service
[Service]
LimitNOFILE=524288

13:07、スコアは25455です。

メモリ対策

MySQLとVarnishのメモリ消費が問題となったので、以下のように対策を実施しました。

MySQLはメモリ量の多いisu2サーバに移設
Varnishはメモリ設定を変更しても削減されず
- xsuportal宛の通信をすべてVarnishに通していたが、キャッシュ対象のみ通すように変更

Varnishのメモリ消費原因の特定がなかなかできなかったのですが、大量の接続とgzip処理による負荷ではないかと思っています。これで一旦メモリ消費は解消しています。

Varnishではforkが問題になったのでこちらも併せて引き上げています。

# systemctl edit varnish.service
[Service]
TasksMax=4096

CPU負荷対策

このあたりでアプリ(xsuportal)のCPU負荷がネックとなっていたのでCPUコアの数が多いisu3へアプリを移設しました。

この時点で14:49、スコアは30244でした。

通知機能対策

この頃になると通知機能がボトルネックになっていました。

Top 50 Sort By Total
Count     Total    Mean  Stddev    Min  P99.9    Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
19604  2624.748  0.1339  0.1460  0.001  1.325  1.943  19604     0    0    0      196884          0         10        118  get /api/contestant/notifications?.*
 2100  2031.179  0.9672  1.1011  0.002  8.695  9.750   2100     0    0    0       77559          5         36         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
 1123  1038.024  0.9243  1.0063  0.001  5.062  5.306   1121     0    2    0     5275953          0       4698       9800  GET /api/contestant/clarifications HTTP/2

そこでアプリケーションマニュアルで手厚く説明されているWeb Push serviceの実装に踏み切ります。慣れないWebPush実装は少し手こずったものの、なんとかベンチマークが実行できるところまで実装することができました。

Top 50 Sort By Total
Count     Total    Mean  Stddev     Min   P99.9     Max    2xx   3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
 2146  1892.735  0.8820  1.1223   0.003   9.864  10.454   2146     0    0    0       85671          5         39         80  POST /xsuportal.proto.services.bench.BenchmarkQueue/ReceiveBenchmarkJob HTTP/2
22411  1785.695  0.0797  0.1195   0.000   1.240   1.843  22411     0    0    0           0          0          0          0  get /api/contestant/notifications?.*
 1321   963.386  0.7293  0.9943   0.002   4.938   4.980   1319     0    2    0     5946332          0       4501       8850  GET /api/contestant/clarifications HTTP/2

この時点で16:29、スコアは32173でした。

TeamCapacity調整

ここからはTeamCapacityを60から120に引き上げることでベストスコア44269を記録するもののfailとなる割合が多く、3回に1回ぐらいの頻度でしか成功しない状況が続きます。が、ここで当日マニュアルの「競技時間終了後に運営によって行う作業手順」を 3回のうち1回でも負荷テストに通ればok、それでダメでもその次の再チェックで通ればok と勘違いをしてしまいこのままフィニッシュとしてしまいました。ここで日和って120から60などに下げておけばおそらくfailにならずに完走できたのではないかと悔やんでおります。うーむ、悔しい。

わいわい

そんなわけでウー馬場ーイーツはほぼインフラエンジニア力で大半のスコアを稼ぎ、おまけで通知機能のプログラミングを少し頑張った実装になりました。まだまだ改善の余地はあるので引き続き感想戦に邁進し、来年こそは優勝をもぎ取ろうと思います。来年の活躍にどうぞご期待ください。

2020-09-13

ISUCON10予選で12位になり本選進出を決めました

TL;DR

ISUCON10の本選出場が決定しました。わいわい。予選12位、最終スコアは2837でした。

毎年素晴らしいコンテストを開催してくださる運営様には、本当に頭が下がります。いつもありがとうございます。本選もがんばるぞ！

体制

チーム名ウー馬場ーイーツ

あいこん	なまえ	やくわり
	matsuu	バリバリ実装する前衛
	netmarkjp	司令塔
	ishikawa84g	~~SELinux~~AppArmorとレギュレーションやコードやDiscordを見るセキュリティ＆情報官

今回は3人が同じ場所に集まらずすべてリモート体制としました。 3人だけのDiscordサーバを用意し、Discord上で画面共有と音声チャットで進めています。

方針

毎年同じですが

sshで接続してtmux上でvimで直接編集
isuumo配下でgit initを実行するが履歴保存用でbranchは作成しない

毎年今年こそはvscodeとか夢見るんですが、結局手に馴染んだtmux+vimが最強というオチです。

解析ツール

使用した解析ツールは以下の通り。

dstat
kataribe
mysqltuner.pl
pt-query-digest
top

ベンチマーク実行中はdstatとtopで負荷状況を目視確認しています。ベンチマーク実行後はkataribeとpt-query-digestでログ解析、おまけでmysqltuner.plを実行しています。

事前にNew Relicも確認してましたが、goでは導入に骨が折れるので利用しませんでした。

最終構成

最終構成は以下の通りです。

サーバ	構成要素	備考
1台目	nginx+go	バージョン変更なし
2台目	mysql	8.0.21にアップグレード
3台目	使用せず(!!!)

3台目も活用できればもっといけたかもですね。

ベンチマーク結果

f:id:tmatsuu:20200913131101p:plain

初動

pt-query-digestとkataribeで集計できるようmysqlとnginxの設定変更。

/etc/mysql/mysql.conf.d/mysqld.cnf

+
+slow_query_log=1
+slow_query_log_file=/var/log/mysql/mysql-slow.log
+long_query_time=0

/etc/nginx/nginx.conf

     log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                       '$status $body_bytes_sent "$http_referer" '
-                      '"$http_user_agent" "$http_x_forwarded_for"';
+                      '"$http_user_agent" $request_length $request_time';

$request_length も追加するのが最近のお気に入りです。

マニュアルを読む

マニュアルを読んだ段階でnginxでUser-Agentによるbotフィルタ実施。正規表現を読み砕いて不要な表現は削除しています。

/etc/nginx/sites-available/issumo.conf

+map $http_user_agent $bot {
+  default 0;
+  "~ISUCONbot" 1;
+  "~Mediapartners-ISUCON" 1;
+  "~ISUCONCoffee" 1;
+  "~ISUCONFeedSeeker" 1;
+  "~crawler \(https://isucon\.invalid/(support/faq/|help/jp/)" 1;
+  "~isubot" 1;
+  "~Isupider" 1;
+  "~*(bot|crawler|spider)(?:[-_ .\/;@()]|$)" 1;
+}
+
 server {
     root /home/isucon/isucon10-qualify/webapp/public;
     listen 80 default_server;
     listen [::]:80 default_server;

+    if ($bot = 1) {
+        return 503;
+    }
+

curlで該当するUser-Agentでアクセスしてみて503応答になることを確認。

初回ベンチ実行

topとdstatを実行しながらベンチマーク実施。この時点でmysqldのCPU負荷が支配的であることを確認。 pt-query-digestの結果をもとにインデックスを追加しました。

isuumo/webapp/mysql/db/3_index.sql

-- この時点で追加したインデックスは記録が取れておらず記憶があいまい
ALTER TABLE isuumo.estate ADD INDEX (rent, popularity);
ALTER TABLE isuumo.estate ADD INDEX (door_width, door_height, popularity);
ALTER TABLE isuumo.estate ADD INDEX (popularity);
ALTER TABLE isuumo.chair ADD INDEX (stock, price);
ALTER TABLE isuumo.chair ADD INDEX (price);

ADMIN PREPARE対策

ADMIN PREPAREが多い。DBへの接続時に自動prepareをしないようDSNに interpolateParams=true を追加しました。

 func (mc *MySQLConnectionEnv) ConnectDB() (*sqlx.DB, error) {
-       dsn := fmt.Sprintf("%v:%v@tcp(%v:%v)/%v", mc.User, mc.Password, mc.Host, mc.Port, mc.DBName)
+       dsn := fmt.Sprintf("%v:%v@tcp(%v:%v)/%v?interpolateParams=true", mc.User, mc.Password, mc.Host, mc.Port, mc.DBName)
        return sqlx.Open("mysql", dsn)
 }

なぞって検索対策

なぞって検索に関連するSQLの実行回数が異常に多いことからN+1実装となっていることを確認。1発のクエリーで取得できるよう変更しました。

SELECT * FROM estate WHERE latitude <= ? AND latitude >= ? AND longitude <= ? AND longitude >= ? AND ST_Contains(ST_PolygonFromText(?), POINT(latitude, longitude)) ORDER BY popularity DESC, id ASC LIMIT ?

rentなどの範囲による絞り込みをID化

pt-query-digestの上位クエリーがrentなどの範囲(range)による絞り込みになっておりインデックスを効かせにくいと判断してrentのIDを格納するカラムをテーブルに追加しています。

ALTER TABLE isuumo.estate ADD COLUMN rent_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.estate ADD COLUMN door_height_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.estate ADD COLUMN door_width_id INTEGER NOT NULL DEFAULT 0;

ALTER TABLE isuumo.chair ADD COLUMN height_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.chair ADD COLUMN width_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.chair ADD COLUMN depth_id INTEGER NOT NULL DEFAULT 0;
ALTER TABLE isuumo.chair ADD COLUMN price_id INTEGER NOT NULL DEFAULT 0;

UPDATE estate SET rent_id = 0 WHERE rent < 50000;
UPDATE estate SET rent_id = 1 WHEN 50000 <= rent AND rent < 100000;
UPDATE estate SET rent_id = 2 WHEN 100000 <= rent AND rent < 150000;
UPDATE estate SET rent_id = 3 WHEN 150000 <= rent;
ALTER TABLE estate ADD INDEX (rent_id);
-- 以下同様のため省略

条件のSQL生成がすっきり。

-               if estateRent.Min != -1 {
-                       conditions = append(conditions, "rent >= ?")
-                       params = append(params, estateRent.Min)
-               }
-               if estateRent.Max != -1 {
-                       conditions = append(conditions, "rent < ?")
-                       params = append(params, estateRent.Max)
-               }
+               conditions = append(conditions, "rent_id = ?")
+               params = append(params, estateRent.ID)
        }

INSERT前に rent_id に格納する値を計算。

var rentId int64
switch {
        case rent < 50000:
                rentId = 0
        case rent < 100000:
                rentId = 1
        case rent < 150000:
                rentId = 2
        default:
                rentId = 3
}

SELECT * FROM ... は rent_id などを取り除いたカラムを列挙。

-- 変更前
SELECT * FROM estate ...
SELECT * FROM chair ...
-- 変更後
SELECT id, name, description, thumbnail, address, latitude, longitude, rent, door_height, door_width, features, popularity FROM estate ...
SELECT id, name, description, thumbnail, price, height, width, depth, color, features, kind, popularity, stock FROM chair ...

initializeがタイムアウト

上記設定後に実行したベンチマーク結果のpt-query-digestの上位クエリーにさらにインデックスを追加していくと、initializeが30秒以内に終わらなくなる。

今回各テーブルの description が VARCHAR(4096) と大きくレコード登録後にカラムを追加するととても時間がかかることが判明。幸いデータの流し込みがカラム名指定付きのINSERTだったのでデータ流し込み前にカラムを追加しても問題ないと判断。

CREATE TABLE isuumo.estate
(
   -- 省略
);

ALTER TABLE isuumo.estate
  ADD COLUMN rent_id INTEGER NOT NULL DEFAULT 0 AFTER id,
  ADD COLUMN door_height_id INTEGER NOT NULL DEFAULT 0 AFTER id,
  ADD COLUMN door_width_id INTEGER NOT NULL DEFAULT 0 AFTER id,

その他のクエリーも高速化。UPDATEはCASEで一度に。インデックス追加も一発で。

UPDATE isuumo.estate SET
  rent_id = CASE WHEN rent < 50000 THEN 0 WHEN rent < 100000 THEN 1 WHEN rent < 150000 THEN 2 ELSE 3 END,
  door_width_id = CASE WHEN door_width < 80 THEN 0 WHEN door_width < 110 THEN 1 WHEN door_width < 150 THEN 2 ELSE 3 END,
  door_height_id = CASE WHEN door_height < 80 THEN 0 WHEN door_height < 110 THEN 1 WHEN door_height < 150 THEN 2 ELSE 3 END;

ALTER TABLE isuumo.estate
  ADD INDEX (rent_id, popularity),
  ADD INDEX (door_height_id, rent_id),
  ADD INDEX (door_width_id, rent_id),
  ADD INDEX (rent),
  ADD INDEX (popularity),
  ADD INDEX (latitude);

この時点で15:37:01、スコアは1144です。

MySQL 8.0へのアップグレード(ORDER BY対策)

この時点でもMySQLのCPU使用率が支配的な状況。pt-query-digestで上位のクエリーのEXPLAINを確認すると ORDER BY でインデックスが効いてない。よく見るとDESCとASCの混合が理由と判明。

SELECT ... ORDER BY popularity DESC, id ASC LIMIT ...

MySQL 8.0ではこのような場合でもインデックスを適用できる降順インデックスの存在を思い出してMySQL 8.0へのアップグレードを決意。

wget https://dev.mysql.com/get/mysql-apt-config_0.8.15-1_all.deb
sudo dpkg -i mysql-apt-config_0.8.15-1_all.deb
sudo apt update
sudo apt install mysql-server

これでMySQLはバージョン8.0.21に。

MySQLアップデート後性能が大きく下がってしまったが、調べていくとMySQL8.0でバイナリログが有効に変わり、undoログが記録されるようになったことを確認。この環境のDISK性能が結構低いなどからio改善のため以下を追加。

disable-log-bin
innodb_log_group_home_dir = /dev/shm/
innodb_doublewrite = 0
innodb_flush_log_at_trx_commit = 0

UNDOログもtmpfsに載せようとしたものの、試行錯誤の結果UNDOログは消えると正常に起動しないことから再起動リスクが大きいと判断して触りませんでした。

innodb_log_fileをtmpfsに逃したことと、disable-log-binの効果が大きかった気がします。

なお、 innodb_log_group_home_dirの/dev/shmへの変更はAppArmorで遮られるため適宜調整しています。

/etc/apparmor.d/usr.sbin.mysqld

  /dev/shm/ r,
  /dev/shm/** rwk,

降順インデックス追加

ALTER TABLE isuumo.estate ADD INDEX (rent_id, popularity DESC, id ASC);
ALTER TABLE issumo.estate ADD INDEX (popularity DESC, id ASC);
ALTER TABLE isuumo.chair ADD INDEX (popularity DESC, id ASC);

いい感じにインデックスが効くようになったことを確認。

この時点で16:50:09、スコアは1200です。

空間インデックスと向き合う

この時点でもMySQLのCPU使用率が支配的な状況ですが、一番遅いクエリーはなぞって検索のクエリー。

SELECT id, name, description, thumbnail, address, latitude, longitude, rent, door_height, door_width, features, popularity FROM estate WHERE latitude <= ? AND latitude >= ? AND longitude <= ? AND longitude >= ? AND ST_Contains(ST_PolygonFromText(?), POINT(latitude,longitude)) ORDER BY popularity DESC, id ASC LIMIT ?

ここで空間インデックスの存在を思い出し ST_Contains() で空間インデックスを利用できないかの検討をはじめました。

まず POINT(latitude, longitude) はlatlngから導出できるためpoint型としてカラムに追加。ただし追加するタイミングではNOT NULLにできず、しかしインデックスを追加するためにはNOT NULLに設定する必要がありこんな感じになりました。

ALTER TABLE isuumo.estate ADD COLUMN point POINT;
-- データ登録
UPDATE isuumo.estate SET point=POINT(latitude, longitude);
ALTER TABLE issumo.estate MODIFY COLUMN point POINT NOT NULL;
ALTER TABLE issumo.estate ADD SPATIAL INDEX (point);

しかしこの変更を行ってもSPATIAL INDEXが使われずしばらく悩んだのですが、ググラビリティと試行錯誤を経て SRID 0 を追加すればインデックスが使われることをEXPLAINで確認しました。

ALTER TABLE issumo.estate MODIFY COLUMN point POINT SRID 0 NOT NULL;

わかるかこんなの！なぞって検索の応答時間は平均0.401秒から平均0.063秒と大きく改善しました。

この時点で18:24:13、スコアは1819です。

件数をキャッシュ

この時点でもMySQLのCPU使用率が支配的な状況ですが、pt-query-digestの上位3番目ぐらいに以下のクエリーがきていたので、

SELECT COUNT(*) FROM estate WHERE rent_id = ?

rentのみが条件の場合に絞ってCOUNTをアプリ側でキャッシュすることにしました。

自分はsync.Mapが大好きマンなのでこんな実装になっています。使い方が間違ってたら教えて下さい。

var rentMap sync.Map

        // 初期化
        rows, err := db.Query("SELECT rent_id, count(1) FROM estate GROUP BY rent_id")
        if err != nil {
                ...
        }
        for rows.Next() {
                var rentId, cnt int64
                rows.Scan(&rentId, &cnt)
                rentMap.Store(rentId, &cnt)
        }
        rows.Close()

        // INSERT時のインクリメント
        v, _ := rentMap.Load(rentId)
        p, _ := v.(*int64)
        atomic.AddInt64(p, 1)

        // 取り出し
        if len(conditions) == 1 && hasRent {
                v, _ := rentMap.Load(rentId)
                res.Count = *v.(*int64)
        }

再起動対策のため起動時はmain()とinitialize()の両方でやってます。

この時点で19:30:06、スコアは2070です。

MySQLを2台目サーバに

この時点でもMySQLのCPU使用率が一番高いのですが、nginxとappのCPU使用率も上がってきたことを確認したのでMySQLを2台目サーバに移すことにしました。

この時点で20:07:59、スコアは2612です。

MySQLを3台目サーバに用意するも断念

binlogを出力するとDISK性能が刺さることからレプリケーションは断念、ただあろうことか両方にINSERTすればいいのではという発想でプログラムを改修したものの、おそらくINSERTにかかる時間でタイムアウトが発生しcritical errorを回避できずに断念しました。

今にして思えばJOINがなかったのでテーブルを分ければ良かったのですが、そこまでは思いつきませんでした。分けた場合の性能改善は今後の検討課題です。

ログ出力を抑制

仕上げとしてmysqlのスロークエリーログ、nginxやアプリのアクセスログ出力を抑制してベンチを回しました。

この時点で20:46:31、スコアは2837です。

事前の再起動テストで問題発覚

最後に再起動試験を行ったところ、1台目サーバと2台目サーバの再起動タイミングがずれるとアプリからのDB接続に失敗、systemdのデフォルト設定によりアクセスできなくなってしまう事象が発生しました。

systemdのログからギリギリで以下の設定を追加しています。

/etc/systemd/system/isuumo.go.service

[Service]
StartLimitBurst=999

あぶない。

その他

その他に以下のような改善を実施しています。

nginxでgzipを有効に
nginxとgolangの間の接続をHTTP/1.1にしてkeepaliveを有効に
POST /api/estate と POST /api/chair で client request body is buffered to a temporary file の発生を確認したため、nginxで client_body_buffer_size を調整
POST /api/estate と POST /api/chair でのINSERT時に tx.Prepare() してから stmt.Exec()

2019-10-06

ISUCON9本選を11位でフィニッシュしました

ISUCON9本選に「いんふらえんじにあー as Code」として参加し、11位でフィニッシュしました。悔しい。最高スコアは9107、運営確認の最終スコアは8995でした。

メンバー紹介

チーム名いんふらえんじにあー as Code

あいこん	なまえ	やくわり
	matsuu	バリバリ実装する前衛
	netmarkjp	司令塔
	ishikawa84g	レギュレーションやコードやログやDiscordを見る情報官

構成

初期はこんな感じですが

1台目 nginx --- go(docker) --- mysql(docker)
2台目 同上
3台目 同上

最終構成はこうなりました。

1台目 nginx --- go --- mysql(docker)
2台目 利用せず
3台目 利用せず

goをdockerから剥がしただけ、中途半端にmysqlをdockerに残したままとなりました。このような構成になったのは以下が理由です。

docker-composeでgoのアプリ更新がうまくいかず手っ取り早く更新ができるようにgoを引きはがした
mysqlはバージョン8が利用されておりインストールの手間を避けた
mysqlのcpu負荷が支配的でmysql レプリケーション構成に変更する時間もなくサーバを分けるところまで至らなかった

ただ、この構成にしたためにsystemdの起動用service unitで考慮が必要となり、再起動対策で終盤時間を取られてヒヤヒヤものでした。

スコアの遷移

f:id:tmatsuu:20191006144309p:plain — ISUCON9本選スコア遷移@いんふらえんじにあー as Code

序盤足踏み状態が続いたものの後半からスコアが倍々に増えていったものの、入賞するところまでスコアを上げきれませんでした。残念。

ざっくりまとめ

ネタバレを含みますのでご了承ください。

安易にPRIMARY KEYを張ってはいけない

今回、初見でDBのCPU負荷が高く、PRIMARY KEYが設定されていないテーブルでスロークエリーが発生していたこともあり安易にPRIMARY KEYを追加したのですが、これが 大きな罠 でした。後から分かったことではあるのですが、PRIMARY KEYがないテーブルはINSERTされた順番に意味がある上に ORDER BY が使われておらず、むやみにPRIMARY KEYやINDEXを追加すると出力結果がかわってしまってFailになるのです。さらに質が悪いのがPRIMARY KEYを張って直後のベンチマークでは即座にエラーにならず、またPRIMARY KEYやINDEXを外しても出力結果が変わってしまい、最初からデータを作り直す以外はどう頑張っても復旧できなくなってしまった（と思い込んだ）ことです。おそらくそれについては勘違いではないかと思いたいのですが、問題が公開されたらしっかり追試するつもりです。

goplsはメモリを食うので気を付ける

我々のチームはサーバ上でvim(vim-go)の環境を構築してプログラムの修正を行っていたのですが、goplsが思いのほかメモリーを食ってました。今回の環境はメモリーが1GBと少なくページイン/ページアウトが発生しまくって極端に体感速度が遅くなる事態が発生しました。一時は killコマンドすらメモリ不足で実行(fork)できない 最悪の事態になって無駄に時間を浪費しました。あの時間ロスがなければ…。

Docker構成は中途半端にはがすことなかれ

Docker構成のまま、Docker構成をやめる、のいずれの対応でもよかったのですが、剥がすなら中途半端にせず全部剥がすべきでした。再起動した場合の起動制御がややこしくなるためです。

docker-composeはログ出力によるメモリ消費に注意

今回webappは意図的にデバッグログの出力が多く残されているためかdocker-composeのメモリ消費がもりもり増える現象に悩まされました。今回の本選マニュアルにもメモリ消費に気をつける旨の記述があったので気をつけたいところですね。現実にもあるあるなのかも。

Alibaba Cloudのサーバはタイムゾーンが中国標準時(CST)

今回OSはUbuntu 18.04だったんですが、Alibaba CloudのUbuntuサーバはデフォルトのタイムゾーン設定が中国標準時になっているのでログを見るときは要注意です。Alibabaらしさを感じますね。ちなみに予選の環境はUTCに設定されていました。

運営のシークレットメッセージを見つけよう

運営はscreen/tmuxをつかった場合にメッセージを残していました。

# ~/.bash_profile
case "${TERM}" in
  screen*)
    export PROMPT_COMMAND='printf "\033k\U1F004 %s:\033\\" "${HOSTNAME%%.*}"'
    ;;
esac

どうなるかはぜひ手元で試してみてください。

おわりに

ありがとう運営。そしてしっかり復習しようと思います。来年も頑張るぞ！

2019-09-08

ISUCON9予選で総合4位になり本選進出を決めました

ISUCON9予選1日目に「いんふらえんじにあー as Code」として参加し、1日目に3位(1位が棄権したため2位)で予選通過を勝ち取りました。予選通過はISUCON4以来、5年ぶりです。なお、総合順位は4位だった模様です。

メンバー紹介

チーム名いんふらえんじにあー as Code

あいこん	なまえ	やくわり
	netmarkjp	司令塔
	ishikawa84g	レギュレーションやコードやログやDiscordを見る情報官
	matsuu	バリバリ実装する前衛

最終構成

nginx --+-- app(go) --+-- mysql 1台目
        |             |
        +-- app(go) --+         2台目
        |             |
        +-- app(go) --+         3台目

2台目と3台目は /login のアクセスのみ振り分け(bcryptのハッシュ処理のため) nginxとmysqlは初期バージョンのまま変更せず

スコアの遷移

f:id:tmatsuu:20190909220031p:plain — ISUCON9予選スコア遷移@いんふらえんじにあー as Code

事前準備

去年のISUCON8予選で敗退した際に原因分析を行ったところ、自分自身に以下の課題があると感じていました。

職業プログラマーではないこともあり実装速度が遅い
Go言語の基本機能をきちんと把握できておらずドキュメントを見ながら実装していた
過去のISUCONの復習を深いところまでできていない

これらの課題改善のため1年かけて以下に取り組みました。

AtCoderにGo言語で挑戦して基礎に慣れつつ実装速度をあげる
HighLoad Cupの過去問を解いてGo言語のWebアプリ実装に慣れる
ISUCON過去問を限界までチューニングしてチューニング力を高める

自分ではHighLoad Cupへの挑戦が一番大きな成果だと思います。 HighLoad Cupはマニュアルを元にアプリケーションを実装するオンライン版ISUCONのような大会です。 2018年と2017年の過去問が公開されており、ていつでもベンチマークを実行できます。みんなやろうぜHighLoad Cup。ただしHighLoad Cupのマニュアルはロシア語もしくは英語のみです。

HighLoad Cupについては前回のブログ記事にも書きましたのでご確認ください。

方針・戦略

詳しくはnetmarkjpのブログをご確認ください。

matsuuが当日やったこと

文章としてまとめるのが下手くそなので箇条書きで失礼します。あと細かく記録取ってませんでした。ごめんなさい。

15000までの道のり

ログイン後に環境構築
- nginx、app、mysqlのログ周り整備
- kataribe、pt-query-digest(percona-toolkit)、dstatのインストール
- net/http/pprofを使ったプロファイル環境整備
nginxチューニング
- error_logをerrorからinfoに
- keepalive_requestsを1000000に
- http2有効化
- upstreamを使ってバックエンドとHTTP/1.1とkeepalive有効化
- 静的ファイルをnginxから直接配信する設定に
mysqlチューニング
- itemsに (status), (created_at), (seller_id, status), (buyer_id) のインデックスを追加
categories テーブルが更新されていないことを確認し、アプリのインメモリに保存
/users/transactions のN+1の一部を解消(items取得時にUserSimple相当の内容も取得する)
UserSimple をアプリのインメモリにキャッシュ保存( sync.Map )
- NumCellItemsは更新されるため、更新のたびにキャッシュを更新
デッドロックが多発するようになる
- ログと実行されるSQLから POST /buy でデッドロックが発生していることを確認
- SET innodb_lock_wait_timeout = 1 を入れてデッドロックを早めに発生させる
  - デッドロックとなった場合は500エラーを返す実装になっていたが、 item is not for sale として403を返すように書換
- innodb_lock_wait_timeout は1秒より短くすることができないので他の方法を考える
  - Redisで SETNX を使おうと実装を試みるもうまく機能せず断念
appからDBへの接続に失敗するエラーが多発
- appからMySQLの同時接続数を最大4096まで引き上げ
パスワードのチェック(bcrypt実装)でCPU負荷が高くなっていた
- 同じパスワードをそのまま保存してはいけないレギュレーションがあるため、複数サーバに負荷を分散させることに
- isucariアプリをサーバの2台目、3台目に配置して/loginのみ2台目、3台目にアクセスを振るよう変更
configs をアプリのインメモリに保存
nginxでToo Many Open Filesのエラーが発生した
- /etc/nginx/nginx.conf に worker_rlimit_nofile を追加
- ついでに /etc/systemd/system/isucari.golang.service に LimitNOFILE を追加
temp fileの生成を抑制するため /etc/nginx/nginx.conf に client_body_buffer_size を追加
1台目サーバのCPU負荷が落ち着いてきたので Campaign: 0 => Campaign: 2

16000までの道のり

GET /users/transactions.json (getTransactions)で transaction_evidences と shippings のN+1を解消
POST /buy のデッドロック対策として sync.Map の LoadOrStore() を使って楽観ロックもどきを実装した
1台目サーバのCPU負荷が落ち着いてきたので Campaign: 2 => Campaign: 4

19000までの道のり

http.DefaultTransportのMaxIdleConnsPerHostを4096に引き上げ

26000までの道のり

外部APIへのステータス確認(APIShipmentStatus)でStatusがdoneになったものをアプリのインメモリでキャッシュ、複数回アクセスが発生しないように

工夫した点

ここらへんを工夫しました

ベンチマークの事前処理、事後処理を行うシェルスクリプトを作成
- 繰り返しやる作業はas codeだ！
ベンチマーク中にアプリやミドルウェアのログを tail -f などで眺めるの重要
- パフォーマンスに直結するログがポロッと出てくることがある
500エラーを返す場所が複数あるもののどの500エラーが発生したのかわからなかったのでlog.Print()を挟んで場所を特定
複数ある SELECT * FROM items WHERE id = ? FOR UPDATE のうちどれが原因で詰まってるか分かりにくかった
- SELECT /* postBuy */ * FROM items ... のように書き換えて SHOW PROCESSLIST で目視判別しやすく
Alibaba Cloudで事前に過去問を解いて練習した際にredis-serverが正常に起動しない問題に気づく
- redis-serverはIPv6が利用できる前提になっているが、今回の環境ではIPv6が割り振られない
- /etc/redis/redis.conf で bind から ::1 を削除
(いつもの)sshrcで個人別競技環境をさっとセットアップ
- vim最新版やneovim最新版もインストール
サーバは基本的に1台目のみ操作、ベンチ直前にrsync転送とssh経由でのsystemd再起動を実施
ソースコードや設定の変更はサーバ上で直接vim/nvim
- ISUCONは短期決戦。デプロイの仕組みを作ってもデプロイを待ってられない
- VSCodeのRemote Developmentを事前に試したものの安定性に難があり断念
- VSCodeのVim拡張でdd後にカーソルが飛ぶ問題もつらかった
同じ場所に集まって横並びに座る
- やりとりは基本口頭で、文字情報の共有はSlackで