Y

ISUCON12予選に参加しました

結果

7/23(土) ISUCON12予選に、チーム「y」(メンバーは私のみ)で参加しました。

昨年に続き2回目の参加となります。

結果は、5,369点 181位 (全1,657チーム) でした。

前回同様、ほぼ何もできませんでしたが、楽しかったです。運営の皆様ありがとうございます。

この記事では「参加振り返り」をします。

振り返り

Keep

  • 1年前の自分のブログを参考にできた
  • 前日は仕事を休みにした
  • 失格にならなかった

Problem

  • 準備不足 (一度も過去問や予習をしなかった)
  • アプリ側が弱かった (Go言語を速く読めない。SQLiteへの移行の工数見積もりができなかった)
  • 解析結果の出力などの自動化準備をしていない

Try

  • 解説を読んで実際に試してみる
  • ISUCON本に書いてあるベンチマークを実装してみる
  • Go言語に慣れる
  • 自動化

当日やったこと

目次

  1. ドキュメント確認 (10:00)
  2. 初期ベンチ確認 (10:25)
  3. 準備作業 (11:00)
  4. 対応1 INDEX追加 (visit_historyテーブル) (12:17)
  5. 対応2 一意な値の生成方法を変更 (id_generatorテーブル) (12:53)
  6. 昼食休憩 (13:30)
  7. 対応3 2台目利用 (14:34)
  8. 対応4 SQLiteにINDEX追加 (16:02)
  9. 対応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に置き換えることに決めます。理由は以下です。

  1. SQLiteへのインデックスが効果無かった
  2. ツール「sqlite3-to-sql」が用意されていて、運営側からのヒントだと受け取った
  3. テーブル構造が移行しやすい形になっていたので、運営側からのヒントだと受け取った
  4. スロークエリログが見れないことが不満だった
  5. 実運用だったら、(時間があれば)MySQLに移行するのが正しいと思い、正しいことをしたいと思った
  6. 残り時間が少なく、スコアも全然ダメだったので、もうどうでもよいと思った
./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さ)

最終作業

各種ログを停止、各サーバーを再起動してベンチを実行して、結果が問題ないことを確認しました。とりあえず失格とならなかったので良かったです。

予選終了後の夜にやったこと

  1. KOBA789さんの動画をリアルタイム視聴 (超参考になりました!)
  2. 「詳解Go言語Webアプリケーション開発」購入して読んだ

現在8/16、予選から1ヶ月近くたちましたが、ISUCON熱がまだまだ冷めません!

参考

[1] 【凸待ち】ISUCON12予選 感想戦やるぞ! #ch789 【なんでSQLite3やねん】