Closed13

ISUCON6 リベンジ

ok8omkok8omk

isudaとisutarの2つのDBがある。

mysql> show databases;
+--------------------+
| Database           |
+--------------------+
| information_schema |
| isuda              |
| isutar             |
| mysql              |
| performance_schema |
| sys                |
+--------------------+
6 rows in set (0.00 sec)

isuda

entryとuserの2テーブルある。

entryがいわゆる記事データっぽい。コンテンツとしてはkeywordとdescriptionか。

mysql> show columns from entry;
+-------------+---------------------+------+-----+---------+----------------+
| Field       | Type                | Null | Key | Default | Extra          |
+-------------+---------------------+------+-----+---------+----------------+
| id          | bigint(20) unsigned | NO   | PRI | NULL    | auto_increment |
| author_id   | bigint(20) unsigned | NO   |     | NULL    |                |
| keyword     | varchar(191)        | YES  | UNI | NULL    |                |
| description | mediumtext          | YES  |     | NULL    |                |
| updated_at  | datetime            | NO   |     | NULL    |                |
| created_at  | datetime            | NO   |     | NULL    |                |
+-------------+---------------------+------+-----+---------+----------------+

userはまぁユーザー。ログイン用のパスワードくらいしかない。

mysql> show columns from user;
+------------+---------------------+------+-----+---------+----------------+
| Field      | Type                | Null | Key | Default | Extra          |
+------------+---------------------+------+-----+---------+----------------+
| id         | bigint(20) unsigned | NO   | PRI | NULL    | auto_increment |
| name       | varchar(191)        | YES  | UNI | NULL    |                |
| salt       | varchar(20)         | YES  |     | NULL    |                |
| password   | varchar(40)         | YES  |     | NULL    |                |
| created_at | datetime            | NO   |     | NULL    |                |
+------------+---------------------+------+-----+---------+----------------+
5 rows in set (0.00 sec)

isutar

starテーブルだけ。いいね機能的なやつっぽい。

mysql> show columns from star;
+------------+---------------------+------+-----+---------+----------------+
| Field      | Type                | Null | Key | Default | Extra          |
+------------+---------------------+------+-----+---------+----------------+
| id         | bigint(20) unsigned | NO   | PRI | NULL    | auto_increment |
| keyword    | varchar(191)        | NO   |     | NULL    |                |
| user_name  | varchar(191)        | NO   |     | NULL    |                |
| created_at | datetime            | YES  |     | NULL    |                |
+------------+---------------------+------+-----+---------+----------------+
ok8omkok8omk

とりあえずベンチマーク。
scoreが0で悲しいので、リクエストがタイムアウトしたやつをとりあえず見ていこう。

  • GET /
  • GET /keyword/ペンスリット
  • POST /keyword
  • POST /login
isucon@ip-172-31-7-116:~/isucon6q$ ./isucon6q-bench
2021/08/02 18:45:00 start pre-checking
2021/08/02 18:45:26 pre-check finished and start main benchmarking
2021/08/02 18:46:00 benchmarking finished
{"pass":true,"score":0,"success":168,"fail":67,"messages":["リクエストがタイムアウトしました (GET /)","リクエストがタイムアウトしました (GET /keyword/ペンスリット)","リクエストがタイムアウトしました (GET /keyword/安来警察署)","リクエストがタイムアウトしました (POST /keyword)","リクエストがタイムアウトしました (POST /login)"]}
ok8omkok8omk

その前にスロークエリログというのを出せるようにしておきたい。
このサイト見ながらやってみる。
https://nishinatoshiharu.com/mysql-slow-query-log/

まずは…その前に/etc/mysql/my.cnfのオリジナルデータは残しておきつつ、
my.cnfの編集履歴見返せるようにgit管理に乗せておく。

ubuntu@ip-172-31-7-116:/etc/mysql$ sudo mv my.cnf my.cnf.org
ubuntu@ip-172-31-7-116:/etc/mysql$ sudo cp my.cnf.org /home/isucon/isucon6-2/my.cnf
ubuntu@ip-172-31-7-116:/etc/mysql$ sudo ln -s /home/isucon/isucon6-2/my.cnf  /etc/mysql

