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使用率が高い

f:id:yzono:20210828131500p:plain

f:id:yzono:20210828131529p:plain

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

MariaDB と MySQL のバージョン比較 [2]

f:id:yzono:20210828131818p:plain

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 の改善

f:id:yzono:20210828131947p:plain

この時点で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コマンド確認

f:id:yzono:20210828132205p:plain

f:id:yzono:20210828132252p:plain

DBの使用率は70%程度だったので、アプリ側の対応に着手しました。

対応5 N+1解決失敗1 (14:30)

ALPコマンド確認

f:id:yzono:20210828132103p:plain

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/

結果