ISUCON3のオンライン予選問題に挑戦


#準備
[ISUCON3](http://isucon.net/archives/32971265.html)のページに従って進める。

- AMIを使って、インスタンスを起動
- Rubyを選択
 - errorでアプリをスタートできない

```
12:49:14 web.1  | ruby: relocation error: /home/isucon/webapp/ruby/vendor/bundle/ruby/2.0.0/gems/mysql2-0.3.13/lib/mysql2/mysql2.so: symbol mysql_get_client_info, version libmysqlclient_18 not defined in file libmysqlclient.so.18 with link time reference
```

- mysql2のバージョンを0.3.13 -> 0.3.18 にあげた

#Benchmarkをtest実行
```
$ sudo isucon3 test --workload 3
```

なにやら失敗

```
Result:   FAIL
RawScore: 917.6
Fails:    32
Score:    0.0
```

perlだと成功

```
Result:   SUCCESS
RawScore: 1057.3
Fails:    0
Score:    1057.3
```

Rubyでも成功。（何も変えていない）

```
Result:   SUCCESS
RawScore: 1135.5
Fails:    0
Score:    1135.5
```

- リソースを確認
 - CPU70%くらい、メモリは2GB/8GBくらいしか使ってない

workloadを3->6に変更

```workloadを3->6に変更
Result:   SUCCESS
RawScore: 1177.2
Fails:    0
Score:    1177.2
```

- apacheのログを確認
 - エラーログはない
 - ログにレスポンスタイムがないので、%Dをコンフィグに追記して出力するようにする

#ApacheLogを解析して、時間のかかっているリクエストを洗い出す

紹介してもらった[GoAccess](http://goaccess.io)というツールを使って見る。

`# goaccess -f access_log`

下のようなI/Fが表示される

```
                +--------------------------------------------------+
                | Log Format Configuration                         |
                | [SPACE] to toggle - [ENTER] to proceed           |
                |                                                  |
                | [x] NCSA Combined Log Format                     |
                | [ ] NCSA Combined Log Format with Virtual Host   |
                | [ ] Common Log Format (CLF)                      |
                | [ ] Common Log Format (CLF) with Virtual Host    |
                | [ ] W3C                                          |
                | [ ] CloudFront (Download Distribution)           |
                |                                                  |
                | Log Format - [c] to add/edit format              |
                | %h %^[%d:%t %^] "%r" %s %b "%R" "%u" %D          |
                |                                                  |
                | Date Format - [d] to add/edit format             |
                | %d/%b/%Y                                         |
                |                                                  |
                | Time Format - [d] to add/edit format             |
                | %H:%M:%S                                         |
                +--------------------------------------------------+
```

このような統計画面が表示される。リアルタイムで更新される。

```
 Dashboard - Overall Analyzed Requests                     [Active Panel: Visitors]

  Total Requests  6036 Unique Visitors 2   Referrers    4   Log Size  686.12 KiB
  Failed Requests 0    Unique Files    754 Unique 404   178 Bandwidth 125.27 MiB
  Generation Time 0    Excl. IP Hits   0   Static Files 4   Log File  access_log

 1 - Unique visitors per day - Including spiders                        Total: 1/1
 Hits having the same IP, date and agent are a unique visit.

  6036 2 100.00%  125.27 MiB   1.88  s 07/Apr/2015 |||||||||||||||||||||||||||||||||







 2 - Top requests (URLs)                                            Total: 366/754
 Top requests sorted by hits - [avg. time served | protocol | method]

  845 1 14.00%   12.71 MiB   2.80  s GET     HTTP/1.1 /
  341 1  5.65%  454.56 KiB 516.37 ms GET     HTTP/1.1 /signin
  341 1  5.65%     0.0   B 468.91 ms POST    HTTP/1.1 /signin
  341 1  5.65%    4.80 MiB   1.59  s GET     HTTP/1.1 /mypage
  341 1  5.65%     0.0   B   1.65  s POST    HTTP/1.1 /memo
  341 1  5.65%     0.0   B   3.00  s POST    HTTP/1.1 /signout
  267 1  4.42%     0.0   B 123.00 us OPTIONS HTTP/1.0 *

 3 - Top static requests (e.g. jpg, png, js, css..)                     Total: 4/4
 Top static requests sorted by hits - [avg. time served | protocol | method]

  437 1 7.24%    7.02 MiB   1.47  s GET HTTP/1.1 /css/bootstrap-responsive.min.css
  437 1 7.24%   44.18 MiB   1.05  s GET HTTP/1.1 /css/bootstrap.min.css
  437 1 7.24%   38.80 MiB 879.79 ms GET HTTP/1.1 /js/jquery.min.js
  437 1 7.24%   11.93 MiB 732.68 ms GET HTTP/1.1 /js/bootstrap.min.js




 4 - HTTP 404 Not Found URLs                                        Total: 178/178
 Top 404 Not Found URLs sorted by hits - [avg. time served | protocol | method]

  1 0 0.02%    13.0   B   2.77  s GET HTTP/1.1 /memo/42353
  1 0 0.02%    13.0   B   2.57  s GET HTTP/1.1 /memo/42355
  1 0 0.02%    13.0   B   2.46  s GET HTTP/1.1 /memo/42354
  1 0 0.02%    13.0   B   2.43  s GET HTTP/1.1 /memo/42361
  1 0 0.02%    13.0   B   2.12  s GET HTTP/1.1 /memo/42366
  1 0 0.02%    13.0   B   2.38  s GET HTTP/1.1 /memo/42368
  1 0 0.02%    13.0   B   2.16  s GET HTTP/1.1 /memo/42371

 5 - Visitor hostnames and IPs                                          Total: 2/2
 Top visitor hosts sorted by hits - [avg. time served]

  5769 1 95.58%  125.27 MiB   1.97  s 127.0.0.1 ||||||||||||||||||||||||||||||||||||
  267  1  4.42%     0.0   B 123.00 us ::1	|
```

合計時間が多いリクエストから優先的に対処をする。リクエスト回数、平均レスポンスタイムともに最大な`GET /`から対処する。

GETの中では、users, memos両方のテーブルにアクセスしているので、まずはクエリとインデックスを確認。

``` users
CREATE TABLE `users` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `username` varchar(255) NOT NULL,
  `password` varchar(255) NOT NULL,
  `salt` varchar(255) NOT NULL,
  `last_access` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `users_username_idx` (`username`)
) ENGINE=InnoDB AUTO_INCREMENT=401 DEFAULT CHARSET=utf8
```

``` memos
CREATE TABLE `memos` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `user` int(11) NOT NULL,
  `content` text,
  `is_private` tinyint(4) NOT NULL DEFAULT '0',
  `created_at` datetime NOT NULL,
  `updated_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=42868 DEFAULT CHARSET=utf8
```

MySQLのslow logでも`GET /`で呼ばれるクエリが頻出。

```
# Time: 150407 13:34:01
# User@Host: isucon[isucon] @ localhost []  Id:     1
# Query_time: 1.086976  Lock_time: 0.000054 Rows_sent: 100  Rows_examined: 56867
use isucon;
SET timestamp=1428413641;
SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT 100 OFFSET 13900;
```

memosのis_privateとcreated_atにインデックスを貼ると性能が改善された。

```
Result:   SUCCESS
RawScore: 1425.2
Fails:    0
Score:    1425.2
```
さらに、userにもはる。

```
Result:   SUCCESS
RawScore: 1781.9
Fails:    0
Score:    1781.9
```

ここまで、test modeでやってきたけど、benchmark modeだと外部APIへアクセスすることもあり、スコアは3割減となった。

```
Result:   SUCCESS
RawScore: 1213.2
Fails:    0
Score:    1213.2
```

#MySQLの方へ

ApacheLogからの流れが消化不良だし、ApacheLogから・・といいつつDBのチューニングしかしてなかったりして、このままMySQLの方をチューニングする。
アプリから投げられるQueryに関するColumnにindexは貼り終えたので他のパラメータを見る。
[MySQLTuner-perl](http://mysqltuner.com/)を使う。

benchmark modeだと実行するたびに、`DROP table`されてた。なので、indexとか貼っても無効・・。アプリレイヤーから上だけのチューニングだったのかな・・？
なので、スコア3割減なのもAPIアクセスじゃなくて、indexがなくなってデフォルトのスコアに戻っただけだろうね。

#つぎの方針を検討中

```
$ sudo isucon3 test --workload 4
Result:   SUCCESS
RawScore: 1673.0
Fails:    0
Score:    1673.0
```

このときCPUの使用率は60%強、メモリも余裕があるので、workloadを8にしてみた。

```
$ sudo isucon3 test --workload 8
2015/04/14 12:34:09 <<<DEBUG build>>>
2015/04/14 12:34:09 test mode
2015/04/14 12:34:09 run benchmark workload: 8
2015/04/14 12:34:28 [FAIL] Timeout http://localhost/memo
2015/04/14 12:34:28 [FAIL] Timeout http://localhost/memo
```

CPUの使用率は80%弱、メモリも余裕がある状態でTimeoutが発生。

apacheログをgoaccessで解析した結果を確認する。DBにインデックスを貼ったのだが、まだrootへのアクセスが平均1.70sになっている。

```
13.82%   26.75 MiB   1.70  s GET     HTTP/1.1 /
```

ためしにcurlしてみると、0.038msで返ってきた。

```
$ curl http://localhost
```

ここで一緒にISUCONをやってる人から、slowクエリの話しがきたので、自分も一応見てみた。

```
$ mysqldumpslow -v -s at -t 10 mysqld-slow.log

Reading mysql slow query log from mysqld-slow.log
Can't open mysqld-slow.log: Permission denied at /usr/bin/mysqldumpslow line 91.
Died at /usr/bin/mysqldumpslow line 161.
[isucon@ip-10-188-159-52 mysql]$ sudo mysqldumpslow -v -s at -t 10 mysqld-slow.log

Reading mysql slow query log from mysqld-slow.log
Count: 208  Time=1.25s (259s)  Lock=0.00s (0s)  Rows=100.0 (20800), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N OFFSET N
```

遅いやん・・。

```
mysql> explain SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT 100 OFFSET 20800;
+----+-------------+-------+------+-----------------+-----------------+---------+-------+-------+-----------------------------+
| id | select_type | table | type | possible_keys   | key             | key_len | ref   | rows  | Extra                       |
+----+-------------+-------+------+-----------------+-----------------+---------+-------+-------+-----------------------------+
|  1 | SIMPLE      | memos | ref  | idx_is_privated | idx_is_privated | 1       | const | 39609 | Using where; Using filesort |
+----+-------------+-------+------+-----------------+-----------------+---------+-------+-------+-----------------------------+
```

filesortになってるやん。複数columnでSORTしてるから複数indexを貼ってあげないといけないのね。

```
mysql> create index idx_is_private_created_at_id on memos(is_private, created_at, id);
Query OK, 0 rows affected (0.12 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> explain SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT 100 OFFSET 20800;
+----+-------------+-------+------+----------------------------------------------+------------------------------+---------+-------+-------+-------------+
| id | select_type | table | type | possible_keys                                | key                          | key_len | ref   | rows  | Extra       |
+----+-------------+-------+------+----------------------------------------------+------------------------------+---------+-------+-------+-------------+
|  1 | SIMPLE      | memos | ref  | idx_is_privated,idx_is_private_created_at_id | idx_is_private_created_at_id | 1       | const | 39609 | Using where |
+----+-------------+-------+------+----------------------------------------------+------------------------------+---------+-------+-------+-------------+
```

早くなった。

```
Result:   SUCCESS
RawScore: 1755.5
Fails:    0
Score:    1755.5
```

```goaccess
  541 1 13.48%    8.24 MiB 908.51 ms GET     HTTP/1.1 /
  216 1  5.38%  287.93 KiB 250.85 ms GET     HTTP/1.1 /signin
  216 1  5.38%     0.0   B 246.25 ms POST    HTTP/1.1 /signin
  215 1  5.36%     0.0   B 302.68 ms POST    HTTP/1.1 /memo
  215 1  5.36%     0.0   B 845.42 ms POST    HTTP/1.1 /signout
  214 1  5.33%    3.02 MiB 430.79 ms GET     HTTP/1.1 /mypage
```

`/`へのアクセスをリアルタイムで見てると、だんだん遅くなっているようだ。けど、1secをきったし50%近く早くなった。

スコアはそんなに改善されてないので、DBのslow query以外のところにボトルネックがあるのだろう。

#HTTPの設定をチューニング

```
KeepAlive On
MaxKeepAliveRequests 200
KeepAliveTimeout 2
```

```
Result:   SUCCESS
RawScore: 1780.6
Fails:    0
Score:    1780.6
```

ちょっと改善。

MaxClientなどをチューニング

```
ServerLimit 512
MaxClients 512
StartServers 512
MinSpareServers 512
MaxRequestsPerChild 0
```

ちょっと改善

```
Result:   SUCCESS
RawScore: 1801.8
Fails:    0
Score:    1801.8
```


(途中だけど一旦投稿。また続きをやるたびに更新します)