でmy.cnfを編集できるように、git管理した方のファイルのパーミッションを変えておく。

ubuntu@ip-172-31-7-116:~$ sudo chmod 646 /home/isucon/isucon6-2/my.cnf

そいでmy.cnfにスロークエリログの設定を追記。まずはlong_query_time=0にして全部のログを出しておく。

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

my.cnf

んでもってmysqldをrestart。

ok8omkok8omk

スロークエリの設定が効いてない！

mysql> show variables like 'slow%';
+---------------------+-----------------------------------------+
| Variable_name       | Value                                   |
+---------------------+-----------------------------------------+
| slow_launch_time    | 2                                       |
| slow_query_log      | OFF                                     |
| slow_query_log_file | /var/lib/mysql/ip-172-31-7-116-slow.log |
+---------------------+-----------------------------------------+

どうやらmy.cnfのパーミッションの問題。勉強になる。

mysql: [Warning] World-writable config file '/etc/mysql/my.cnf' is ignored.

my.cnfはsudoで編集することにして644にしておこう。

ok8omkok8omk

シンボリックリンクではなく直にファイルを置いて、それを編集したら反映された。
...シンボリックリンクだと駄目なのかな。わからんがとりあえず解決。

mysql> show variables like 'slow%';
+---------------------+-------------------------+
| Variable_name       | Value                   |
+---------------------+-------------------------+
| slow_launch_time    | 2                       |
| slow_query_log      | ON                      |
| slow_query_log_file | /var/log/mysql/slow.log |
+---------------------+-------------------------+
ok8omkok8omk

わーい見れた。tail -f的な感じでfollowしてくれる、less +Fってオプション知ったので使ってみる。

ubuntu@ip-172-31-7-116:~$ sudo less +F /var/log/mysql/slow.log

GET /ではこのクエリが遅いっぽい。どーにかするぞ。

# Time: 2021-08-02T11:12:57.170727Z
# User@Host: isucon[isucon] @ localhost []  Id:    10
# Query_time: 0.061420  Lock_time: 0.000058 Rows_sent: 7110  Rows_examined: 14220
use isuda;
SET timestamp=1627902777;
select * from entry order by character_length(keyword) desc;

といいつつ前回このクエリとかコード周り読んで、何やってるかは検討つけたんだった。
wikiとかニコニコ大百科にあるような「本文中の文字列に記事名があったらリンクを貼る」機能に使われてるやつ。
その機能のために辞書の文字列を文字列長順にソートして全取得してる。

毎回select *クエリするのは重いので、index貼ったりキャッシュを効かせたりしたいところ。

ok8omkok8omk

keywordにindexを貼ってみる。

mysql> ALTER TABLE entry ADD INDEX keyword_index(keyword);
Query OK, 0 rows affected (0.03 sec)
Records: 0  Duplicates: 0  Warnings: 0

その上でkeywordだけ取ってくるように変えてみる。

-        keywords = db.xquery(%| select * from entry order by character_length(keyword) desc |)
+        keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)

そしてベンチマーク。

isucon@ip-172-31-7-116:~/isucon6q$ ./isucon6q-bench
2021/08/02 22:21:47 start pre-checking
2021/08/02 22:21:57 pre-check finished and start main benchmarking
2021/08/02 22:22:47 benchmarking finished
{"pass":true,"score":0,"success":870,"fail":22,"messages":["リクエストがタイムアウトしました (POST /keyword)","リクエストがタイムアウトしました (POST /login)","リクエストがタイムアウトしました (POST /stars)"]}

爆裂にsuccessが増えた。それでもscoreは0点なんだなー。
そもそもfailが0にならないと、scoreが0以上にならないのかな。

というわけでGET /は改善の余地あるがmessageに出なくなったので、

  • POST /keyword
  • POST login
  • POST /stars

の順で、他の改善にも手を付けてみる。

ok8omkok8omk

POST /keyword

ローカルのスパム文字列判定サーバーへのリクエストを2回送ってたので、1回にまとめた。
仕組み的にはこんな感じっぽいので、文字列連結して1回のリクエストにまとめてしまう。

def spam?(word)
  spam_words.includes?(word)
