やり方
とりあえず、現状自分たちが考えることができる理想的な方法で、過去問を解いてみる。
参考資料
https://speakerdeck.com/fujiwara3/isucon-summer-school-1
https://speakerdeck.com/fujiwara3/isucon-summer-school-2
環境を作る
https://github.com/matsuu/vagrant-isucon
# 1時間以上かかるので、暇な時にやっておくと良い
➜ isucon git clone git@github.com:matsuu/vagrant-isucon.git
➜ vagrant-isucon git:(master) cd ./vagrant-isucon/isucon6-qualifier-standalone
➜ isucon6-qualifier-standalone git:(master) vagrant up
➜ isucon6-qualifier-standalone git:(master) vagrant ssh
ubuntu@ubuntu-xenial:~$ sudo -i -u isucon
isucon@ubuntu-xenial:~$ cd isucon6q
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 11:35:16 start pre-checking
2017/10/09 11:35:22 pre-check finished and start main benchmarking
2017/10/09 11:36:16 benchmarking finished
nginxのプロファイリング
# alpのinstall
root@ubuntu-xenial:~# wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
root@ubuntu-xenial:~# apt install unzip
root@ubuntu-xenial:~# unzip alp_linux_amd64.zip
root@ubuntu-xenial:~# install ./alp /usr/local/bin/
#ベンチマーク実行
isucon@ubuntu-xenial:~/isucon6q$ cd isucon6q/
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
#alp実行
root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access_log --aggregates='/keywords/.*'
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+--------------------------------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+--------------------------------------------------------+
| 68 | 1.147 | 7.731 | 323.394 | 4.756 | 1.147 | 4.726 | 7.696 | 1.423 | 7894.000 | 108819.000 | 4688744.000 | 68952.118 | GET | / |
| 270 | 0.001 | 4.718 | 274.573 | 1.017 | 0.001 | 0.882 | 4.559 | 0.943 | 106015.000 | 106015.000 | 28624050.000 | 106015.000 | GET | /css/bootstrap.min.css |
| 135 | 0.001 | 4.710 | 137.316 | 1.017 | 0.001 | 0.856 | 4.154 | 0.942 | 28631.000 | 28631.000 | 3865185.000 | 28631.000 | GET | /js/bootstrap.min.js |
| 135 | 0.001 | 4.711 | 137.077 | 1.015 | 0.000 | 0.868 | 4.152 | 0.942 | 16849.000 | 16849.000 | 2274615.000 | 16849.000 | GET | /css/bootstrap-responsive.min.css |
| 135 | 0.001 | 4.710 | 136.959 | 1.015 | 0.001 | 0.859 | 4.153 | 0.942 | 86351.000 | 86351.000 | 11657385.000 | 86351.000 | GET | /js/jquery.min.js |
| 135 | 0.001 | 4.709 | 136.811 | 1.013 | 0.000 | 0.872 | 4.150 | 0.943 | 1092.000 | 1092.000 | 147420.000 | 1092.000 | GET | /favicon.ico |
| 135 | 0.001 | 4.709 | 136.020 | 1.008 | 0.000 | 0.852 | 4.148 | 0.941 | 93.000 | 93.000 | 12555.000 | 93.000 | GET | /img/star.gif |
| 57 | 0.003 | 3.001 | 63.052 | 1.106 | 0.003 | 1.046 | 3.000 | 0.802 | 25.000 | 335.000 | 2615.000 | 45.877 | POST | /stars |
| 67 | 0.001 | 3.006 | 59.732 | 0.892 | 0.001 | 0.714 | 3.001 | 0.779 | 5.000 | 335.000 | 3615.000 | 53.955 | POST | /login |
| 41 | 0.032 | 3.002 | 49.207 | 1.200 | 0.032 | 0.969 | 3.001 | 0.886 | 5.000 | 331.000 | 6374.000 | 155.463 | POST | /keyword
root@ubuntu-xenial:~# vim /etc/mysql/my.cnf
[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 0
root@ubuntu-xenial:~# systemctl restart mysql
root@ubuntu-xenial:~# systemctl restart isuda.ruby
root@ubuntu-xenial:~# systemctl restart isutar.ruby
root@ubuntu-xenial:~# head -20 /var/log/mysql/slow.log
/usr/sbin/mysqld, Version: 5.7.19-0ubuntu0.16.04.1-log ((Ubuntu)). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
# Time: 2017-10-09T05:02:00.742015Z
# User@Host: isucon[isucon] @ localhost [] Id: 4
# Query_time: 0.000143 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0
use isuda;
SET timestamp=1507525320;
SET SESSION sql_mode='TRADITIONAL,NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY';
# Time: 2017-10-09T05:02:00.746467Z
# User@Host: isucon[isucon] @ localhost [] Id: 4
# Query_time: 0.004247 Lock_time: 0.003866 Rows_sent: 2 Rows_examined: 4
SET timestamp=1507525320;
SELECT * FROM entry
ORDER BY updated_at DESC
LIMIT 10
OFFSET 0;
# Time: 2017-10-09T05:02:00.747545Z
# User@Host: isucon[isucon] @ localhost [] Id: 4
# Query_time: 0.000388 Lock_time: 0.000143 Rows_sent: 2 Rows_examined: 4
root@ubuntu-xenial:~# wget https://www.percona.com/downloads/percona-toolkit/3.0.4/binary/debian/xenial/x86_64/percona-toolkit_3.0.4-1.xenial_amd64.deb
root@ubuntu-xenial:~# apt install libdbd-mysql-perl libdbi-perl libio-socket-ssl-perl libnet-ssleay-perl libterm-readkey-perl
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0x6C987DBB94BEC091 43.9842 96.9% 414 0.1062 0.13 SELECT entry
# 2 0x51C26B78ABE63960 0.6851 1.5% 28 0.0245 0.00 INSERT SELECT UPDATE entry
# 3 0x0C85264D3C24C18B 0.3384 0.7% 44 0.0077 0.09 SELECT entry
# 4 0x782FEBA311BC59ED 0.1392 0.3% 414 0.0003 0.00 SELECT star
# 5 0xF32185B56AEF3A1D 0.0631 0.1% 44 0.0014 0.00 SELECT entry
# 6 0x7E7900C7AF4DD0A4 0.0440 0.1% 23 0.0019 0.00 INSERT star
# 7 0x6FF06CCB4B4E1FAC 0.0261 0.1% 17 0.0015 0.00 INSERT UPDATE entry
# 8 0x41883793B68D128E 0.0235 0.1% 82 0.0003 0.00 SELECT user
# 9 0x16F15936BC5B2382 0.0224 0.0% 70 0.0003 0.00 SELECT entry
# 10 0x87B0C6DEA95CEF2E 0.0201 0.0% 84 0.0002 0.00 SELECT user
# MISC 0xMISC 0.0312 0.1% 59 0.0005 0.0 <32 ITEMS>
上から順番に遅いやつ。
# Query 1: 0.70 QPS, 0.07x concurrency, ID 0x6C987DBB94BEC091 at byte 28601055
# Scores: V/M = 0.13
# Time range: 2017-10-09T05:24:22 to 2017-10-09T05:34:12
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 32 414
# Exec time 96 44s 129us 1s 106ms 266ms 117ms 75ms
# Lock time 39 64ms 40us 5ms 153us 224us 361us 93us
# Rows sent 99 2.70M 1 6.94k 6.67k 6.63k 1.28k 6.63k
# Rows examine 91 5.40M 2 13.89k 13.34k 13.78k 2.66k 13.78k
# Query size 0 23.85k 59 59 59 59 0 59
# String:
# Databases isuda
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us ###
# 1ms
# 10ms ################################################################
# 100ms ###########################
# 1s #
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuda` LIKE 'entry'\G
# SHOW CREATE TABLE `isuda`.`entry`\G
# EXPLAIN /*!50100 PARTITIONS*/
select * from entry order by character_length(keyword) desc\G
改善作業に入る
step1 不要なカラムを読み込まないようにする
# before
keywords = db.xquery(%| select * from entry order by character_length(keyword) desc |)
# after
keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)
# Query 1: 17.68 QPS, 0.14x concurrency, ID 0x8AC9E716A43D8A44 at byte 610435
# Scores: V/M = 0.00
# Time range: 2017-10-09T05:57:41 to 2017-10-09T05:58:44
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 37 1114
# Exec time 89 9s 5ms 103ms 8ms 16ms 6ms 6ms
# Lock time 34 111ms 45us 4ms 99us 144us 138us 80us
# Rows sent 99 7.55M 6.93k 6.95k 6.94k 6.63k 0 6.63k
# Rows examine 92 15.11M 13.87k 13.90k 13.89k 13.78k 0 13.78k
# Query size 21 70.71k 65 65 65 65 0 65
# String:
# Databases isuda
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms ###############
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuda` LIKE 'entry'\G
# SHOW CREATE TABLE `isuda`.`entry`\G
# EXPLAIN /*!50100 PARTITIONS*/
select keyword from entry order by character_length(keyword) desc\G
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 14:57:41 start pre-checking
2017/10/09 14:57:45 pre-check finished and start main benchmarking
2017/10/09 14:58:41 benchmarking finished
{"pass":true,"score":4719,"success":1918,"fail":1,"messages":["リクエストがタイムアウトしました (POST /stars)"]}
step2 何度も実行されないようにする
#before
entries.each do |entry|
entry[:html] = htmlify(entry[:description])
entry[:stars] = load_stars(entry[:keyword])
end
#after
keywords =
entries.each do |entry|
entry[:html] = htmlify(keywords, entry[:description])
entry[:stars] = load_stars(entry[:keyword])
end
# Query 1: 4.67 QPS, 0.04x concurrency, ID 0x8AC9E716A43D8A44 at byte 687529
# Scores: V/M = 0.00
# Time range: 2017-10-09T06:04:42 to 2017-10-09T06:05:54
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 13 336
# Exec time 69 3s 5ms 54ms 9ms 17ms 5ms 6ms
# Lock time 9 28ms 32us 287us 83us 144us 33us 73us
# Rows sent 99 2.28M 6.93k 6.95k 6.94k 6.63k 0 6.63k
# Rows examine 73 4.56M 13.87k 13.90k 13.89k 13.78k 0.00 13.78k
# Query size 7 21.33k 65 65 65 65 0 65
# String:
# Databases isuda
# Hosts localhost
# Users isucon
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms ################################################################
# 10ms ############################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `isuda` LIKE 'entry'\G
# SHOW CREATE TABLE `isuda`.`entry`\G
# EXPLAIN /*!50100 PARTITIONS*/
select keyword from entry order by character_length(keyword) desc\G
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 15:04:42 start pre-checking
2017/10/09 15:04:47 pre-check finished and start main benchmarking
2017/10/09 15:05:42 benchmarking finished
{"pass":true,"score":5051,"success":2093,"fail":1,"messages":["リクエストがタイムアウトしました (POST /keyword)"]}
step3 assetsをnginxで返す
root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access.log --aggregates='/keywords/.*'
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+---------------------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+---------------------------------------------+
| 114 | 0.645 | 6.417 | 314.101 | 2.755 | 0.645 | 2.723 | 4.654 | 0.862 | 7960.000 | 93210.000 | 4816125.000 | 42246.711 | GET | / |
| 456 | 0.001 | 3.043 | 278.135 | 0.610 | 0.002 | 0.503 | 2.131 | 0.497 | 106015.000 | 106015.000 | 48342840.000 | 106015.000 | GET | /css/bootstrap.min.css |
| 228 | 0.001 | 3.038 | 140.322 | 0.615 | 0.001 | 0.511 | 2.059 | 0.496 | 28631.000 | 28631.000 | 6527868.000 | 28631.000 | GET | /js/bootstrap.min.js |
| 228 | 0.001 | 3.039 | 140.048 | 0.614 | 0.002 | 0.513 | 2.060 | 0.496 | 86351.000 | 86351.000 | 19688028.000 | 86351.000 | GET | /js/jquery.min.js |
| 228 | 0.002 | 3.044 | 139.345 | 0.611 | 0.002 | 0.505 | 2.062 | 0.497 | 16849.000 | 16849.000 | 3841572.000 | 16849.000 | GET | /css/bootstrap-responsive.min.css |
| 228 | 0.001 | 3.038 | 138.529 | 0.608 | 0.001 | 0.509 | 2.058 | 0.497 | 1092.000 | 1092.000 | 248976.000 | 1092.000 | GET | /favicon.ico |
| 228 | 0.001 | 3.027 | 137.308 | 0.602 | 0.001 | 0.498 | 2.057 | 0.495 | 93.000 | 93.000 | 21204.000 | 93.000 | GET | /img/star.gif
やっぱり /
重いけれども、まずはすぐにできそうな assetsまわりからやってみる。
location ~ ^/(img|css|js|favicon.ico){
root /home/isucon/webapp/public;
}
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 15:15:16 start pre-checking
2017/10/09 15:15:20 pre-check finished and start main benchmarking
2017/10/09 15:16:16 benchmarking finished
{"pass":true,"score":5258,"success":2380,"fail":2,"messages":["リクエストがタイムアウトしました (POST /stars)"]}
200 score早くなった。
step4 失敗しているリクエストをなくす
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
{"pass":true,"score":3779,"success":1851,"fail":4,"messages":["starがついていません (GET /)","リクエストがタイムアウトしました (POST /stars)","讃岐典侍日記 に 1109年 へのリンクがありません (GET /)"]}
これを見ると POST /stars
でtimeoutしている。
post '/stars' do
keyword = params[:keyword]
isuda_keyword_url = URI(settings.isuda_origin)
isuda_keyword_url.path = '/keyword/%s' % [Rack::Utils.escape_path(keyword)]
res = Net::HTTP.get_response(isuda_keyword_url)
halt(404) unless Net::HTTPSuccess === res
POST /stars
では GET /keyword/:keyword
を実行している。
GET /keyword/:keyword
の検索がなかなか遅いので、こいつをなんとかしなければならない。
root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access.log --aggregates='/keywords/.*'
| 8 | 1.287 | 3.497 | 19.388 | 2.423 | 1.287 | 2.553 | 2.927 | 0.671 | 11924.000 | 11928.000 | 95408.000 | 11926.000 | GET | /keyword/巨大基数
なぜ遅いのか見てみる。
mysql> desc 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 | |
+
keywordにindexが貼られていない。keywordにindexを貼っておく。
isucon@ubuntu-xenial:~/isucon6q$ ./isucon6q-bench -target http://127.0.0.1
2017/10/09 16:01:56 start pre-checking
2017/10/09 16:01:59 pre-check finished and start main benchmarking
2017/10/09 16:02:56 benchmarking finished
{"pass":true,"score":5671,"success":2476,"fail":0,"messages":[]}
300 scoreあがった。
5step get /
をなんとかする。
root@ubuntu-xenial:~# alp --sum -r -f /var/log/nginx/access.log --aggregates='/keywords/.*'
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+-------------------------------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+--------+-------------------------------------------------------+
| 101 | 0.709 | 7.417 | 345.768 | 3.423 | 0.709 | 3.317 | 6.436 | 1.414 | 7960.000 | 162448.000 | 5027564.000 | 49777.861 | GET | / |
keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)
entries.each do |entry|
entry[:html] = htmlify(keywords, entry[:description])
entry[:stars] = load_stars(entry[:keyword])
end
ここを、下記のようにできるのは無いか。
keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)
stars = load_stars(keywords)
entries.each do |entry|
entry[:html] = htmlify(keywords, entry[:description])
entry[:stars] = stars[entry[:keyword]]
end
今日は一旦ここまで
その他
再起動用script
#!/bin/sh
set -e
now=`date +%Y%m%d-%H%M%S`
mv /var/log/nginx/access.log /var/log/nginx/access.log.$now
systemctl restart nginx
mv /var/log/mysql/slow.log /var/log/mysql/slow.log.$now
mysqladmin -uisucon -pisucon flush-logs
systemctl restart isuda.ruby
systemctl restart isutar.ruby
過去問の作業ログ
当日の作業の流れ
環境確認
- githubでコード管理
- アプリケーションの動作確認: ブラウザでさわってみる、どんなプロセス動いてるとか
- 運営側から提供されているベンチマークを実行
- マシンスペックの確認(core数とか重要そう)
計測