LoginSignup
1
1

More than 5 years have passed since last update.

@osamunmun

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

Last updated at Posted at 2015-04-07

準備

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

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

1
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
1
1