準備

ISUCON3のページに従って進める。

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に変更

Result:   SUCCESS
RawScore: 1177.2
Fails:    0
Score:    1177.2

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

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

紹介してもらったGoAccessというツールを使って見る。

# 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両方のテーブルにアクセスしているので、まずはクエリとインデックスを確認。

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

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を使う。

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

  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

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