end

-      halt(400) if is_spam_content(description) || is_spam_content(keyword)
+      halt(400) if is_spam_content(description + keyword)

ちょっとよくなったかなー、もうひと押し。

isucon@ip-172-31-7-116:~/isucon6q$ ./isucon6q-bench
2021/08/02 22:45:00 start pre-checking
2021/08/02 22:45:10 pre-check finished and start main benchmarking
2021/08/02 22:46:00 benchmarking finished
{"pass":true,"score":0,"success":906,"fail":15,"messages":["リクエストがタイムアウトしました (POST /keyword)","リクエストがタイムアウトしました (POST /login)","リクエストがタイムアウトしました (POST /stars)"]}
ok8omkok8omk

POST /login
nameで検索してる処理があるのでnameにindexを貼ってみる。

      user = db.xquery(%| select * from user where name = ? |, name).first

mysql> ALTER TABLE user ADD INDEX name_index(name);
Query OK, 0 rows affected (0.02 sec)
Records: 0  Duplicates: 0  Warnings: 0

結果対して変わらず。誤差だなぁ。

isucon@ip-172-31-7-116:~/isucon6q$ ./isucon6q-bench
2021/08/02 23:00:10 start pre-checking
2021/08/02 23:00:18 pre-check finished and start main benchmarking
2021/08/02 23:01:10 benchmarking finished
{"pass":true,"score":0,"success":899,"fail":30,"messages":["リクエストがタイムアウトしました (POST /keyword)","リクエストがタイムアウトしました (POST /login)","リクエストがタイムアウトしました (POST /stars)"]}
ok8omkok8omk

POST /stars

お気に入りレコード登録時対象の記事(entry)が存在しているか確認しているのだが、
GET /keyword/:keywordにリクエストを飛ばして200かどうかを見て確認している。
よくわからないサーバー分割。DB直接見たらよさそう。gggg

そもそもデータベースがisudaとisutarに分かれており扱いづらい。starもisudaにうつしてしまう。

mysql> CREATE table isuda.star LIKE isutar.star;
Query OK, 0 rows affected (0.01 sec)
mysql> INSERT INTO isuda.star SELECT * FROM isutar.star;
Query OK, 37 rows affected (0.01 sec)
Records: 37  Duplicates: 0  Warnings: 0

コードも整理してisudaに寄せる。
長いので↓にて。
https://github.com/ok8omk/isucon6-2/commit/fbed06e9980da377a798994f36ebdf87ffde3bc2

動くかなーと思ったら500。
nginxの設定で/starはport: 5001になってるのを見つけたので、この設定を削除。

        location / {
            proxy_pass http://127.0.0.1:5000;
        }

        location /stars {
            proxy_pass http://127.0.0.1:5001;
        }

いざベンチマーク。とうとうスコアが！(TT)
ただ「starがついてません」という謎エラーでfail。力尽きたのでまた後日。。

isucon@ip-172-31-7-116:~/isucon6q$ ./isucon6q-bench
2021/08/03 00:25:46 start pre-checking
{"pass":false,"score":273,"success":95,"fail":1,"messages":["starがついていません (GET /)"]}
ok8omkok8omk

静的なファイルをsinatra介さずにnginxで返す設定を試してみたんだった。

ポイント

  • 静的ファイルのルートディレクトリを指定: root /home/isucon/webapp/public
  • 各ルールを設定: location /css
    • 列挙してるがもっとスマートな指定方法ある気がする
  • cssがcssと認識されるようにmime typeの指定: include mime.types
    • mime typeの指定で罠にハマった

多分もっとうまい指定の方法があるんだろうなー。と思うがとりあえず動いたのでヨシ！

http {
  include mime.types;
    server {
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header X-Forwarded-Proto $scheme;
        proxy_set_header Host $http_host;

        root /home/isucon/webapp/public;

        location /css {
                expires 24h;
        }

        location /js {
                expires 24h;
        }

        location /img {
                expires 24h;
        }

        location /favicon.ico {
                expires 24h;
        }

        location / {
                proxy_pass http://127.0.0.1:5000;
        }
    }
}
このスクラップは2021/08/15にクローズされました