ISUCON3遊び (2) - 猿に文明を与えるな

久々に記録。(1) は書き忘れたので存在しない。環境構築は省略。

遅い処理を見つける

Apacheログの設定変更

combinedログ設定に処理時間マイクロ秒出力の %D を追加してbenchmarkモードで実行すると、以下のようにログが出力される。

127.0.0.1 - - [07/Apr/2015:13:00:49 +0000] "GET / HTTP/1.1" 200 15121 "-" "ISUCON Agent 2013" 1176357
127.0.0.1 - - [07/Apr/2015:13:00:50 +0000] "GET / HTTP/1.1" 200 15344 "-" "ISUCON Agent 2013" 537984
127.0.0.1 - - [07/Apr/2015:13:00:50 +0000] "GET /css/bootstrap-responsive.min.css HTTP/1.1" 200 16849 "-" "ISUCON Agent 2013" 344748
127.0.0.1 - - [07/Apr/2015:13:00:51 +0000] "GET /css/bootstrap.min.css HTTP/1.1" 200 106015 "-" "ISUCON Agent 2013" 1853
127.0.0.1 - - [07/Apr/2015:13:00:51 +0000] "GET /js/jquery.min.js HTTP/1.1" 200 93107 "-" "ISUCON Agent 2013" 1350
127.0.0.1 - - [07/Apr/2015:13:00:51 +0000] "GET /js/bootstrap.min.js HTTP/1.1" 200 28631 "-" "ISUCON Agent 2013" 1077

遅いアクセスを特定する

Apacheログから時間がかかったアクセスを炙り出す。

$ awk -F\" '{ print $2 $7 }' httpd/access_log-20150407  | sort -k 4 -n -r
GET /memo/32220 HTTP/1.1 9780123
GET /memo/38624 HTTP/1.1 4976940
GET /recent/204 HTTP/1.1 3924117
GET /recent/204 HTTP/1.1 3776329
GET /recent/204 HTTP/1.1 3684999
GET /recent/198 HTTP/1.1 3408030
GET /recent/153 HTTP/1.1 3385198
GET /recent/205 HTTP/1.1 3241328
GET /recent/175 HTTP/1.1 3110753

アクセスURLパターンが少ないのでアプリ or DBを見る方がよいと考えここで方針転換した。

遅いSQLを特定する

slow log

MySQLにいつものごとく設定を施し、ベンチマークを実行した。

$ mysqldumpslow -v -s t /tmp/mysql-slow.log            
Reading mysql slow query log from /tmp/mysql-slow.log
Count: 23  Time=1.94s (44s)  Lock=0.00s (0s)  Rows=100.0 (2300), isucon[isucon]@localhost
  SELECT * FROM memos WHERE is_private=N ORDER BY created_at DESC, id DESC LIMIT N OFFSET N

どうやら GET / の中で実行されてる上記クエリが遅いらしい。

上記クエリをExplainするとFilesortを使ったALL検索になっていたのでスキーマを確認。するとインデクスが無かったので作成。

mysql> create index idx_created_at_id on memos(created_at, id);

併せてアプリ側のクエリも変更する。

memos = mysql.xquery("SELECT * FROM memos WHERE is_private=0 AND id >= #{page * 100} ORDER BY created_at DESC, id DESC LIMIT 100")
# memos = mysql.xquery("SELECT * FROM memos WHERE is_private=0 ORDER BY created_at DESC, id DESC LIMIT 100 OFFSET #{page * 100}")

早くなったかとおもいきやスコア変わらず。benchmarkモードだと実行毎にスキーマがリセットされることに最後に気付いたので次回はそこから対応する。