ISUCON12予選の復習をしました 3
この記事は何か?
ISUCON12予選の復習記録です。
第3回はISUCON12 予選の解説 (Node.jsでSQLiteのまま10万点行く方法)の「3. Score APIの追加のループクエリをなくす」を試します。
目次
1. 「3. Score APIの追加のループクエリをなくす」を試す (N+1問題)
「3. Score APIの追加のループクエリをなくす」には2つの対策が解説されています。
N+1問題とバルクインサートです。どちらもISUCONでは馴染みのある対応ですね。
まずは、N+1問題を解決します。
ということで、「CSVを全行チェックしてPlayerIdの重複ないリストを作る」→「それをSELECT COUNT(*) as count FROM player WHERE id IN (...) に渡してCOUNTに差分があるか確認する」という処理を追加すると参加者数チェックの部分は1クエリでできるようになります。
解説では上記の対応方法が記載されていますが、私は件数だけの確認では整合性が取れない場合はあるのではないかと思い、先にテナントに紐づくプレイヤーをスライスに格納することにしました。今後他の人の解法も見てみるつもりなので、そこで答え合わせしたいと思います。
- ソースコードの変更点
+
+ "golang.org/x/exp/slices"
+ // プレイヤー一覧をスライスにいれておく
+ playerIDs := []string{}
+ if err := tenantDB.SelectContext(
+ ctx,
+ &playerIDs,
+ "SELECT DISTINCT(id) FROM player WHERE tenant_id = ?",
+ v.tenantID,
+ ); err != nil && err != sql.ErrNoRows {
+ return fmt.Errorf("error Select player ID: tenantID=%d, %w", v.tenantID, err)
+ }
+
+ // 存在しない参加者が含まれている (スライス利用)
+ if !slices.Contains(playerIDs, playerID) {
+ fmt.Errorf("error retrievePlayer: %w", err)
+
+ return echo.NewHTTPError(
+ http.StatusBadRequest,
+ fmt.Sprintf("player not found: %s", playerID),
+ )
+ }
+
+ /*
if _, err := retrievePlayer(ctx, tenantDB, playerID); err != nil {
// 存在しない参加者が含まれている
if errors.Is(err, sql.ErrNoRows) {
...
}
return fmt.Errorf("error retrievePlayer: %w", err)
}
+ */
「go get golang.org/x/exp/slices」 を実行します。
- 変更前のスコア
21:50:11.084591 SCORE: 2811 (+2811 0(0%))
- 変更後のスコア
21:46:04.478709 SCORE: 3188 (+3188 0(0%))
2. 「3. Score APIの追加のループクエリをなくす」を試す (バルクインサート)
これは分かりやすいバルクインサート適用部分です。
- ソースコードの変更点
+
+ // バルクインサート
+ if _, err := tenantDB.NamedExecContext(
+ ctx,
+ "INSERT INTO player_score (id, tenant_id, player_id, competition_id, score, row_num, created_at, updated_at) VALUES (:id, :tenant_id, :player_id, :competition_id, :score, :row_num, :created_at, :updated_at)",
+ playerScoreRows,
+ ); err != nil {
+ return fmt.Errorf("error Insert player_score: %w", err)
+ }
+
+ /*
for _, ps := range playerScoreRows {
if _, err := tenantDB.NamedExecContext(
ctx,
.....
}
}
+ */
- 変更前のスコア (N+1対応後)
21:46:04.478709 SCORE: 3188 (+3188 0(0%))
- 変更後のスコア
22:05:24.438783 SCORE: 3862 (+3862 0(0%))
感想
今回の対応でスコアが1,000点改善しました。
上記のとおりN+1問題とバルクインサートはISUCON頻出問題ですが、僕は当日解決できませんでした 😭
参考
ISUCON12予選の復習をしました 2
この記事は何か?
ISUCON12の復習記録です。
第2回はISUCON12 予選の解説 (Node.jsでSQLiteのまま10万点行く方法)の「2 Ranking APIが重いのでひとまずループクエリをなくす」を試します。
目次
- 環境構築 (alp, pporf)
- 「2 Ranking APIが重いのでひとまずループクエリをなくす」を試す
1. 環境構築 (alp, pporf)
alpとpporfをインストールします。alpのインストール手順は過去に書いたので省略します。
- pporfインストール
go install runtime/pprof
go install net/http/pprof
vi isuports.go
-----------------
+
+ "runtime"
+ _ "net/http/pprof"
@@ -137,6 +140,12 @@ func Run() {
e.Debug = true
e.Logger.SetLevel(log.DEBUG)
+ runtime.SetBlockProfileRate(1)
+ runtime.SetMutexProfileFraction(1)
+ go func() {
+ http.ListenAndServe("0.0.0.0:6060", nil)
+ }()
-----------------
make
sudo systemctl restart isuports
sudo apt install graphviz
セキュリティグループの設定で1080を開放
go tool pprof -http=0.0.0.0:1080 /home/isucon/webapp/go http://localhost:6060/debug/pprof/profile?seconds=90
http://xxx.xxx.xxx.xxx:1080/にアクセス
- alp結果
alp --sum -r -f /var/log/nginx/access.log | head -100 +-------+--------+--------+---------+--------+--------+--------+--------+--------+-----------+------------+-------------+-----------+--------+-----------------------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+--------+--------+---------+--------+--------+--------+--------+--------+-----------+------------+-------------+-----------+--------+-----------------------------------------------+ | 18 | 2.764 | 16.020 | 189.032 | 10.502 | 2.764 | 12.688 | 15.708 | 5.091 | 0.000 | 14439.000 | 245022.000 | 13612.333 | GET | /api/player/competition/9fa538f9/ranking | | 16 | 0.140 | 18.724 | 183.480 | 11.467 | 0.140 | 17.804 | 18.588 | 8.684 | 13563.000 | 13636.000 | 217081.000 | 13567.562 | GET | /api/player/competition/9fa53e35/ranking | | 31 | 0.016 | 17.592 | 135.380 | 4.367 | 0.016 | 0.156 | 17.464 | 5.416 | 13650.000 | 13741.000 | 423394.000 | 13657.871 | GET | /api/player/competition/9fa52cc0/ranking | | 27 | 0.028 | 17.632 | 132.436 | 4.905 | 0.028 | 0.192 | 10.464 | 5.561 | 13654.000 | 13708.000 | 368743.000 | 13657.148 | GET | /api/player/competition/9fa53286/ranking | | 20 | 0.012 | 10.188 | 119.448 | 5.972 | 0.012 | 9.972 | 10.156 | 4.851 | 0.000 | 13730.000 | 260867.000 | 13043.350 | GET | /api/player/competition/9fa53ed0/ranking | | 38 | 0.008 | 18.508 | 116.096 | 3.055 | 0.008 | 0.044 | 17.724 | 4.939 | 912.000 | 3439.000 | 124093.000 | 3265.605 | GET | /api/player/competition/9fa5278c/ranking | | 19 | 0.000 | 9.648 | 105.476 | 5.551 | 0.000 | 9.428 | 9.620 | 4.686 | 0.000 | 13633.000 | 244237.000 | 12854.579 | GET | /api/player/competition/9fa53fc1/ranking | | 23 | 0.020 | 7.888 | 99.780 | 4.338 | 0.020 | 6.480 | 7.888 | 3.786 | 13571.000 | 13721.000 | 312385.000 | 13581.957 | GET | /api/player/competition/9fa5325a/ranking | | 26 | 0.020 | 7.624 | 98.900 | 3.804 | 0.020 | 0.252 | 7.620 | 3.710 | 0.000 | 13727.000 | 325444.000 | 12517.077 | GET | /api/player/competition/9fa537bf/ranking | | 34 | 0.016 | 7.572 | 95.484 | 2.808 | 0.016 | 0.076 | 6.908 | 3.116 | 13457.000 | 13669.000 | 458558.000 | 13487.000 | GET | /api/player/competition/9fa52a27/ranking | | 28 | 0.020 | 8.356 | 87.816 | 3.136 | 0.020 | 5.228 | 7.048 | 2.963 | 13555.000 | 13682.000 | 379750.000 | 13562.500 | GET | /api/player/competition/9fa52efc/ranking | | 33 | 0.924 | 15.380 | 84.456 | 2.559 | 0.000 | 1.804 | 6.764 | 2.576 | 0.000 | 1565.000 | 46830.000 | 1419.091 | GET | /api/admin/tenants/billing | | 17 | 0.076 | 8.368 | 80.968 | 4.763 | 0.076 | 7.756 | 8.232 | 3.897 | 13639.000 | 13653.000 | 231922.000 | 13642.471 | GET | /api/player/competition/9fa546cf/ranking | | 16 | 0.072 | 7.352 | 79.784 | 4.986 | 0.072 | 7.128 | 7.320 | 3.299 | 13686.000 | 13686.000 | 218976.000 | 13686.000 | GET | /api/player/competition/9fa54745/ranking | | 29 | 0.012 | 4.060 | 44.864 | 1.547 | 0.012 | 0.048 | 4.052 | 1.923 | 11049.000 | 14504.000 | 416088.000 | 14347.862 | GET | /api/player/competition/9fa533be/ranking | | 28 | 0.012 | 3.320 | 36.696 | 1.311 | 0.012 | 0.036 | 3.316 | 1.593 | 2908.000 | 12357.000 | 330278.000 | 11795.643 | GET | /api/player/competition/9fa53adb/ranking |
GET /api/player/competition/:competition_id/rankingが遅いことが分かります。
- pprof結果
tenantDB.SelectContextが4.89秒、retrievePlayerが3.14秒かかっていて、retrievePlayerはいわゆる「N+1問題」になっていることが分かります
2. 「2 Ranking APIが重いのでひとまずループクエリをなくす」を試す
mysqlがちょっと落ち着いたら、alpでリクエストごとの総レスポンスタイム(SUM)を見てみると、rankingが重いことが分かります。flockしているのも気になりますが、ロック区間内でループクエリが発生しているのがマズいので、まずはplayer_scoreを取るところにplayerをJOINして、retrievePlayerせずともdisplay_nameを取れるようにします。
解説ではSQLiteのロックは一旦そのまま放置して、N+1問題の解決をしています。
- 変更後のソースコード
+type PlayerScoreJoinPlayerRow struct {
+ TenantID int64 `db:"tenant_id"`
+ ID string `db:"id"`
+ PlayerID string `db:"player_id"`
+ CompetitionID string `db:"competition_id"`
+ Score int64 `db:"score"`
+ RowNum int64 `db:"row_num"`
+ CreatedAt int64 `db:"created_at"`
+ UpdatedAt int64 `db:"updated_at"`
+ DisplayName string `db:"display_name"`
+}
- "SELECT * FROM player_score WHERE tenant_id = ? AND competition_id = ? ORDER BY row_num DESC",
+ "SELECT player_score.*, player.display_name FROM player_score JOIN player ON player.id = player_score.player_id WHERE player_score.tenant_id = ? AND competition_id = ? ORDER BY row_num DESC",
/*
p, err := retrievePlayer(ctx, tenantDB, ps.PlayerID)
if err != nil {
return fmt.Errorf("error retrievePlayer: %w", err)
}
*/
ranks = append(ranks, CompetitionRank{
Score: ps.Score,
PlayerID: ps.PlayerID,
PlayerDisplayName: ps.DisplayName,
RowNum: ps.RowNum,
})
- 変更後のpprof結果
N+1問題は解決しました。しかしスコアは2972と改善していません。解説にあるとおりflockを解決しないとスコア改善しないようです。
感想
今見ると分かりやすいN+1問題ですが、予選当日は対応できませんでした。アプリやコードの仕様理解をさくっとできるようになる必要があります。
また、対応できたとしてもスコアが改善しないので、「それはそれとして、改善を重ねていこう」というゆるい気持ちが必要そうです。
参考
ISUCON12予選の復習をしました 1
この記事は何か?
ISUCON12の復習をやっていきます。
第1回はISUCON12 予選の解説 (Node.jsでSQLiteのまま10万点行く方法)の「adminDB visit_history にINDEXを張る」までをやります。
目次
- 環境構築
- 「adminDB visit_history にINDEXを張る」を試す
1. 環境構築
用意されたCloudFormationテンプレートを利用する場合に記載された方法でAWS上に環境を用意します。
- cloudformation.yamlをダウンロードして、CloudFormationの画面から実行
- 3台起動されるが、節約のため1台停止 (1台をベンチ実行用、2台目をチューニング用に利用します)
- Systems Manager > パラメータストア を開き、秘密鍵をコピペ、SSHログイン
vi ~/.ssh/isucon12q.pem chmod 400 ~/.ssh/isucon12q.pem ssh -i ~/.ssh/isucon12q.pem ubuntu@xx.xx.xx.xx ← 1台目にログイン
04.初回ベンチ実行
sudo su - isucon cd /home/isucon/bench ./bench -target-addr xx.xx.xx.xx:443 ← 2台目に向けてベンチ実行
初回スコアは2,781でした。運営の方がCloudFormationテンプレートを用意してくれたおかげで準備が超簡単です。ありがとうございます。
「adminDB visit_history にINDEXを張る」を試す
初手は「adminDB visit_history にINDEXを張る」でした。私と同じで嬉しかったのですがINDEXの張り方が違っていました。
最後にcreated_atまで入れておくと、Covering Indexになるのでセカンダリインデックス単体でクエリを返すことができて高速ですが、created_atを張るのを忘れるとcreated_atを読むためにクラスタインデックスを読みに行くのでそこまで伸びない(もちろん張らないよりはマシ)といった感じです。私は最初created_atまで入れてなくて「アルェー」と言ってました。
私は2カラムしか設定しませんでしたが、解説では4カラムでした。
私: tenant_id, competition_id 解説: tenant_id, competition_id, player_id, created_at
気になったので、インデックス毎に「Extra」の値を確認しました。
- スロークエリログ
Reading mysql slow query log from /var/lib/mysql/slow.log Count: 1152 Time=0.11s (129s) Lock=0.00s (0s) Rows=92.7 (106831), isucon[isucon]@localhost SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id
- EXPLAIN結果 (インデックス無し)
mysql> explain SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id\G;
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: visit_history
partitions: NULL
type: ref
possible_keys: tenant_id_idx
key: tenant_id_idx
key_len: 8
ref: const
rows: 1293162
filtered: 10.00
Extra: Using where; Using temporary
1 row in set, 1 warning (0.00 sec)
- EXPLAIN結果 (インデックス tenant_id, competition_id)
mysql> explain SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id\G;
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: visit_history
partitions: NULL
type: ref
possible_keys: tenant_id_idx,idx_tenant_id_competition_id
key: idx_tenant_id_competition_id
key_len: 1030
ref: const,const
rows: 1
filtered: 100.00
Extra: Using temporary
1 row in set, 1 warning (0.00 sec)
- EXPLAIN結果 (インデックス tenant_id, competition_id, player_id)
mysql> explain SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id\G;
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: visit_history
partitions: NULL
type: ref
possible_keys: tenant_id_idx,idx_tenant_id_competition_id_player_id
key: idx_tenant_id_competition_id_player_id
key_len: 1030
ref: const,const
rows: 1
filtered: 100.00
Extra: NULL
1 row in set, 1 warning (0.00 sec)
- EXPLAIN結果 (インデックス tenant_id, competition_id, player_id, created_at)
mysql> explain SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id\G;
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: visit_history
partitions: NULL
type: ref
possible_keys: tenant_id_idx,idx_all_cover
key: idx_all_cover
key_len: 1030
ref: const,const
rows: 1
filtered: 100.00
Extra: Using index
1 row in set, 1 warning (0.00 sec)
- スコア比較
// Before (インデックス無し) 07:03:05.717432 SCORE: 2781 (+2781 0(0%)) Count: 1152 Time=0.11s (129s) Lock=0.00s (0s) Rows=92.7 (106831), isucon[isucon]@localhost SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id // After (インデックス idx_all_cover) 07:13:45.086791 SCORE: 3238 (+3238 0(0%)) Count: 4076 Time=0.01s (20s) Lock=0.00s (0s) Rows=153.0 (623605), isucon[isucon]@localhost SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id
idx_all_coverは「Using index」になっていて、スコアも上がっています。(他のスコアは省略して計測しませんでした)
感想
「クラスタインデックス」と「セカンダリインデックス」の説明は(通称)ISUCON本[2]の説明が分かりやすいです。その本では、「クラスタインデックス」だけから情報を取得できることでの性能向上について書かれていましたが、「セカンダリインデックス」だけにアクセスすることも可能ということを知りました。またyoku0825さんの以下の説明[3]も分かりやすいです。
MySQLのインデックスはほぼB+Treeです。MySQLのB+Treeインデックスのリーフには「テーブル内での行の位置」が記録されています（MyISAMであれば.MYDファイルの先頭からオフセットバイト数、InnoDBであればクラスターインデックスの値が記録されている）。そのため、インデックスを利用した行フェッチを行う際は、以下の3ステップで行われます。 1 インデックス上から条件にマッチするリーフを探す 2 インデックスのリーフ上に書かれた情報から行の位置を探す 3 行をフェッチする
Using indexが示すのはインデックス上に書かれた情報だけで（インデックスは「ソート済みのデータの複製（サブセット）」でありインデックスを作成したカラムの値を含む）、要求された情報の取り出しが終了したため 2. と 3. のステップを省略した、というものです。
参考
1 ISUCON12 予選の解説 (Node.jsでSQLiteのまま10万点行く方法)
ISUCON12予選に参加しました
結果
7/23(土) ISUCON12予選に、チーム「y」(メンバーは私のみ)で参加しました。
昨年に続き2回目の参加となります。
結果は、5,369点 181位 (全1,657チーム) でした。
前回同様、ほぼ何もできませんでしたが、楽しかったです。運営の皆様ありがとうございます。
この記事では「参加振り返り」をします。
振り返り
Keep
- 1年前の自分のブログを参考にできた
- 前日は仕事を休みにした
- 失格にならなかった
Problem
Try
- 解説を読んで実際に試してみる
- ISUCON本に書いてあるベンチマークを実装してみる
- Go言語に慣れる
- 自動化
当日やったこと
目次
- ドキュメント確認 (10:00)
- 初期ベンチ確認 (10:25)
- 準備作業 (11:00)
- 対応1 INDEX追加 (visit_historyテーブル) (12:17)
- 対応2 一意な値の生成方法を変更 (id_generatorテーブル) (12:53)
- 昼食休憩 (13:30)
- 対応3 2台目利用 (14:34)
- 対応4 SQLiteにINDEX追加 (16:02)
- 対応5 MySQLに変更失敗 (16:24)
ドキュメント確認 (10:00)
ISUCON12 予選当日マニュアルを読みました。前年と比べてドキュメント量が少なくて理解しやすかったです。
初期ベンチ確認 (10:25)
初期ベンチを実行。2,926でした。
準備作業 (11:00)
対象サーバーにSSHログインできなくて、調べたらauthorized_keysに公開鍵が設定されていませんでした。環境構築不備かなと思って再度CloudFormationを再実行しましたが、解決しなかったのでauthorized_keysに直接公開鍵を設定しました。時間を無駄にしたので、これは反省しています。(最初からauthorized_keysを変更すればよかった)
その後以下作業を実行しました。過去のブログを参考にして問題なく設定できました。
- gitコミット
cd /etc/ sudo git init sudo git add . sudo git commit -a -m "Initial checkin." cd /home/isucon/webapp/ git init git add . git config --global user.email "xxx@gmail.com" git config --global user.name "xxx" git commit -a -m "Initial checkin."
- mysqldumpslow設定
sudo vi /etc/mysql/conf.d/my.cnf slow_query_log = 1 slow_query_log_file = /var/lib/mysql/slow.log long_query_time = 0 sudo rm /var/lib/mysql/slow.log && sudo /etc/init.d/mysql restart # 上記だとエラーが出たのでstatusで確認 root@ip-192-168-0-11:/etc/mysql/conf.d# systemctl status mysql ● mysql.service - MySQL Community Server # mysql -u isucon -p mysql: [ERROR] unknown variable 'slow_query_log=1' # 上記エラーを見て以下に変更 [mysqld] slow_query_log = 1 slow_query_log_file = /var/lib/mysql/slow.log long_query_time = 0
- alp設定
wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
unzip alp_linux_amd64.zip
sudo install ./alp /usr/local/bin
sudo vim /etc/nginx/nginx.conf
http {
log_format ltsv "time:$time_local"
"\thost:$remote_addr"
"\tforwardedfor:$http_x_forwarded_for"
"\treq:$request"
"\tmethod:$request_method"
"\turi:$request_uri"
"\tstatus:$status"
"\tsize:$body_bytes_sent"
"\treferer:$http_referer"
"\tua:$http_user_agent"
"\treqtime:$request_time"
"\truntime:$upstream_http_x_runtime"
"\tapptime:$upstream_response_time"
"\tcache:$upstream_http_x_cache"
"\tvhost:$host";
access_log /var/log/nginx/access.log ltsv;
}
sudo rm /var/log/nginx/access.log && sudo /etc/init.d/nginx restart
ここまでで11:30頃。もう少し短縮できたと思う。
4. 対応1 INDEX追加 (visit_historyテーブル) (12:17)
- データ件数確認
mysql> select count(*) from id_generator; +----------+ | count(*) | +----------+ | 1 | +----------+ 1 row in set (0.00 sec) mysql> select count(*) from tenant; +----------+ | count(*) | +----------+ | 106 | +----------+ 1 row in set (0.00 sec) mysql> select count(*) from visit_history; +----------+ | count(*) | +----------+ | 3225470 | +----------+ 1 row in set (1.33 sec)
前年同様1つのテーブルだけがレコード数が多い(300万件)。これをどうにかする必要がある。
- 実行計画確認
mysql> SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id;
Empty set (9.11 sec)
mysql> EXPLAIN SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id\G;
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: visit_history
partitions: NULL
type: ref
possible_keys: tenant_id_idx
key: tenant_id_idx
key_len: 8
ref: const
rows: 1472383
filtered: 10.00
Extra: Using where; Using temporary
1 row in set, 1 warning (0.00 sec)
ERROR:
No query specified
- テーブル構造確認
CREATE TABLE `tenant` ( `id` BIGINT NOT NULL AUTO_INCREMENT, `name` VARCHAR(255) NOT NULL, `display_name` VARCHAR(255) NOT NULL, `created_at` BIGINT NOT NULL, `updated_at` BIGINT NOT NULL, PRIMARY KEY (`id`), UNIQUE KEY `name` (`name`) ) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4; CREATE TABLE `id_generator` ( `id` BIGINT NOT NULL AUTO_INCREMENT, `stub` CHAR(1) NOT NULL DEFAULT '', PRIMARY KEY (`id`), UNIQUE KEY `stub` (`stub`) ) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4; CREATE TABLE `visit_history` ( `player_id` VARCHAR(255) NOT NULL, `tenant_id` BIGINT UNSIGNED NOT NULL, `competition_id` VARCHAR(255) NOT NULL, `created_at` BIGINT NOT NULL, `updated_at` BIGINT NOT NULL, INDEX `tenant_id_idx` (`tenant_id`) ) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;
当日のメモには「プライマリーキーが存在しないのか」と書かれている。でもインデックス追加しているみたい。その方がよいのか? (それと今見るとインデックス名が変だな)
この時点のスコアは2,500でした。
- インデックス追加
ALTER TABLE visit_history ADD INDEX tenant_id_idx_competition_id (tenant_id, competition_id);
- インデックス追加後の実行計画
mysql> SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id;
Empty set (0.00 sec)
mysql> EXPLAIN SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = 'S' GROUP BY player_id\G;
*************************** 1. row ***************************
id: 1
select_type: SIMPLE
table: visit_history
partitions: NULL
type: ref
possible_keys: tenant_id_idx,tenant_id_idx_competition_id
key: tenant_id_idx_competition_id
key_len: 1030
ref: const,const
rows: 1
filtered: 100.00
Extra: Using temporary
1 row in set, 1 warning (0.00 sec)
- インデックス追加後のスロークエリログ
// 変更前 Count: 1718 Time=0.06s (105s) Lock=0.00s (0s) Rows=82.7 (142040), isucon[isucon]@localhost SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id // 変更後 Count: 2903 Time=0.02s (50s) Lock=0.00s (0s) Rows=119.7 (347424), isucon[isucon]@localhost SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id
スループットが16.36から58.06に改善しました。ただしスコアは2,647でほとんど変更がありません。
5. 対応2 一意な値の生成方法を変更 (id_generatorテーブル) (12:53)
あやしげなスロークエリログがあります。
Count: 8384 Time=0.01s (51s) Lock=0.01s (47s) Rows=0.0 (0), isucon[isucon]@localhost
REPLACE INTO id_generator (stub) VALUES ('S')
mysql> select * from id_generator;
+------------+------+
| id | stub |
+------------+------+
| 2678409755 | a |
+------------+------+
1 row in set (0.00 sec)
"REPLACE INTO"なんて当然知らないので検索すると、該当レコードの置き換えをするSQLらしいです。Goのソースコードを読むと丁寧にコメントが書いてありました。
// システム全体で一意なIDを生成する
func dispenseID(ctx context.Context) (string, error) {
というわけで、DBアクセスなしに一意なIDを生成すればよいとのことなので、雑な関数を作成しました。(UUID生成ライブラリは数値以外を除去する方法が分からないためランダム関数を利用しました)
import (
"fmt"
"math/rand"
"time"
)
func main() {
rand.Seed(time.Now().UnixNano())
min := 2678400000
max := 922337203685477
fmt.Println(rand.Intn(max - min) + min)
}
max値を大きくすることで重複をさける狙いがありましたが、KOBA789さんの解説動画を見ると、BTree構造上あまりよくないらしいです。[1]
- 変更後のスコア
04:28:20.169932 SCORE: 4050 (+4132 -82(2%))
スロークエリログから対象のクエリーがなくなり上機嫌になったので昼食にすることにしました。
6. 昼食休憩 (13:30)
13:31〜14:12お昼休み。何食べたか覚えていない。
7. 対応3 2台目利用 (14:34)
いつものとおりbind-addressを変更
mysql> SHOW GLOBAL VARIABLES like 'bind_address'; +---------------+-----------+ | Variable_name | Value | +---------------+-----------+ | bind_address | 127.0.0.1 | +---------------+-----------+ 1 row in set (0.01 sec) sudo vi /etc/mysql/conf.d/my.cnf [mysqld] slow_query_log = 1 slow_query_log_file = /var/lib/mysql/slow.log long_query_time = 0 bind-address = 0.0.0.0
アプリ側の環境変数は以前はSystemdの設定だったけど、今回は... 忘れましたが別のところを変更したと思います。
05:34:15.776365 SCORE: 4689 (+4833 -144(3%))
600点ぐらいUPしました。
8. 対応4 SQLiteにINDEX追加 (16:02)
ここまでSQLiteを利用していることをなんとなく知っていましたが、これがボトルネックになっていることを考えたのはこの時間からでした。(絶望的に遅い..)
ここで僕は考えます。SQLiteをこのまま使うか? または置き換えるか? 前回ISUCON11ではMariaDBが使われていて、MySQLに置き換えるか悩みましたが、結果的にMariaDBでも問題ありませんでした。そのことを思い出した僕は「SQLiteを利用し続ける」と決めました。
調べるとSQLiteもインデックスを利用できて、実行計画も見れるようでした。
sqlite> explain SELECT * FROM player_score WHERE tenant_id = 1 AND competition_id = 1 AND player_id = 1 ORDER BY row_num DESC LIMIT 1; addr opcode p1 p2 p3 p4 p5 comment ---- ------------- ---- ---- ---- ------------- -- ------------- 0 Init 0 39 0 0 Start at 39 1 OpenEphemeral 1 10 0 k(1,-B) 0 nColumn=10 2 Integer 1 1 0 0 r[1]=1; LIMIT counter 3 OpenRead 0 6 0 8 0 root=6 iDb=0; player_score 4 Rewind 0 27 0 0 5 Column 0 1 2 0 r[2]=player_score.tenant_id 6 Ne 3 26 2 BINARY-8 84 if r[2]!=r[3] goto 26 7 Column 0 3 2 0 r[2]=player_score.competition_id 8 Ne 3 26 2 BINARY-8 82 if r[2]!=r[3] goto 26 9 Column 0 2 2 0 r[2]=player_score.player_id 10 Ne 3 26 2 BINARY-8 82 if r[2]!=r[3] goto 26 11 Column 0 5 4 0 r[4]=player_score.row_num 12 Sequence 1 5 0 0 r[5]=cursor[1].ctr++ 13 IfNotZero 1 17 0 0 if r[1]!=0 then r[1]--, goto 17 sqlite> PRAGMA table_info(player_score); 0|id|VARCHAR(255)|1||1 1|tenant_id|BIGINT|1||0 2|player_id|VARCHAR(255)|1||0 3|competition_id|VARCHAR(255)|1||0 4|score|BIGINT|1||0 5|row_num|BIGINT|1||0 6|created_at|BIGINT|1||0 7|updated_at|BIGINT|1||0
でも上記の実行計画は見方が分かりません。試しにインデックスを追加したところ、体感的に速くなったので(正しいかは不明。ただのキャッシュだったのかも)、全部のDBファイルに対してインデックスを追加することにしました。
sqlite3 1.db < test.sql sqlite3 14.db < test.sql sqlite3 2.db < test.sql sqlite3 25.db < test.sql sqlite3 30.db < test.sql sqlite3 36.db < test.sql
上記のような感じでインデックスを追加しました。
07:03:47.987977 SCORE: 5081 (+5405 -324(6%))
失敗も増えましたが、少しスコアが上がりました。なんで失敗が増えたのか分かりません。
9. 対応5 MySQLに変更失敗 (16:24)
ここでMySQLに置き換えることに決めます。理由は以下です。
- SQLiteへのインデックスが効果無かった
- ツール「sqlite3-to-sql」が用意されていて、運営側からのヒントだと受け取った
- テーブル構造が移行しやすい形になっていたので、運営側からのヒントだと受け取った
- スロークエリログが見れないことが不満だった
- 実運用だったら、(時間があれば)MySQLに移行するのが正しいと思い、正しいことをしたいと思った
- 残り時間が少なく、スコアも全然ダメだったので、もうどうでもよいと思った
./sqlite3-to-sql ../../initial_data/1.db >> insert.sql ./sqlite3-to-sql ../../initial_data/14.db >> insert.sql ./sqlite3-to-sql ../../initial_data/2.db >> insert.sql ./sqlite3-to-sql ../../initial_data/25.db >> insert.sql ./sqlite3-to-sql ../../initial_data/30.db >> insert.sql ./sqlite3-to-sql ../../initial_data/36.db >> insert.sql
上記のようなSQL文を作成して、MySQL DBにインポートしました。インポートに20分ぐらいかかりました。(この時間が一番ドキドキしました)
インポート後、SQLiteを利用しているGoのコードを変更しましたが、ベンチマークが失敗したので、元に戻しました。
データベースオブジェクトを作成している部分を1箇所変更すればワンチャンいけるかなと思いましたが、いけませんでした。
当日夜にリアタイ視聴したKOBA789さんの動画を観ると、KOBA789さんのチームは年蜜に移行準備を行っており、自分の浅はかさを思い知らされました。(それがISUCONさ)
最終作業
各種ログを停止、各サーバーを再起動してベンチを実行して、結果が問題ないことを確認しました。とりあえず失格とならなかったので良かったです。
予選終了後の夜にやったこと
- KOBA789さんの動画をリアルタイム視聴 (超参考になりました!)
- 「詳解Go言語Webアプリケーション開発」購入して読んだ
現在8/16、予選から1ヶ月近くたちましたが、ISUCON熱がまだまだ冷めません!
参考
「ISUCON11 予選問題の解説と講評」を読んで試してみた
この記事は何か?
ISUCON12予選に参加しました。そのことは別の記事で書きますが、
ISUCON12予選参加時に参考にしたのは自分のブログでした。
なので、去年やってブログに書いていなかった「"ISUCON11 予選問題の解説と講評"を読んで試したこと」を書きます。
たぶん1年後の自分が参考にすると思います。
ISUCON11 予選問題の解説と講評
ISUCON11 予選問題の解説と講評 https://isucon.net/archives/56044867.html ISUCON11 予選問題実践攻略法 https://isucon.net/archives/56082639.html
上記の2サイトに書いてあることをやりました。
実行環境
AMIがまだなかった(?)ため、matsuuさんのVagrantfileを利用させていただいた気がします。いつもありがとうございます。
vagrant-isucon/isucon11-qualifier-standalone/Vagrantfile https://github.com/matsuu/vagrant-isucon/blob/master/isucon11-qualifier-standalone/Vagrantfile
コミットログとスコア
- 初期スコア (1,402)
- alp設定 (1,491)
- mysqldumpslow設定 (1,458)
- pprof設定 (1,386)
- プライマリキー変更 (17,340)
- バルクインサート (18,628)
- LIMIT 1 追加 (23,848)
- レベルカラム追加 (27,000)
- グラフデータ条件追加 (28,630)
- ログ停止 (32,770)
1 初期スコア (1,402)
https://github.com/zono/isucon11-qualify/issues/1#issue-1007352307
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 190249 mysql 20 0 1713420 126116 11744 S 73.4 3.3 1:26.76 mysqld 212863 isucon 20 0 1372068 144984 11548 S 43.9 3.8 0:16.23 bench 212664 isucon 20 0 1526580 29908 7632 S 40.5 0.8 0:27.59 isucondition 162 root 19 -1 303276 123968 122668 S 13.3 3.3 0:07.85 systemd-journal 188178 www-data 20 0 16616 9200 4116 S 12.6 0.2 0:09.35 nginx 188179 www-data 20 0 14728 7276 4116 S 7.0 0.2 0:03.13 nginx 520 syslog 20 0 224500 4860 3416 S 5.6 0.1 0:03.58 rsyslogd
mysqld、対象アプリ(isucondition)、nginxがCPUを使っています。またbenchも同じサーバーで動かしていますね。
2 alp設定 (1,491)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927283219
+-------+--------+------------------------------+-------+-------+---------+-------+-------+ | COUNT | METHOD | URI | MIN | MAX | SUM | AVG | P99 | +-------+--------+------------------------------+-------+-------+---------+-------+-------+ | 69454 | POST | /api/condition/[-a-z0-9]+ | 0.020 | 0.232 | 706.684 | 0.010 | 0.104 | | 403 | GET | /api/isu | 0.004 | 3.000 | 342.580 | 0.850 | 1.012 | | 530 | GET | /api/isu/.+/icon | 0.004 | 1.812 | 93.848 | 0.177 | 1.008 | | 156 | GET | /api/condition/[-a-z0-9]+ | 1.000 | 1.004 | 28.992 | 0.186 | 1.004 | | 35 | GET | /api/trend | 0.028 | 1.020 | 27.828 | 0.795 | 1.020 | | 126 | POST | /api/auth | 0.004 | 3.004 | 25.176 | 0.200 | 3.000 | | 80 | GET | /api/isu/.+/graph | 1.000 | 1.004 | 14.092 | 0.176 | 1.004 | | 130 | GET | /api/isu/[-a-z0-9]+ | 3.004 | 3.004 | 13.328 | 0.103 | 1.000 | | 55 | POST | /api/isu | 0.004 | 0.116 | 4.208 | 0.077 | 0.116 | | 39 | GET | /api/user/me | 0.000 | 0.632 | 0.920 | 0.024 | 0.632 | | 23 | POST | /api/signout | 0.004 | 0.088 | 0.312 | 0.014 | 0.088 | | 81 | GET | /assets/favicon.d0f5f504.svg | 0.004 | 0.020 | 0.256 | 0.003 | 0.020 | | 81 | GET | /assets/vendor.ee7444dd.js | 0.004 | 0.020 | 0.240 | 0.003 | 0.020 | | 81 | GET | /assets/index.23dac98b.js | 0.004 | 0.012 | 0.196 | 0.002 | 0.012 | | 1 | POST | /initialize | 0.164 | 0.164 | 0.164 | 0.164 | 0.164 | | 81 | GET | /assets/index.144d8ca8.css | 0.004 | 0.012 | 0.148 | 0.002 | 0.012 | | 48 | GET | / | 0.004 | 0.012 | 0.124 | 0.003 | 0.012 | | 81 | GET | /assets/logo_white.svg | 0.000 | 0.008 | 0.104 | 0.001 | 0.008 | | 37 | GET | /assets/logo_orange.svg | 0.000 | 0.008 | 0.096 | 0.003 | 0.008 | | 21 | GET | /?jwt= | 0.000 | 0.012 | 0.056 | 0.003 | 0.012 | | 30 | GET | /isu/........-....-.+ | 0.000 | 0.004 | 0.004 | 0.000 | 0.004 | | 3 | GET | /register | 0.000 | 0.004 | 0.004 | 0.001 | 0.004 | +-------+--------+------------------------------+-------+-------+---------+
書き込みが多いことが分かります。解説にも以下の記載があります。
例年と違う要素として、予選では珍しい大量の書き込み処理と、書き込まれた分だけ重くなる表示処理をいかにパフォーマンスチューニングするかという要素も問題に取り入れました。
3 mysqldumpslow設定 (1,458)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927284684
Count: 2504 Time=0.16s (405s) Lock=0.00s (0s) Rows_sent=1.0 (2483), Rows_examined=40767.5 (102081883), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N
Count: 1721 Time=0.08s (129s) Lock=0.00s (0s) Rows_sent=246.2 (423744), Rows_examined=18328.1 (31542676), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
Count: 7035 Time=0.01s (38s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
COMMIT
Count: 4016 Time=0.00s (11s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
#
Count: 2304 Time=0.00s (10s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (2304), isucon[isucon]@localhost
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S')
Count: 102 Time=0.04s (4s) Lock=0.00s (0s) Rows_sent=91.0 (9282), Rows_examined=7201.6 (734561), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' AND `timestamp` < 'S' ORDER BY `timestamp` DESC
Count: 29 Time=0.04s (1s) Lock=0.00s (0s) Rows_sent=142.6 (4135), Rows_examined=7799.1 (226174), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` ASC
合計405秒かかっているクエリーがあります。
4 pprof設定 (1,386)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927287786
1109行目で1.98秒かかっています。pprof分かりやすいです。(ISUCON12予選では存在を忘れてて使いませんでした)
5 プライマリキー変更 (17,340)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927289590
- PRIMARY KEY(`id`) + PRIMARY KEY(`jia_isu_uuid`, `timestamp`)
// 変更前 Count: 1877 Time=0.08s (144s) Lock=0.00s (0s) Rows_sent=251.8 (472671), Rows_examined=18193.5 (34149146), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC // 変更後 Count: 4768 Time=0.00s (22s) Lock=0.00s (0s) Rows_sent=538.2 (2566154), Rows_examined=538.2 (2566142), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
この発想はありませんでした。余分なインデックス作成が無くなるので良いです。
6 バルクインサート (18,628)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927294136
var rows []IsuCondition
rows = append(rows, IsuCondition{
JIAIsuUUID: jiaIsuUUID,
Timestamp: timestamp,
IsSitting: cond.IsSitting,
Condition: cond.Condition,
Message: cond.Message,
})
_, err = tx.NamedExec(
"INSERT INTO `isu_condition`"+
" (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`)"+
" VALUES (:jia_isu_uuid, :timestamp, :is_sitting, :condition, :message)",
rows)
// 変更前
Count: 1064 Time=0.00s (3s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (1064), isucon[isucon]@localhost
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S')
// 変更後
Count: 255 Time=0.00s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=10.0 (2550), isucon[isucon]@localhost
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S')
7 LIMIT 1 追加 (23,848)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927302335
- "SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC", + "SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1",
// 変更前 Count: 4862 Time=0.00s (20s) Lock=0.00s (0s) Rows_sent=637.5 (3099623), Rows_examined=637.5 (3099537), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC // 変更後 Count: 1378 Time=0.00s (4s) Lock=0.00s (0s) Rows_sent=1.0 (1357), Rows_examined=1.0 (1353), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC LIMIT N
8 レベルカラム追加 (27,000)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927305929
ALTER TABLE `isu_condition` ADD `level` VARCHAR(8) NOT NULL DEFAULT "warning"; UPDATE `isu_condition` SET `level`="info" WHERE `condition`="is_dirty=false,is_overweight=false,is_broken=false"; UPDATE `isu_condition` SET `level`="critical" WHERE `condition`="is_dirty=true,is_overweight=true,is_broken=true";
高得点を狙うならデータ構造の変更は必ず発生する と思ってます。(またはISUCON12予選のSQLiteからMySQLヘの変更のようにDB自体を変更することも)
9 グラフデータ条件追加 (28,630)
https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927307267
- rows, err := tx.Queryx("SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY `timestamp` ASC", jiaIsuUUID)
+ rows, err := tx.Queryx("SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ?"+
+ " AND ? <= timestamp AND timestamp < ?"+
+ " ORDER BY `timestamp` ASC", jiaIsuUUID, graphDate, graphDate.Add(24*time.Hour))
これは仕様理解が必要で、ISUCON11予選は仕様理解が難しかったです。前日は仕事を休む方がいいです。(ISUCON12予選は休んだけど遊びに行きました)
10 ログ停止 (32,770)
- c.Logger().Warnf("drop post isu condition request")
これも気づきませんでした。詰めが甘いです。
まとめ(1年前に思ったこと)
- pprof便利
- アプリ仕様理解するの難しい
- benchのソースコード理解したい
補足 Makefile
https://github.com/zono/isucon11-qualify/blob/f9c424a0beafc719c4b4b67600c135d26f5ee532/Makefile
例: alp結果表示 $ make alp
1年間の自分は便利なツールを用意してくれたのに、ISUCON12予選では気づきませんでした。(それでは勝てません)
2022/7/30に思うこと
成長が足りません。がんばるます。(2022年にはやっている言葉です to 来年の僕)
ISUCON11予選参加
結果
ISUCON11予選に、チーム「z」(メンバーは私のみ)で参加しました。
結果は、23,886点 195位 (全598チーム) でした。[1]
ほとんど何もできずに終わりましたが、楽しかったです。
来年に向けて1年間準備します!
振り返り
Keep
- 準備していたことはできた (mysqldumpslow設定, ALP設定など)
Problem
- 準備不足 (ISUCON慣れしていない)
- アプリ側何もできなかった (N+1問題すら解決できなかった)
Try
- ISUCON11予選再実行
- ISUCON過去問全部やる (ISUCON10予選問題しかやってない)
- Go言語アプリに慣れる
当日やったこと
目次
- 初期ベンチ確認 (10:15)
- 準備作業 (10:45)
- 対応1 INDEX追加(timestamp) (11:15)
- 対応2 INDEX追加(jia_isu_uuid) (12:15)
- 対応3 サーバー2台利用(WEB+DB) (13:15)
- 対応4 DBログ書き込みのタイミングを変更 (14:15)
- 対応5 N+1解決失敗1 (14:30)
- 仕様再確認 (15:00)
- 対応6 /assets/以下をキャッシュ対象に設定 (16:00)
- 対応7 N+1解決失敗2 (17:00)
初期ベンチ確認 (10:15)
初期ベンチを実行。(3,278)
画面を見るためにhostsファイルを変更 (マニュアルに画面を見る方法が記載されていた)
sudo vi /etc/hosts xxx.xxx.xxx.xxx isucondition.t.isucon.dev
準備作業 (10:45)
マニュアルを30分ぐらい読んだ。ISUの登録がエラーになり、最後まで理由が分からなかった。
ISUCON10予選の「isuumo」よりも構成が複雑と思った。(JIA? ISUからコンディションが送信される? どういう意味?)
とりあえずtopコマンド実行。以下を確認。
- CPUは2コアあり、全体で100%近く利用されている
- mysqldのCPU使用率が高い
- gitコミット
cd /etc/ git init git add . git commit -a -m "Initial checkin." cd /home/isucon/webapp/ git init git add . git commit -a -m "Initial checkin."
- mysqldumpslow設定
sudo vi /etc/mysql/conf.d/my.cnf slow_query_log = 1 slow_query_log_file = /var/lib/mysql/slow.log long_query_time = 0 sudo rm /var/lib/mysql/slow.log && sudo /etc/init.d/mysql restart
- mysqldumpで使うコマンド
// 実行時間の合計が多い順でソート mysqldumpslow -s t /var/lib/mysql/slow.log | head -30 // 平均実行時間が多い順でソート mysqldumpslow -s at /var/lib/mysql/slow.log | head -30 // スロークエリログとして検出された件数で多い順でソート mysqldumpslow -s c /var/lib/mysql/slow.log | head -30
- DBバージョン確認
isucon@ip-192-168-0-11:~/webapp$ mysql --version mysql Ver 15.1 Distrib 10.3.31-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
- ALP設定 [3]
wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
unzip alp_linux_amd64.zip
sudo install ./alp /usr/local/bin
sudo vim /etc/nginx/nginx.conf
http {
log_format ltsv "time:$time_local"
"\thost:$remote_addr"
"\tforwardedfor:$http_x_forwarded_for"
"\treq:$request"
"\tmethod:$request_method"
"\turi:$request_uri"
"\tstatus:$status"
"\tsize:$body_bytes_sent"
"\treferer:$http_referer"
"\tua:$http_user_agent"
"\treqtime:$request_time"
"\truntime:$upstream_http_x_runtime"
"\tapptime:$upstream_response_time"
"\tcache:$upstream_http_x_cache"
"\tvhost:$host";
access_log /var/log/nginx/access.log ltsv;
}
sudo rm /var/log/nginx/access.log && sudo /etc/init.d/nginx restart
- ALPで使うコマンド
alp -f /var/log/nginx/access.log | head alp -r -f /var/log/nginx/access.log | head alp --sum -r -f /var/log/nginx/access.log | head alp --sum -r -f /var/log/nginx/access.log --aggregates='/api/condition/.*' | head alp --sum -r -f /var/log/nginx/access.log --aggregates='/api/isu/.*' | head
対応1 INDEX追加(timestamp) (11:15)
- 実行時間の合計が多いクエリ
sudo mysqldumpslow -s t /var/lib/mysql/slow.log | head -30 Count: 6482 Time=0.14s (889s) Lock=0.00s (0s) Rows_sent=1.0 (6343), Rows_examined=41212.3 (267137976), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N
- 実行時間の合計が多いクエリのEXPLAIN
MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT 10; +------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+ | 1 | SIMPLE | isu_condition | ALL | NULL | NULL | NULL | NULL | 72591 | Using where; Using filesort | +------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+
- インデックス追加
jia_isu_uuidとtimestampのどちらに設定すべきか迷ったけど、カーディナリティが高い(であろう)timestampに設定した。どのカラムに設定すべきかはよく分かっていない。
CREATE INDEX idx_timestamp ON isucondition.isu_condition(timestamp);
- 実行時間の合計が多いクエリ (インデックス追加後)
Count: 3780 Time=0.06s (208s) Lock=0.00s (0s) Rows_sent=207.6 (784729), Rows_examined=15865.0 (59969855), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
0.14s → 0.06s の改善
- 実行時間の合計が多いクエリのEXPLAIN (インデックス追加後)
MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT 10; +------+-------------+---------------+-------+---------------+---------------+---------+------+------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+---------------+-------+---------------+---------------+---------+------+------+-------------+ | 1 | SIMPLE | isu_condition | index | NULL | idx_timestamp | 5 | NULL | 10 | Using where | +------+-------------+---------------+-------+---------------+---------------+---------+------+------+-------------+
72591 → 10 の改善
- ベンチ実行
3,278 → 5,166 の改善
対応2 INDEX(jia_isu_uuid)追加 (12:15)
- 実行時間の合計が多いクエリ
Count: 750 Time=0.16s (118s) Lock=0.00s (0s) Rows_sent=396.1 (297053), Rows_examined=36562.2 (27421666), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' AND `timestamp` < 'S' ORDER BY `timestamp` DESC
- 実行時間の合計が多いクエリのEXPLAIN
MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' AND `timestamp` < 'S' ORDER BY `timestamp` DESC; +------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+ | 1 | SIMPLE | isu_condition | ALL | idx_timestamp | NULL | NULL | NULL | 73244 | Using where; Using filesort | +------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+
- インデックス追加
CREATE INDEX idx_jia_isu_uuid ON isucondition.isu_condition(jia_isu_uuid);
- 実行時間の合計が多いクエリ (インデックス追加後)
Count: 2383 Time=0.02s (39s) Lock=0.00s (0s) Rows_sent=489.3 (1166055), Rows_examined=1174.4 (2798517), Rows_affected=0.0 (0), isucon[isucon]@localhost SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' AND `timestamp` < 'S' ORDER BY `timestamp` DESC
0.16s → 0.02s の改善
- 実行時間の合計が多いクエリのEXPLAIN (インデックス追加後)
MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' AND `timestamp` < 'S' ORDER BY `timestamp` DESC; +------+-------------+---------------+------+--------------------------------+------------------+---------+-------+------+----------------------------------------------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +------+-------------+---------------+------+--------------------------------+------------------+---------+-------+------+----------------------------------------------------+ | 1 | SIMPLE | isu_condition | ref | idx_timestamp,idx_jia_isu_uuid | idx_jia_isu_uuid | 144 | const | 1 | Using index condition; Using where; Using filesort | +------+-------------+---------------+------+--------------------------------+------------------+---------+-------+------+----------------------------------------------------+
73244 → 1 の改善
- ベンチ実行
5,166 → 15,894 の改善
対応3 サーバー2台利用(WEB+DB) (13:15)
- WEB→DBへのアクセス許可設定
MariaDB [(none)]> SHOW GLOBAL VARIABLES like 'bind_address'; +---------------+-----------+ | Variable_name | Value | +---------------+-----------+ | bind_address | 127.0.0.1 | +---------------+-----------+
- bind-addressコメントアウト
sudo vi /etc/mysql/mariadb.conf.d/50-server.cnf #bind-address = 127.0.0.1 sudo rm /var/lib/mysql/slow.log && sudo /etc/init.d/mysql restart
- WEB→DBへのアクセス許可設定 (変更後)
MariaDB [(none)]> SHOW GLOBAL VARIABLES like 'bind_address'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | bind_address | * | +---------------+-------+
- isuconditionのサービス確認
$ cat /etc/systemd/system/isucondition.go.service EnvironmentFile=/home/isucon/env.sh
- env.shファイル変更
$ vi env.sh MYSQL_HOST="xxx.xxx.xxx.xxx" $ sudo /etc/init.d/isucondition.go.service restart
- ベンチ実行
15,894 → 23,436 の改善
この時点で50位でした。
対応4 DBログ書き込みのタイミングを変更 (14:15)
- 実行時間の合計が多いクエリ
Count: 10025 Time=0.00s (37s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@isucondition-1.t.isucon.dev COMMIT
この「COMMIT」の総時間が多かったので、DBログ書き込みのタイミングを変更しました。[4]
- DBログ書き込みのタイミングを変更
$ sudo vi /etc/mysql/conf.d/my.cnf innodb_flush_log_at_trx_commit=2
- 実行時間の合計が多いクエリ
Count: 9990 Time=0.00s (2s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@isucondition-1.t.isucon.dev COMMIT
37s → 2s の改善
- ベンチ実行
23,436 → 23,196。ほぼ変化なし
- topコマンド確認
DBの使用率は70%程度だったので、アプリ側の対応に着手しました。
対応5 N+1解決失敗1 (14:30)
- ALPコマンド確認
1079 func getTrend(c echo.Context) error {
1080 characterList := []Isu{}
1081 err := db.Select(&characterList, "SELECT `character` FROM `isu` GROUP BY `character`")
N+1が発生していることを確認
- スロークエリログとして検出された件数で多いクエリ確認
sudo mysqldumpslow -s c /var/lib/mysql/slow.log | head -30 Count: 25255 Time=0.00s (88s) Lock=0.00s (0s) Rows_sent=318.9 (8053234), Rows_examined=631.8 (15955566), Rows_affected=0.0 (0), isucon[isucon]@isucondition-1.t.isucon.dev SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
88sを解決できないか確認
- Makefile作成
all: isucondition
isucondition: *.go
go build -o isucondition
- 断念
クエリを1つにした場合にベンチエラーが発生したので一旦断念。
仕様再確認 (15:00)
アプリの仕様を理解するために、再度マニュアルや画面を確認しました。
- ISU登録失敗
{"time":"2021-08-21T15:53:41.260291827+09:00","level":"ERROR","prefix":"echo","file":"main.go","line":"610","message":"failed to request to JIAService: Post \"http://13.113.232.243:5000/api/activate\": dial tcp 13.113.232.243:5000: connect: connection refused"}
{"time":"2021-08-21T15:53:41.260559356+09:00","id":"","remote_ip":"127.0.0.1","host":"isucondition.t.isucon.dev","method":"POST","uri":"/api/isu","user_agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36","status":500,"error":"","latency":2877574,"latency_human":"2.877574ms","bytes_in":275,"bytes_out":0}
{"time":"2021-08-21T16:22:33.295717404+09:00","level":"ERROR","prefix":"echo","file":"main.go","line":"610","message":"failed to request to JIAService: Post \"/api/activate\": unsupported protocol scheme \"\""}
結局、最後までISU登録は成功しませんでした。
対応6 /assets/以下をキャッシュ対象に設定 (16:00)
isuconditionアプリログを見ると、/assets/へのアクセスが多かったのでキャッシュ設定を追加。[5]
- WEBサーバー設定変更
server {
location /assets/ {
expires 24h;
}
- ベンチ実行
23,196 → 23,528。ほぼ変化なし
対応7 N+1解決失敗2 (17:00)
N+1問題に再チャレンジ。「時系列の最新を取得する」といえば「ウィンドウ関数」ではないか? MariaDBのバージョンも「ウィンドウ関数」をサポートしている。ということで試してみました。
- ウィンドウ関数の結果
SELECT
i.id,
i.jia_isu_uuid,
c.condition,
c.timestamp
FROM
isu i
INNER JOIN
(
SELECT
c.id,
c.condition,
c.timestamp,
Row_number() OVER (
partition BY
id
ORDER BY
timestamp DESC
) AS seqnum
FROM
`isu_condition` c
) c
WHERE
i.id = c.id
AND
c.seqnum = 1;
+----+--------------------------------------+----------------------------------------------------+---------------------+
| id | jia_isu_uuid | condition | timestamp |
+----+--------------------------------------+----------------------------------------------------+---------------------+
| 14 | 023c8e56-4410-484d-b7fa-702d48188d3c | is_dirty=false,is_overweight=false,is_broken=false | 2021-06-04 04:59:09 |
| 21 | 0634a999-5f5b-4e8b-bee6-f95d622954a4 | is_dirty=true,is_overweight=false,is_broken=false | 2021-06-04 11:59:09 |
| 63 | 063a0168-f0da-4603-9267-4f05c8565c45 | is_dirty=false,is_overweight=false,is_broken=true | 2021-06-06 05:59:09 |
| 23 | 08985a64-c425-48d2-ac33-25ac61d5a931 | is_dirty=false,is_overweight=false,is_broken=false | 2021-06-04 13:59:09 |
| 24 | 0b675a72-c8fd-4c21-b87b-eefc1d5df5e4 | is_dirty=false,is_overweight=true,is_broken=false | 2021-06-04 14:59:09 |
| 34 | 0bb7ebac-2dd0-49c8-a3bf-830a5b3c02a1 | is_dirty=false,is_overweight=true,is_broken=false | 2021-06-05 00:59:09 |
| 65 | 1135cbe0-c5f5-4e77-ac87-d79dce97b1a7 | is_dirty=false,is_overweight=false,is_broken=true | 2021-06-06 07:59:09 |
| 4 | 15063e10-26fc-4dac-ae3a-1f195e0c6c4a | is_dirty=true,is_overweight=false,is_broken=true | 2021-06-03 18:59:09 |
当時は「それっぽい結果が出た」と思いました。
- ベンチ実行
失敗。時間が迫っていたのでソースコードを元に戻しました。
最終作業 (18:00)
各サーバーを再起動してベンチを実行して、結果が問題ないことを確認しました。
参考
[1] ISUCON11 オンライン予選 全てのチームのスコア（参考値） https://isucon.net/archives/56021246.html
[2] MariaDB と MySQL のバージョン比較 https://qiita.com/katzueno/items/e735950c7440f232ef27
[3] alpのインストールからNginxのアクセスログ解析までの手順【ISUCON】 https://nishinatoshiharu.com/install-alp-to-nginx/
[4] [ISUCON用メモ] MySQL https://qiita.com/stomk/items/6265e9fdfdfb4f104a7e
[5] nginxで静的コンテンツをキャッシュ配信する方法 https://nishinatoshiharu.com/nginx-static-deliver/
